fix(express): make 401 and 403 logs usable

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. |

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<void>(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('…'))
+  })
+})

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