Structured logs and correlation IDs

One field name everywhere, the id read from the request's own store on every line, and secrets removed by the logger itself.

Before you read: predict

ExamHall's autosave service logs with pino. Its middleware runs each request inside its own als.run({ attemptId }, …). The answer store's client keeps one connection: autosave waits for it with a callback, submit with a promise:

Attempt a-1 autosaves and gets the connection. While its save runs, a-2 submits and then a-3 autosaves, so both wait. Then a-1's save finishes, then a-2's, then a-3's.

Which attemptId does a-2's attempt submitted line carry, and which does a-3's answer saved line carry?

const als = new AsyncLocalStorage();const log = pino({ mixin: () => ({ attemptId: als.getStore()?.attemptId }) }); const waiting = [];let busy = false;function withConnection(fn) {  if (busy) { waiting.push(fn); return; }  busy = true;  fn(conn);}function release() {  const next = waiting.shift();  if (next) next(conn); else busy = false;}const acquire = () => new Promise((resolve) => withConnection(resolve)); export function autosave(body) {  withConnection((conn) => {    conn.save(body).then(() => { log.info('answer saved'); release(); });  });}export async function submit(body) {  const conn = await acquire();  await conn.save(body);  log.info('attempt submitted');  release();}

The 30-second version

Write every log line as JSON with the same field names in every service, so one filter finds one request's lines. Stamp each line with the id from the request's AsyncLocalStorage store, read when the line is written; work that runs later for someone else needs its context bound. Redact in the logger's configuration, not at call sites.

One field name everywhere, the id read from the request's own store on every line, and secrets removed by the logger itself.

How it works

Step 1 of 14

Text can't be filtered. console.log with interpolation writes a sentence; a log store can search it, not filter or count it by field.

Analogy: A soil-testing laboratory's analyser (agriculture)

A laboratory tests farmers' soil samples on one analyser. Each result prints with the farm whose batch is open on the analyser's screen at that moment.

In the laboratory	In the code
every result is printed on a report form with the same boxes, so the lab can pull every result for farm 41	JSON lines with agreed field names (steps 2, 3)
the analyser fills the farm box from the batch open on its screen when the result prints	the id read from the request's store when the line is written (step 6)
samples wait in a rack for the analyser; the technician who finishes farm 41's batch runs the next sample from the rack with farm 41 still open, and its result prints as farm 41's	a queued callback run in the releasing request's context (steps 7, 8)
entering each sample's farm in the analyser's run list when it goes in the rack	binding the callback when it is queued (step 9)
the report form has no box for the farmer's phone number or bank details; they stay in the office's customer file	redaction in the logger's configuration (step 11)

In real terms: the farm on a result comes from the screen at the moment it prints, not from where the sample came from.

Breaks down when: a technician can notice a result that looks wrong for that field; code never re-checks the id it holds.

Contrasting case: a lab with one technician and an empty rack never mixes farms, until a second batch waits; tests that send one request at a time hide step 8 the same way.

Examples, run for real

4.1 ExamHall EXH-3990 and MR !4290: the autosave lines

In EXH-3990 the autosave handler wrote console.log(`autosave ${candidate.name} attempt ${attemptId}: ${answer.text}`). Two attempts autosaved three answers each, interleaved.

4.1 EXH-3990 console.log text: 6 autosave lines · field filter attemptId = "at-17" returns 0 · lines holding a candidate's name or answer 6 of 6
4.1 MR !4290 pino JSON: 6 lines, every one with the fields level, attemptId, institutionId, traceId, questionId, msg · field filter attemptId = "at-17" returns 3 · lines holding a candidate's name or answer 0 of 6

MR !4290 switches to pino. The middleware opens a store per request with attemptId, institutionId and traceId; a mixin copies them onto every line. The handler logs only { questionId }, and redact: ['candidate.name', 'answer.text'] backs that up for any later call that passes them (steps 2, 6, 11, 14).

Try it

Answer first, then check. Nothing is saved.

Question 1 of 6

A chat platform's send-message request passes through three services, each with its own pino logger. For request r-7 they run:

All six lines reach one log store. On-call runs its field filter requestId = "r-7".

How many lines does it return?

// gatewayconst log = logger.child({ requestId: req.id });log.info('message accepted');log.info({ room: 'general' }, 'rate limit ok');log.info('forwarded to messages');// messages servicelogger.info({ reqId: req.id }, 'message stored');logger.info({ reqId: req.id, room: 'general' }, 'room updated');// notifications servicelogger.info(`push sent for request ${req.id}`);

Question 2 of 6

A streaming service's logger is pino({ redact: ['viewer.email', '*.email'] }). With const viewer = { id: 'v-3', email: 'ana@stream.test' }; it runs:

Which lines write the viewer's email in clear?

(1) logger.info({ viewer }, 'playback started');(2) logger.child({ viewer }).info('heartbeat');(3) logger.info({ session: { id: 's-9', viewer } }, 'playback resumed');(4) logger.info({ email: viewer.email }, 'receipt sent');

Question 3 of 6

A ticket site's seat page loads an event's seat map once and shares that load with every request that arrives while it runs. Its middleware runs each request inside its own als.run({ requestId }, …), and the logger's mixin adds requestId from that store:

