Ch. 6 · Node.js

Node.js Structured Logging

Write one JSON object per log line in Node.js, add request ids with AsyncLocalStorage, serialise errors properly and redact secrets.

~8 min readintermediateupdated Oct 19, 2026

At 3 a.m., during an incident, nobody reads logs. They query them. “Show me every error for order ord_81 in the last hour”, “count CARD_DECLINED by payment provider”, “which requests took longer than two seconds”. A line like Charge failed for order ord_81 (49.99) after 2 tries answers none of those without a fragile regular expression, and the regex breaks the next time someone rewords the message.

Structured logging means each log entry is data: one JSON object per line, with named fields. The message stays human-readable, and everything you might filter or aggregate on goes into its own field. This guide builds a small logger to show the moving parts, then covers what production libraries add. Everything ran on Node 22.23.

What a good log line contains

A useful line answers four questions: when, how bad, what happened, and in what context. This one comes from the demo later in the article, with the stack trace left out:

{"time":"2026-10-20T14:48:52.827Z","level":"error","msg":"charge failed","service":"checkout","component":"payments","requestId":"04425470","orderId":"ord_81","amountCents":4999,"err":{"type":"Error","message":"card declined","code":"CARD_DECLINED"}}
JSON
  • time in ISO 8601 UTC. Local time zones in logs cause real confusion when servers run in several regions.
  • level: debug, info, warn, error. Production usually runs at info; debug is switched on per service when investigating.
  • msg: a short constant string. “charge failed”, not “charge failed for ord_81”. Keeping variable data out of the message means you can group by it and count occurrences.
  • Context fields with names that stay the same across services: requestId, orderId, userId, durationMs. If one service logs order_id and another orderId, every cross-service query has to know both.

Units belong in the field name (amountCents, durationMs) because a bare amount: 4999 will be misread by someone eventually.

Levels deserve a moment of thought because interviewers ask about them. error should mean something needs attention: a request failed in a way the user noticed, or data couldn’t be saved. A card declined by the bank is arguably a normal business outcome and might be warn or even info; the payment provider being unreachable is an error. If everything is logged at error, alerts on error rates become noise and people stop reading them.

Building a small JSON logger

Here’s the core of a logger with levels and child loggers:

const LEVELS = { debug: 20, info: 30, warn: 40, error: 50 };

function createLogger(bindings = {}, minLevel = process.env.LOG_LEVEL ?? 'info') {
  const write = (level, msg, fields = {}) => {
    if (LEVELS[level] < LEVELS[minLevel]) return;
    const line = { time: new Date().toISOString(), level, msg,
                   ...bindings, ...context.getStore(), ...clean(fields) };
    process.stdout.write(JSON.stringify(line) + '\n');
  };
  return {
    debug: (m, f) => write('debug', m, f),
    info:  (m, f) => write('info', m, f),
    warn:  (m, f) => write('warn', m, f),
    error: (m, f) => write('error', m, f),
    child: (more) => createLogger({ ...bindings, ...more }, minLevel),
  };
}

const log = createLogger({ service: 'checkout' });
JavaScript

A child logger is a logger with extra fields baked in. log.child({ component: 'payments' }) returns one that adds component to every line, so the payments module doesn’t repeat it on each call.

The logger writes to stdout, not to a file. In containers and on most platforms, the runtime collects stdout and ships it to your log system. The application shouldn’t manage files, rotation or network shipping; that’s the platform’s job, and doing it in-process means a slow log server can slow down requests.

The level check happens before anything is serialised. That matters because JSON.stringify on a large object is real CPU on the main thread. With LOG_LEVEL unset, the debug line in the example below costs a function call and a comparison, nothing more. Running with LOG_LEVEL=debug produced the extra line:

{"time":"2026-10-20T14:48:52.867Z","level":"debug","msg":"calling provider","service":"checkout","component":"payments","requestId":"c05cb362","provider":"acme"}
Text

One weakness of this sketch: caller fields are spread last, so a caller who passes { level: 'x' } or { msg: ... } overwrites the reserved fields. Libraries guard against that; a quick fix is to spread caller fields first and the reserved ones after.

Request ids without passing them everywhere

The field that makes logs usable during an incident is the request id. With it, you can pull every line one request produced, across every function and every service it touched. Without it, concurrent requests interleave in the log and you can’t tell which “charge failed” belongs to which “order received”.

Passing requestId as a parameter to every function is tedious, and someone always forgets. AsyncLocalStorage from node:async_hooks holds a value for the duration of an async call chain, including across await, timers and promise callbacks:

import { AsyncLocalStorage } from 'node:async_hooks';
import { randomUUID } from 'node:crypto';

const context = new AsyncLocalStorage();

// in the HTTP handler, once per request:
await context.run({ requestId: randomUUID() }, async () => {
  log.info('order received', { orderId: req.id });
  await chargeCard(req);   // logs inside here still see requestId
});
JavaScript

The logger reads context.getStore() on every write, so chargeCard logs with the right requestId without knowing it exists. In the run below, both lines carry "requestId":"04425470", even though the second was written from a different function after a setTimeout. In a real service, take the id from an incoming header (X-Request-Id, or the W3C traceparent if you use tracing) when one is present, and send it on to downstream calls, so a single id follows the request through every service.

