Logging

1Why console.log Isn't Enough

console.log("order created", order.id);           // fine on your laptop

In production you have many instances, thousands of requests per second, and a log pipeline (CloudWatch, Loki, Elasticsearch, Datadog) that has to search, filter and aggregate those lines. Plain text forces people to grep with regexes. Production logging needs:

• levels — so noise can be turned down without a deploy
• structure — machine-parseable fields instead of sentences
• context — which request, which user, which trace
• speed — logging must not become the bottleneck

2Log Levels

A logger configured at level info drops debug and trace before doing any formatting work. Production usually runs at info; you raise to debug temporarily (ideally per module or per request) when investigating.

3Structured (JSON) Logging

import pino from "pino";
const logger = pino({ level: process.env.LOG_LEVEL ?? "info" });

logger.info({ orderId: order.id, userId: user.id, totalCents: order.total }, "order created");

{"level":30,"time":1718000000000,"pid":4242,"hostname":"api-7f9c","orderId":"o_81","userId":"u_12","totalCents":4599,"msg":"order created"}

Now the log backend can answer "all order created events for userId=u_12 in the last hour" or "p95 of durationMs per route" without regexes. Rules of thumb:

• message is a constant string; variables go in fields ("order created", not ` order ${id} created `) — so you can group by message
• consistent field names across services (userId, not user_id here and uid there)
• log errors as objects (logger.error({ err }, "charge failed")) so the serializer captures type, message and stack

4Request Context: Child Loggers and Correlation IDs

Every log line produced while handling a request should carry the same requestId (and ideally a traceId, see devops-cloud/observability/03-tracing_and_correlation_ids):

app.use((req, res, next) => {
  const requestId = req.headers["x-request-id"]?.toString() ?? crypto.randomUUID();
  req.log = logger.child({ requestId, method: req.method, path: req.path }); // fields bound once
  res.setHeader("x-request-id", requestId);
  const start = performance.now();
  res.on("finish", () => {
    req.log.info({ status: res.statusCode, durationMs: Math.round(performance.now() - start) }, "request completed");
  });
  next();
});

// later, deep in a handler:
req.log.warn({ attempt: 2 }, "payment retry");  // automatically includes requestId/method/path

Passing req.log down is explicit; AsyncLocalStorage (07-request_response_lifecycle/ section 6) lets services get the request's logger without threading it through every call.

5What NOT to Log

Use the logger's redaction feature rather than relying on discipline:

const logger = pino({ redact: { paths: ["req.headers.authorization", "*.password", "*.cardNumber"], censor: "[REDACTED]" } });

6Where Logs Go

The twelve-factor rule: the app writes an event stream to stdout; it doesn't manage files, rotation or shipping. The platform (Docker/Kubernetes log driver, systemd, a sidecar like Fluent Bit/Vector) collects stdout and forwards it to the backend. That keeps the app simple and the routing configurable per environment. Locally, pipe through a pretty-printer (node app.js | pino-pretty) instead of changing the app's output format.

Under the HoodWhy Fast Loggers Are Fast▾

Logging sits on the hot path of every request, so the implementation matters:

1. Level check first. logger.debug(obj, msg) at level info returns immediately — but the arguments are still evaluated by JavaScript before the call. logger.debug({ dump: JSON.stringify(hugeObject) }) pays the stringify cost even when dropped; guard expensive work with if (logger.isLevelEnabled("debug")).
2. Pre-serialized bindings. A child logger serializes its bound fields ("requestId":"...") once when created, and splices that string into every line, instead of re-serializing them per call.
3. No per-line formatting work. pino writes a JSON line with minimal string building; pretty-printing (colors, aligned timestamps) is done by a separate process reading the pipe.
4. Asynchronous/batched I/O. process.stdout writes to a pipe can block when the reader is slow. pino can buffer and flush via sonic-boom, or move I/O to a worker thread transport, so a slow log collector can't stall the event loop. The trade-off: on a hard crash, the last buffered lines can be lost — which is why fatal handlers flush synchronously before exit.

⚠️ Common Pitfalls

1. Interpolating variables into the message — impossible to group "same event" lines.
2. Logging secrets in headers, bodies or error messages (new Error(\login failed for ${password}\)).
3. logger.error(err.message) — loses the stack and error type; log { err }.
4. Logging and rethrowing at every layer — the same failure appears five times; log once, where it's handled.
5. Synchronous file logging in the request path — blocks the event loop.
6. Debug level left on in production — cost and noise explode.

📋 Quick Reference

🎤 Interview Q&A

🛠️ Practice exercises

Each exercise is a file in this topic folder. Code exercises are self-checking: run them and make the checks pass.

✅ Check yourself

Source: fw_logging_theory.md · generated by tools/build_lessons.py