Chapter 7 — Logs

The Flight Recorder: Writing Logs You Can Debug With, and Reading Them Under Pressure

Part 2: Instruments. Prerequisites: Chapters 1–6. Concept background: SD QA Q53 — Structured logging.

Opening

The browser and curl show you a request while you watch it. Production bugs happen to requests nobody was watching — at 3 a.m., for one customer, on one server out of twenty, twelve hours before anyone noticed. The only record of what happened is what the system wrote down at the time.

That makes logs the flight recorder of your system. When they are good, an incident is a search: filter, group, follow one request from end to end, find the first failure. When they are bad — unstructured, missing the request ID, full of noise, empty where it mattered — the incident is a guessing game played against the clock.

This chapter covers both sides: what a useful log line contains, and how to read thousands of them under pressure.

Part 1: Anatomy of a Log Line

Every useful log line answers four questions: when, how serious, what happened, and in what context.

{
  "time": "2026-10-10T14:05:31.482Z",
  "level": "error",
  "msg": "payment provider request failed",
  "service": "checkout-api",
  "version": "a3f9c21",
  "request_id": "req_7f3c9a",
  "user_id": "u_1042",
  "route": "POST /checkout",
  "upstream": "payments",
  "duration_ms": 30012,
  "error": { "type": "TimeoutError", "message": "request timed out after 30000ms", "stack": "…" }
}

Timestamps

• Always UTC, always ISO 8601 (2026-10-10T14:05:31.482Z; the Z means UTC). When logs from servers in different time zones are mixed, local times make the order of events impossible to read.
• Millisecond precision. Many events happen within the same second.
• Clocks on different machines drift slightly (clock skew), so when ordering events across servers, a few milliseconds of disagreement is normal. Order events within one request by the request ID, not only by time.

Levels

Levels exist so you can filter. They only work if everyone uses them the same way:

Two failure modes ruin levels. Everything is error: every handled 404 and validation failure logged as an error, so real errors drown and alerts on error counts fire constantly (alert fatigue). Nothing is error: failures logged as info with the word "failed" in the message, so filtering by level finds nothing.

Part 2: Structured Logs

A structured log is a log line written as data — usually one JSON object per line — instead of a sentence.

# Unstructured
[2026-10-10 14:05:31] ERROR Payment failed for user 1042 after 30012ms (timeout)

# Structured
{"time":"2026-10-10T14:05:31.482Z","level":"error","msg":"payment failed","user_id":"u_1042","duration_ms":30012,"error":{"type":"TimeoutError"}}

The unstructured line is easy for a person to read once. The structured line can be queried: "every error where duration_ms > 10000 grouped by upstream" is one filter, not a regular expression you write in a panic. Structured logs also solve a classic problem with text logs: a multi-line stack trace in a text log becomes many separate log entries, and the lines of different errors interleave. In JSON, the stack is one field of one entry.

The fields that make a log line debuggable

That last row is underrated. Many investigations stall on "the email was never sent, and nothing was logged." Logging the reason a branch was taken turns silence into evidence.

Part 3: Correlation IDs — Following One Request Everywhere

A single user action may touch a gateway, three services, a queue and a database. Each writes its own logs. Without a shared identifier, connecting them means guessing by timestamp.

A correlation ID (also called a request ID) is a unique ID created when a request enters your system and passed along to every service it touches. Every log line includes it. A trace ID is the same idea, standardised for distributed tracing (Chapter 10) and carried in the W3C traceparent header.

Three practices make correlation IDs work:

1. Create it at the edge (gateway, load balancer, or the first service), or accept one from the client.
2. Propagate it on every outgoing call — HTTP headers, queue message metadata, background job payloads.
3. Attach it to every log line automatically. In Node, AsyncLocalStorage holds per-request context across awaits, so a logger can read the current request ID without every function passing it around.

Then return it to the client — in a response header and in error messages ("Something went wrong. Reference: req_7f3c9a"). When a customer contacts support with that reference, you can find their exact request in seconds instead of searching by "around 2 p.m., I think."

Part 4: Where Logs Live

In modern deployments, an app writes logs to standard output (stdout) and standard error (stderr). A log collector (an agent on the machine, or the platform itself) ships them to a log aggregator — a searchable store such as Datadog, Grafana Loki, Elasticsearch, CloudWatch, or your hosting platform's log view.

Facts about that pipeline that matter while debugging:

• Logs can arrive late and out of order. Shipping is asynchronous. A missing line may simply not have arrived yet.
• A crashed container's local logs vanish unless they were shipped. In Kubernetes, kubectl logs --previous shows the last crashed container's output — usually the line that explains the crash (Chapter 3).
• Retention is limited. Logs are often kept for days or weeks, not forever. Old incidents may have no logs left.
• Logs may be sampled. High-volume info logs are sometimes kept at 10% or less. A missing line is not proof that something did not happen.

Part 5: Reading Logs During an Incident

The mistake under pressure is reading logs top to bottom, or chasing the loudest error. The technique is to narrow, count, compare, and follow.

1. Narrow by time

Start from when the problem began, as precisely as you can. Look at a window just before and after it. The first new error after a known-good period is worth more than ten thousand repeats later.

2. Count and group — find the biggest bucket

Do not read lines; count them. Group errors by type, route, version, host or tenant:

# JSON logs in a file: the most common error types
jq -r 'select(.level=="error") | .error.type' app.log | sort | uniq -c | sort -rn | head

#    4212 TimeoutError
#      37 ValidationError
#       3 TypeError

Most aggregators have the same operation as a "group by" or "top values" view. The biggest group is your first lead.