Errors, secrets and things JSON can’t hold

Three problems show up the first time you log real objects.

Errors serialise to nothing. An Error’s message and stack are not enumerable properties, so:

JSON.stringify(new Error): {}
Text

A log line that says "err":{} is worse than none, because it looks like you logged something. Serialise errors explicitly: name, message, code (Node’s system errors and many libraries set one) and stack, plus cause if you use error chaining.

Secrets end up in logs when someone logs a whole request, user or config object “for debugging”. Once a password or token is written, it’s copied to the log pipeline, the search index, backups and anyone’s laptop who exports a query. Redact by key name before serialising, and treat the list as security-sensitive code. Personal data needs the same thought: card numbers never, email addresses only if your privacy policy and retention period allow it.

Some values can’t be serialised: BigInt throws Do not know how to serialize a BigInt, and a circular reference throws too. A logger that throws turns a logging call into an outage, so it has to handle both.

Here’s the clean function the logger above calls:

const REDACT = new Set(['password', 'authorization', 'cookie', 'token', 'cardNumber']);

function clean(value, seen = new WeakSet()) {
  if (value instanceof Error) {
    return { type: value.name, message: value.message, code: value.code, stack: value.stack };
  }
  if (typeof value === 'bigint') return value.toString();
  if (value && typeof value === 'object') {
    if (seen.has(value)) return '[Circular]';
    seen.add(value);
    const out = Array.isArray(value) ? [] : {};
    for (const [k, v] of Object.entries(value)) {
      out[k] = REDACT.has(k) ? '[REDACTED]' : clean(v, seen);
    }
    return out;
  }
  return value;
}
JavaScript

I fed it a request object containing a password, an Authorization header and a reference to itself, then an error with a code. The real output (the demo trimmed the stack to two lines and I’ve shortened the file path):

{"time":"2026-10-20T14:48:52.813Z","level":"info","msg":"order received","service":"checkout","requestId":"04425470","orderId":"ord_81","request":{"id":"ord_81","user":{"id":"u_17","password":"[REDACTED]"},"headers":{"authorization":"[REDACTED]"},"self":"[Circular]"}}
{"time":"2026-10-20T14:48:52.827Z","level":"error","msg":"charge failed","service":"checkout","component":"payments","requestId":"04425470","orderId":"ord_81","amountCents":4999,"err":{"type":"Error","message":"card declined","code":"CARD_DECLINED","stack":"Error: card declined\n    at chargeCard (file:///.../log.mjs:47:29)"}}
Text

The seen set is deliberately simple: an object referenced twice without a cycle is also reported as [Circular] the second time. Real libraries track the current path instead. Note also that the redaction list is matched case-sensitively, so an Authorization key with a capital A would slip through; Node lowercases incoming header names, but your own objects might not.

What a library adds

In production, use pino (or winston if the codebase already has it) rather than a hand-rolled logger. Pino writes newline-delimited JSON very cheaply, supports child loggers and level checks like the sketch above, has built-in redaction by path (redact: ['req.headers.authorization', '*.password']) and standard serialisers for errors and HTTP requests, and can move formatting and shipping into a worker thread so the event loop isn’t doing it. For local development, piping output through pino-pretty gives coloured, readable lines without changing what production writes. Being able to say why you’d still choose a library, after showing you know what it does, is a good place to end an interview answer.

“Our Node services log with console.log template strings. During last week’s outage, it took the team 40 minutes to find which customer requests failed, because each service words its messages differently, and we later found access tokens in the logs. You have a sprint to fix logging. What do you do, in what order?”

Answer. First, stop the leak, because tokens in logs are a live security problem: rotate the exposed tokens, purge or restrict the affected log indices, and find the log statements that printed whole request or header objects. Then I’d introduce one shared logging package, a thin wrapper around pino, so every service gets the same JSON format, levels and redaction list (authorization, cookie, password, token and anything payment-related) without each team configuring it.

Next, request ids: middleware that reads X-Request-Id or traceparent from the incoming request or generates one, stores it in AsyncLocalStorage, puts it on every log line and forwards it on outgoing HTTP calls. That alone would have turned the 40-minute search into one query. Then I’d agree on a short field-name convention (requestId, userId, orderId, durationMs, err) and convert the highest-traffic and error paths first, keeping messages as constant strings with data in fields. I wouldn’t try to rewrite every console.log in one sprint; the shared package plus the hot paths gets most of the value. Finally, I’d add a test in the shared package that logs an object containing each redacted key and asserts none of the values appear in the output, so redaction can’t silently regress.

Further reading

More in Node.js

read ✓Node.js · mid

Node.js AsyncLocalStorage for Request Context

Use AsyncLocalStorage to keep a request ID in every log line, see why a module-level variable mixes requests, and find where context gets lost.

~7 min readread →
read ✓Node.js · mid

Node.js Request Body Validation and Limits

Read a JSON request body in Node.js with a byte limit that also catches chunked uploads, then validate its shape and return 413, 415, 400 or 422.

~6 min readread →
read ✓Node.js · hard

Node.js Health Checks and Service Readiness

Separate liveness from readiness in Node.js, bound dependency checks with timeouts and caching, and avoid probes that restart healthy pods.

~6 min readread →
esc