Structured Logging, and What to Actually Put in a Log Line

The short answer

Log objects, not sentences.

// unqueryable
logger.info(`User ${userId} placed order ${orderId} for ${total} INR`);

// queryable
logger.info({ event: "order.placed", userId, orderId, totalPaise, currency: "INR" },
            "order placed");

The second can answer "what is the p95 order value for users in the last hour" with a query. The first requires a regex against prose that somebody will change next month.

Every log line should carry a request id, an event name, and the identifiers needed to find the related records.

Why prose logs fail

The failure is not aesthetic. It is that during an incident you need to ask questions you did not anticipate.

"Show me every failed payment for merchant 8823 in the last hour, grouped by error code" is a one line query against structured logs and an afternoon of grepping against prose.

Prose also breaks silently. Somebody changes the message from "User X placed order Y" to "Order Y placed by user X" for readability, and every dashboard built on a regex stops working. Nobody notices until the next incident.

The fields that matter

A correlation id on every line. The single most valuable field. Without it you cannot reconstruct what happened to one request across services.

Generate it at the edge, propagate it through every call, attach it to every log line:

import { AsyncLocalStorage } from "node:async_hooks";
const context = new AsyncLocalStorage();

app.use((req, res, next) => {
  const requestId = req.get("x-request-id") ?? crypto.randomUUID();
  res.set("x-request-id", requestId);
  context.run({ requestId }, next);
});

// logger automatically includes it
const logger = pino({
  mixin: () => ({ requestId: context.getStore()?.requestId }),
});

AsyncLocalStorage is the mechanism that makes this work without threading a parameter through every function. Returning the id in the response header matters too, so a user reporting a problem can give you something you can search.

A stable event name. event: "order.placed" is a machine identifier that should never change. The human message can be edited freely.

Identifiers, not descriptions. userId, orderId, merchantId, variantId. These are what you join on.

Duration on anything that takes time. durationMs on external calls, database queries, and handlers. Without it you cannot find the slow thing.

The outcome. Success or failure, and the error code if failure. Logging only failures means you cannot compute a rate.

What not to log

Secrets. Tokens, passwords, API keys, full card numbers, session ids. Obvious and it happens constantly, usually by logging a whole request object.

Redact at the logger, not at every call site:

const logger = pino({
  redact: {
    paths: ["req.headers.authorization", "req.headers.cookie",
            "*.password", "*.token", "*.apiKey", "*.card.number"],
    censor: "[redacted]",
  },
});

Doing this centrally is the only version that works, because doing it per call site depends on everyone remembering.

Personal data you do not need. Log a user id, not an email address. Under GDPR a log containing personal data is personal data, subject to deletion requests and retention limits. A log of opaque ids largely is not, which makes your life easier.

Entire request and response bodies at info level. Fine at debug on a sampled basis, and at scale it is expensive and it is where secrets leak.

Anything you cannot act on. logger.info("entering function") is noise. Noise makes real signal harder to find, and there is a genuine cost to logging things nobody will ever query.

Levels, used consistently

Teams argue about this and then use them inconsistently anyway. A working definition:

ERROR means something failed and a human needs to know. If nobody would act on it, it is not an error. A validation failure on user input is not an error, it is expected behaviour.

WARN means something unexpected happened and the system recovered. A retry succeeded. A fallback was used. A deprecated endpoint was called.

INFO means a significant business event happened. Order placed, payment captured, user registered. These should be sparse enough to read.

DEBUG means detail useful when investigating. Off in production by default, switchable per module.

The test I use for ERROR: would you want to be paged for a thousand of these in an hour? If not, it is a WARN.

The most common failure is logging handled errors at ERROR level. If you caught it and returned a sensible 400, that is INFO at most. Filling the error log with expected outcomes trains everyone to ignore it, and then the real error is invisible.

Log the negative case

Something people almost never do.

const match = rules.find(r => r.matches(input));
if (!match) {
  logger.debug({ event: "rule.no_match", inputId: input.id,
                 candidateCount: rules.length }, "no matching rule");
}

Silence is ambiguous. It could mean the code did not run, or it ran and found nothing. Those are completely different diagnoses and only one line separates them.

Same reasoning as logging the negative case in print debugging, and it matters more in production where you cannot add the line retroactively.

Sampling

At volume, logging everything is expensive and mostly useless. Log all errors, and sample the successful path:

const shouldSample = () => Math.random() < 0.01;

if (result.ok) {
  if (shouldSample()) logger.info({ event: "request.completed", ...fields });
} else {
  logger.error({ event: "request.failed", ...fields });
}

Sample by trace, not by line. If you sample individual lines you get fragments of many requests and complete records of none. Decide once per request whether to log it, then log everything for that request. That gives you complete stories for one percent of traffic, which is far more useful.

Logging in a container

Two rules.

Write to stdout, one JSON object per line. The runtime collects it. Do not write to files inside a container, do not implement rotation, do not ship logs from inside the application.

Flush before exiting. Most loggers buffer. A process that exits immediately on a fatal error loses the log line explaining why, which is the worst possible outcome:

process.on("unhandledRejection", (reason) => {
  logger.fatal({ err: reason }, "unhandled rejection");
  setTimeout(() => process.exit(1), 100).unref();
});

If you have a pod restarting with no useful log, unflushed logs on exit is a strong suspect.

One exception to the stdout rule: if your log volume is high enough that stdout becomes a bottleneck, the write is synchronous and it will block your event loop. Pino's transport mechanism moves serialisation to a worker thread for this reason, and it is worth using at scale.

What good looks like during an incident

The test of a logging setup is a single question you should be able to answer in under a minute:

"A user reports order 8823 failed at 09:14. What happened?"

With correlation ids and structured events, that is one query returning every line across every service for that request, in order, with timings.

Without them, it is grepping several services for a string and trying to line up timestamps.

If your setup cannot answer that question quickly, that is the gap to close, and it is worth more than any amount of dashboard work. It is also the foundation for everything else you might want to measure.