3. Compare with the baseline — is this error new?

Every production system has background errors that are always there. Before chasing an error, check whether it also appeared yesterday at the same time. If ValidationError happens 40 times an hour every day, it is not your incident. The incident is what changed.

4. Correlate with changes

Line up the start of the errors with deploys (the version field makes this trivial), config changes, feature flag changes, traffic spikes, and upstream incidents. "Errors started at 14:05; version a3f9c21 went live at 14:03" is a strong lead (Chapter 1: correlation is a lead, not proof).

5. Follow one request end to end

Pick one failing request and filter by its request_id. Read every line it produced, in every service, in order. This turns "4,212 timeouts" into one concrete story: which service called which, what each one saw, and where the time went.

6. Look for what is missing

An expected line that is not there is evidence. If every successful checkout logs "payment authorised" and the failing ones never do, the failure is before that point.

The commands

Part 6: Logging Bugs That Hurt You Later

Logging secrets and personal data. Tokens, passwords, API keys, full card numbers, and often emails and phone numbers do not belong in logs. Logs are copied, shipped, retained and read by many people. Redact at the logger: most structured loggers can mask fields such as authorization, password and cookie automatically.

Logging too much in hot paths. A log line inside a loop over 100,000 items costs CPU, I/O and money, and can slow the request it is describing. Heavy synchronous logging can even block Node's event loop (Chapter 8). Use a fast structured logger, and log summaries ("processed 100,000 rows in 4.2 s, 12 failed") instead of one line per item.

Messages with no context. "Error occurred" or "Something failed" with no IDs, no route and no error object is close to useless.

The {} error. JSON.stringify(err) produces {} (Chapter 2). Make sure the logger serialises type, message, stack and cause.

Logs used as metrics. Counting log lines to compute request rates is slow, expensive and breaks when logs are sampled. Rates and latencies belong in metrics (Chapter 10).

The same error logged five times. Each layer catches, logs and rethrows. One failure becomes five error lines, and error counts become meaningless. Log an error once, at the boundary that handles it; inner layers should add context (with cause) and rethrow.

Part 7: What Good Logging Looks Like

• Log at boundaries. Every incoming request (once, at the end, with status and duration), every outgoing call to another system (with target, status and duration), every error, and every significant business event.
• One rich line per request. Many teams emit a single canonical log line at the end of each request containing everything: route, status, duration, user, version, upstream timings, error. One line per request is easy to count, group and alert on.
• Log decisions and skipped work. "Not retrying: error is not retryable (23505)." "Skipping webhook: endpoint disabled."
• Include the version. The commit SHA in every line is the fastest way to tie a problem to a deploy.
• Make log levels configurable at runtime where possible, so you can turn on debug for one service during an investigation without a redeploy.

The Worked Example — "Some Checkouts Are Failing"

Symptom. Support reports that "some customers" cannot check out. The error rate on POST /checkout is 6%, up from a baseline of 0.2%.

1. Narrow by time. Filter logs to route = "POST /checkout" and status >= 500. The first one appears at 14:05:12. Before that, almost none.

2. Count and group. Group by error.type: 98% are TypeError: Cannot read properties of undefined (reading 'currency'). One bucket — good.

3. Group by other fields. By version: all failures come from a3f9c21, deployed at 14:03. By tenant_id's region: every failure is an EU customer. US customers on the same version succeed.

4. Follow one request. Filter by one failing request_id. The checkout service logs "fetched price quote" with quote: { amount: 4999 } — no currency field. The pricing service's line for the same request ID shows it returned a quote from a new EU pricing table added in the same release.

5. Root cause. The release added an EU pricing table without a currency column in the response mapping, and the checkout code assumed quote.currency always exists.

6. Mitigate and fix. Roll back to the previous version (EU checkouts recover). Fix the mapping, add validation of the quote shape at the service boundary, and add a test with an EU tenant.

Every step was a filter or a group, not reading. The request ID turned "some customers" into one specific story in about five minutes.

The Causal Chains

The Rule You Keep Forever

Never read logs; query them. Narrow by time, count and group to find the biggest new bucket, compare with yesterday, line it up with changes, then follow one request ID end to end — and write every log line so that tomorrow's you can do exactly that.

Vocabulary Map

Practice Problems

Problem 1 — Fix the log line. Rewrite this log line into a structured line with every field you would need during an incident: console.log("Error: failed to update order", err.message).

Problem 2 — Find the incident. Error logs show three buckets in the last hour: 9,000 RateLimitError, 400 ValidationError, 120 ConnectionResetError. Yesterday at the same time: 8,800 RateLimitError, 410 ValidationError, 0 ConnectionResetError. Which do you investigate first, and why?

Problem 3 — The missing ID. A request passes through a gateway, an API, a queue and a worker. The worker's logs never include the request ID. Explain where the ID is being lost and what change fixes it.

Problem 4 — Five errors for one failure. A single failed database write produces five error lines from the repository, service, controller, middleware and global handler. What does this do to your error metrics, and how should the code be changed?

Problem 5 — Command line. Write the jq (or grep) command that prints the five slowest requests to GET /search in a JSON log file, showing the time, duration and request ID.

What's Coming Next

Logs tell you what happened. When the question is why the process itself is behaving badly — slow for everyone at once, using more and more memory, hanging without an error — you need to look inside the running Node process. Chapter 8 covers the inspector and breakpoints on the server, the event loop and how one slow function blocks every request, CPU profiles and flame graphs, memory growth and heap snapshots, and the async bugs that produce no error at all.