Requests r-14 and r-41 open event ev-5's seat page at the same moment, r-14 first, and the database answers once. On-call is looking into r-41's slow page.

Which requestId does the seat map loaded line carry?

let seatMap = null;function loadSeatMap(eventId) {  seatMap ??= db.seatMap(eventId).then((map) => {    log.info({ eventId }, 'seat map loaded');    return map;  });  return seatMap;}export async function showSeats(eventId) {  const map = await loadSeatMap(eventId);  log.info({ free: map.free }, 'seats shown');}

Question 4 of 6

A payments ledger's nightly posting job and the bank module it calls import the same pino logger. For batch b-9 they run:

The five lines reach one log store. On-call runs its field filter batchId = "b-9".

How many lines does it return?

// posting jobconst log = logger.child({ batchId: 'b-9' });log.info('batch opened');for (const entryId of ['e-1', 'e-2']) log.child({ entryId }).info('entry posted');notifyBank();log.info('batch closed');// bank moduleexport function notifyBank() { logger.info('bank notified'); }

Question 5 of 6

A payments ledger's logger is pino({ redact: ['*.card.number'] }). With

the card number reaches the log.

Which change keeps it out of this line?

const payment = { id: 'pay-81', amount: 4200, card: { number: '0000-TEST-0002', brand: 'visa' } };log.warn(`charge declined: card ${payment.card.number}, amount ${payment.amount}`);

Question 6 of 6

A chat service sends read receipts in batches. Its logger is pino({ mixin: () => ({ roomId: als.getStore()?.roomId }) }), and each request runs inside its own als.run({ roomId }, …):

Rooms r-1, r-2 and r-3 each mark a message read in the same tick, r-1 first.

What fills the slot so each receipt sent line carries its own roomId?

const pending = [];let timer = null;function flush() {  timer = null;  for (const send of pending.splice(0)) send();}export function markRead(userId) {  const send = () => log.info({ userId }, 'receipt sent');  ____}

Go deeper

Pro tip

Put the redact list in the logger's configuration, not a sanitiser at each call site. When: a code review or a design round where someone proposes wrapping log calls in a safe() helper (step 11). Verify:
```
tip 5 call sites, a sanitiser at 4 of them: 1 of 5 lines hold the name · one redact path in the logger: 0 of 5
```
Status: RAN.

Sources

Each web page was fetched with curl on 2026-10-13; the three pino pages are the copies shipped in the installed pino 10.4.0 package. quote-check.mjs finds every passage below verbatim in its saved text. No passage keys an item; every key is executed. Valid as of 2026-10-13.

Node.js v24 docs, Asynchronous context tracking (the row's AsyncLocalStorage page): https://nodejs.org/docs/latest-v24.x/api/async_context.html (node-async-context.txt). Quoted: "The store is accessible to any asynchronous operations created within the callback."; "use the AsyncResource class to associate the asynchronous operation with the correct execution context."; "Binds the given function to the current execution context." Supports steps 5, 8 and 9.
OWASP, Logging Cheat Sheet: https://cheatsheetseries.owasp.org/cheatsheets/Logging_Cheat_Sheet.html (owasp-logging.txt). Quoted: "Application logging should be consistent within the application, consistent across an organization's application portfolio and use industry standards where relevant, so the logged event data can be consumed, correlated, analyzed and managed by a wide variety of systems."; "The "Interaction identifier" is a method of linking all (relevant) events for a single user interaction"; "The following should usually not be recorded directly in the logs, but instead should be removed, masked, sanitized, hashed, or encrypted:"; "Access tokens"; "Authentication passwords"; "Bank account or payment card holder data". Supports steps 3, 6 and 14.
pino 10.4.0, API (the row's Pino docs): https://github.com/pinojs/pino/blob/v10.4.0/docs/api.md (pino-api.txt). Quoted: "If provided, the mixin function is called each time one of the active logging methods is called."; "As an array, the redact option specifies paths that should have their values redacted from any log output." Supports steps 6 and 11.
pino 10.4.0, Redaction: https://github.com/pinojs/pino/blob/v10.4.0/docs/redaction.md (pino-redaction.txt). Quoted: "paths may contain the asterisk * to denote a wildcard". Supports step 12.
pino 10.4.0, Child loggers: https://github.com/pinojs/pino/blob/v10.4.0/docs/child-loggers.md (pino-child-loggers.txt). Quoted: "Child logger bindings are top-level fields on every log line emitted by the child logger." Supports step 4.

Checked against the tools and docs as of 2026-10-13.

Predict first

Which attemptId does a-2's attempt submitted line carry, and which does a-3's answer saved line carry?

The 30-second version

How it works

Analogy: A soil-testing laboratory's analyser (agriculture)

Examples, run for real

4.1 ExamHall EXH-3990 and MR !4290: the autosave lines

Try it

How many lines does it return?

Which lines write the viewer's email in clear?

Which requestId does the seat map loaded line carry?

How many lines does it return?

Which change keeps it out of this line?

What fills the slot so each receipt sent line carries its own roomId?

Go deeper

Related lessons