From 94e4f50d22cef1942198b60d67af98b4106551ca Mon Sep 17 00:00:00 2001 From: BatLeDev Date: Wed, 4 Nov 2026 12:58:21 +0100 Subject: [PATCH] fix(express): make 401 and 403 logs usable The error handler logged an empty message for errors without one, like the 401 of session.reqAuthenticated, and its lines did not say which route was concerned. - use a default log message for 401 and 403, response bodies are unchanged - add the method and the url to 401, 403 and 5xx lines, never the query string as it can carry secrets - truncate the logged url to 1000 characters as it comes from the client --- packages/express/README.md | 2 +- packages/express/error-handler.test.ts | 98 ++++++++++++++++++++++++++ packages/express/error-handler.ts | 13 +++- 3 files changed, 109 insertions(+), 4 deletions(-) create mode 100644 packages/express/error-handler.test.ts diff --git a/packages/express/README.md b/packages/express/README.md index 5f6e014..b02052c 100644 --- a/packages/express/README.md +++ b/packages/express/README.md @@ -16,7 +16,7 @@ Peer dependencies: `@data-fair/lib-node@^3.0.0`, `express@5`, and `ws@8` (option | --- | --- | | `@data-fair/lib-express` | Re-exports the small common pieces: `session.js`, `errorHandler`, find utils, `httpError`, `req-origin.js`, `site.js`, `serve-spa.js`. | | `@data-fair/lib-express/session.js` | `session` singleton: verifies the simple-directory session cookies, `session.middleware()` (also opens the request log context, see `@data-fair/lib-node/log.js`), `reqSession()` / `reqSessionAuthenticated()` / `reqAdminMode()` accessors. | -| `@data-fair/lib-express/error-handler.js` | Express error handler: maps errors to status codes, logs 5xx as errors and 401/403 as warnings, hides 5xx details when `NODE_ENV=production`. | +| `@data-fair/lib-express/error-handler.js` | Express error handler: maps errors to status codes, logs 5xx as errors and 401/403 as warnings (with the method and the url, never the query string), hides 5xx details when `NODE_ENV=production`. | | `@data-fair/lib-express/req-origin.js` | Reverse-proxy aware request info: `reqOrigin()`, `reqHost()`, `reqIp()`, `reqIsInternal()`, `assertReqInternalSecret()`, `secretKeyMatches()`… | | `@data-fair/lib-express/site.js` | `createSiteMiddleware(servicePathPart)`: extracts the site path prefix of the request, `reqSitePath()`, `reqSiteUrl()`. | | `@data-fair/lib-express/serve-spa.js` | `createSpaMiddleware()`: serves a built SPA with UI config injection, cache headers and CSP. | diff --git a/packages/express/error-handler.test.ts b/packages/express/error-handler.test.ts new file mode 100644 index 0000000..364f734 --- /dev/null +++ b/packages/express/error-handler.test.ts @@ -0,0 +1,98 @@ +import { describe, it, after, before, beforeEach } from 'node:test' +import { strict as assert } from 'assert' +import type { Server } from 'node:http' +import type { AddressInfo } from 'node:net' +import express from 'express' +import { httpError } from '@data-fair/lib-utils/http-errors.js' +import { _resetLogger } from '@data-fair/lib-node/log.js' +import errorHandler from './error-handler.js' + +describe('errorHandler', () => { + let server: Server + let baseUrl: string + let lines: any[] = [] + + before(async () => { + const app = express() + const router = express.Router() + router.get('/no-message/:status', (req) => { throw httpError(Number(req.params.status)) }) + router.get('/message/:status', (req) => { throw httpError(Number(req.params.status), 'some reason') }) + router.get('/message/:status/:long', (req) => { throw httpError(Number(req.params.status), 'some reason') }) + router.get('/failure', () => { throw new Error('boom') }) + app.use('/api', router) + // a handler mounted on a sub-router sees a req.url relative to its mount path + const mounted = express.Router() + mounted.get('/route', () => { throw httpError(403, 'some reason') }) + mounted.use(errorHandler) + app.use('/mounted', mounted) + app.use(errorHandler) + + await new Promise(resolve => { server = app.listen(0, () => resolve()) }) + baseUrl = `http://localhost:${(server.address() as AddressInfo).port}` + _resetLogger({ format: 'json', destination: { write: (s: string) => { for (const l of s.split('\n')) if (l) lines.push(JSON.parse(l)) } } }) + }) + + beforeEach(() => { + lines = [] + }) + + after(async () => { + _resetLogger() + await new Promise(resolve => server.close(resolve)) + }) + + it('gives 401 and 403 errors without message a default log message', async () => { + await fetch(`${baseUrl}/api/no-message/401`) + await fetch(`${baseUrl}/api/no-message/403`) + assert.equal(lines[0].msg, 'unauthorized request') + assert.equal(lines[0].code, 'unauthorized-req') + assert.equal(lines[1].msg, 'forbidden request') + assert.equal(lines[1].code, 'forbidden-req') + }) + + it('does not send the default log message to the client', async () => { + const previous = process.env.NODE_ENV + process.env.NODE_ENV = 'production' + try { + const res = await fetch(`${baseUrl}/api/no-message/401`) + assert.equal(res.status, 401) + assert.equal(await res.text(), '') + } finally { + process.env.NODE_ENV = previous + } + }) + + it('keeps the message of the error when there is one', async () => { + await fetch(`${baseUrl}/api/message/403`) + assert.equal(lines[0].msg, 'some reason') + }) + + it('logs the method and the url on 401, 403 and 5xx', async () => { + await fetch(`${baseUrl}/api/no-message/401`) + await fetch(`${baseUrl}/api/message/403`) + await fetch(`${baseUrl}/api/failure`) + assert.deepEqual(lines.map(l => [l.level, l.method, l.url]), [ + ['warn', 'GET', '/api/no-message/401'], + ['warn', 'GET', '/api/message/403'], + ['error', 'GET', '/api/failure'] + ]) + }) + + it('never logs the query string', async () => { + await fetch(`${baseUrl}/api/no-message/401?apiKey=secret`) + assert.equal(lines[0].url, '/api/no-message/401') + assert.ok(!JSON.stringify(lines[0]).includes('secret')) + }) + + it('logs the full url when mounted on a sub-router', async () => { + await fetch(`${baseUrl}/mounted/route`) + assert.equal(lines[0].url, '/mounted/route') + }) + + it('truncates long urls', async () => { + const res = await fetch(`${baseUrl}/api/message/403/${'a'.repeat(2000)}`) + assert.equal(res.status, 403) + assert.equal(lines[0].url.length, 1001) + assert.ok(lines[0].url.endsWith('…')) + }) +}) diff --git a/packages/express/error-handler.ts b/packages/express/error-handler.ts index 2255d7d..14c267e 100644 --- a/packages/express/error-handler.ts +++ b/packages/express/error-handler.ts @@ -4,6 +4,9 @@ import debugModule from 'debug' const debug = debugModule('http-errors') +// the url comes from the client and can be logged for anonymous requests, keep log lines bounded +const maxUrlLength = 1000 + const errorHandler: ErrorRequestHandler = (err, req, res, next) => { // let the default error handler manage closing the connection if (res.headersSent) { next(err); return } @@ -17,14 +20,18 @@ const errorHandler: ErrorRequestHandler = (err, req, res, next) => { // a mongodb conflict on an index should usually be returned as a 409 if (err.name === 'MongoServerError' && err.code === 11000) status = 409 + // originalUrl because req.url is relative to the mount path, and no query string as it can carry secrets + const url = req.originalUrl.split('?')[0] + const reqFields = { method: req.method, url: url.length > maxUrlLength ? url.slice(0, maxUrlLength) + '…' : url } + if (status >= 500) { - log.error('failure while serving http request', { code: 'http', err }) + log.error('failure while serving http request', { code: 'http', err, ...reqFields }) } if (status === 403) { - log.warn(err.message, { code: 'forbidden-req' }) + log.warn(err.message || 'forbidden request', { code: 'forbidden-req', ...reqFields }) } if (status === 401) { - log.warn(err.message, { code: 'unauthorized-req' }) + log.warn(err.message || 'unauthorized request', { code: 'unauthorized-req', ...reqFields }) } res.set('Cache-Control', 'no-cache') res.set('Expires', '-1')