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')