Request Logging

Request Logging

Request Logging and Correlation IDs

One user report — "checkout was slow around 9:15" — has to become one filter in your log tool. That needs a correlation id: a value generated at the edge, attached to every line the request produces, and returned to the client so the id in the ticket matches the id in the logs.

pino-http 11.0.0 705 (npm 2,036 i pino-http, MIT) supplies half of it: a line when each response finishes, and a child logger on req.log with the id bound. The other half is AsyncLocalStorage from AsyncLocalStorage, which carries that logger through every function the request calls:

server.mjs — one id from the edge to the deepest functionJavaScript

import express from 'express';
import pino from 'pino';
import pinoHttp from 'pino-http';
import { randomUUID } from 'node:crypto';
import { AsyncLocalStorage } from 'node:async_hooks';
export const store = new AsyncLocalStorage();
const app = express();
app.use(pinoHttp({
  logger: pino({ base: null }),
  quietReqLogger: true,
  genReqId(req, res) {
    const id = req.headers['x-request-id'] ?? randomUUID().slice(0, 8);
    res.setHeader('x-request-id', id);
    return id;
  },
  serializers: { req: () => undefined, res: () => undefined },
  customSuccessMessage: (req, res) => `${req.method} ${req.url} ${res.statusCode}`,
}));
app.use((req, res, next) => store.run(req.log, next));
const chargeCard = (amount) => store.getStore().info({ amount }, 'charging card');
app.get('/orders/:id', (req, res) => {
  chargeCard(78.5);
  res.json({ id: req.params.id, status: 'paid' });
});
app.listen(3000);

Output

{"level":30,"time":1789645622308,"reqId":"9f2c","amount":78.5,"msg":"charging card"}
{"level":30,"time":1789645622313,"reqId":"9f2c","responseTime":6,"msg":"GET /orders/42 200"}
{"level":30,"time":1789645622378,"reqId":"97cded93","amount":78.5,"msg":"charging card"}
{"level":30,"time":1789645622379,"reqId":"97cded93","responseTime":1,"msg":"GET /orders/7 200"}

The first request arrived with x-request-id: 9f2c from a gateway, so the server reused it; the second got a generated one. Either way the id is echoed back in the response header, every line of that request carries it, and responseTime is measured for you. chargeCard took no logger and no request argument: store.getStore() finds the right one because AsyncLocalStorage follows the async context.

quietReqLogger moves the id to a top-level reqId. Without the serializers overrides, pino-http also logs headers, query, params and remote address — what you want in production, far too wide for a printed page. Propagate the id outward too: sending 'x-request-id': store.getStore().bindings().reqId on every outgoing fetch lets one filter follow a user across your services. Express.js returns to this with Express 24,430 error middleware.

MENU