Engineering Atlas › System Design Fundamentals

Writing logs that help during incidents

14 min read · last reviewed 2026-10-17

Open in the interactive app: practice, quiz, mock interview →

In one minute

How it works

This lesson is about what to put in log lines and how to emit them safely. The Log Aggregation lesson covers shipping and storage, and Design a Logging Framework covers logger hierarchies and sinks.

Events, not prose

Compare two lines that describe the same failure:

Failed to charge customer 8812 for order 55120 after 3 attempts: timeout
{"level":"error","event":"charge_failed","customer_id":8812,"order_id":55120,"attempts":3,"error":"timeout","provider":"acme","trace_id":"4bf9..."}

The first reads well once. The second can be counted by provider, filtered to one order_id, and joined to a trace. Write a stable event name that never changes when someone edits wording, and put variable data only in fields. Keep field names consistent across services (user_id, not userId in one and uid in another); the OpenTelemetry semantic conventions are a good default vocabulary (http.request.method, http.response.status_code, db.system) (OTel HTTP conventions). The OpenTelemetry log data model now has a first-class EventName field for exactly this stable name (OTel logs data model).

Levels as a contract

Teams misuse levels in two directions: expected conditions logged as ERROR (a 404, a validation failure), so real failures drown in noise; or handled-and-retried failures logged as INFO, so nobody sees a provider failing half its calls. A workable rule: ERROR when the unit of work failed and the system could not compensate; WARN when it succeeded through a fallback, a retry, or degraded data; INFO for state changes a human or auditor cares about (order placed, deploy started, config reloaded); DEBUG for everything else. If an ERROR line does not lead someone to do something, it is not an error.

Log once, at the boundary

A common anti-pattern is log-and-rethrow: the repository logs the SQL error, the service logs it again with more words, the handler logs it a third time. One failure becomes three ERROR lines with three stack traces. Instead, lower layers wrap the error with context (fmt.Errorf("load order %d: %w", id, err) in Go, exception chaining in Python and Java) and return it. The outermost layer that decides what happens to the request logs it once, with the full chain.

Context travels with the request

Every line inside a request should carry the request's identity without each call site passing it. Go's slog has logger.With("trace_id", id) and handlers that read the span from context.Context; Python uses contextvars with a logging filter; Java uses MDC (a thread-local map) which needs care with thread pools and virtual threads. The canonical-line pattern, popularised by Stripe (Stripe), goes further: accumulate fields in a request-scoped map as the request runs and emit one wide line at the end with route, status, duration, user tier, DB time, cache hits and the flags that were on. Searches then become group-bys over one line per request. Amazon reaches the same rule independently: one request log entry per unit of work, with the latency and status of every dependency call, and periodic entries only for long-running jobs (AWS Builders' Library).

What never to log

Passwords, tokens, session cookies, full card numbers, private keys, and request bodies that might contain any of them. Personal data (emails, phone numbers, addresses) only when there is a reason and a retention policy, ideally hashed or tokenised (OWASP). Prefer opt-in fields: a logger that prints whole request objects will start leaking the next sensitive parameter someone adds. Untrusted input must be escaped, or an attacker can forge lines by embedding newlines (CWE-117); truncating long values also stops a caller from filling the disk. Log4Shell (CVE-2021-44228) showed the extreme: Log4j 2 performed JNDI lookups on ${...} patterns inside logged strings, so logging a user-agent header was remote code execution. It scored the maximum CVSS 10.0, and the first fix (2.15.0) was incomplete, so a second CVE needed 2.16.0 (Apache Log4j security).

Volume control

A tight loop that logs at WARN on every iteration can produce 100,000 lines per second. Defences, in order of preference: do not log in the loop (count and log a summary); rate-limit identical messages and emit "suppressed N" summaries; sample INFO per event type; and always keep ERROR. This is the overload problem shape: the signal you need during an incident is generated fastest during the incident, and an unbounded producer will starve the consumer. The same shape appears in alert storms in a pager, and in a crash reporter that uploads the same stack trace from a million phones, where clients deduplicate by fingerprint and send counts.

Down the stack

Layer 1The contract

A log call is best effort. An asynchronous handler loses its queue on SIGKILL or the OOM killer, so the lines just before a crash are the likeliest to vanish. Order holds per logger within a process, not across hosts, and timestamps come from a wall clock that can jump. Under overload the library blocks the caller (Logback's AsyncAppender default, neverBlock=false (Logback docs)), drops events (neverBlock=true, zap's sampler), or grows memory without bound. Choose deliberately: "blocks the caller" means logging can stall request threads.

Layer 2The mechanism

Fast loggers do three things. They check the level first: slog's Handler.Enabled(ctx, level) and Python's cached isEnabledFor return in nanoseconds, and logger.debug("x=%s", x) defers formatting, unlike an f-string. They avoid allocation: zap and slog encode typed fields (zap.Int("attempts", 3)) straight into a pooled byte buffer. They move I/O off the request thread: Logback's AsyncAppender uses an ArrayBlockingQueue (default size 256) and, once less than 20 percent of capacity remains, discards TRACE, DEBUG and INFO while keeping WARN and ERROR; Python's QueueHandler and QueueListener split the work the same way. Zap's sampler counts entries per level and message in one-second ticks, logging the first Initial (100 in the production config) and then every Thereafterth (100) (zap config.go).

Layer 3The machine

In containers, stdout is a pipe read by the container runtime, and a Linux pipe holds 64 KiB by default (16 pages) (pipe(7)). If the runtime or log agent falls behind, the pipe fills, write(2) blocks, and a synchronous logger blocks whichever thread called it: logging becomes a hidden lock across all request threads. Pipe writes up to PIPE_BUF (4,096 bytes) are atomic, so lines from many threads do not interleave if each is one write; a 10 KB stack trace written in pieces can be split. Formatting costs 1 to 5 microseconds per JSON line, and allocation is the hidden cost: 20,000 requests per second times 10 lines times 500 bytes of garbage is 100 MB per second for the garbage collector. Services that log to local files have one more failure to plan for: a full disk. Decide in advance whether the service stops taking traffic or keeps running blind, rotate often, put logs on their own partition, and test with a nearly full disk (AWS Builders' Library).

Why it's built this way

  1. Most log calls are below the active level, so the fast path must exit before formatting or allocating.
  2. Enabled calls still run on the request thread, so I/O is moved to a queue drained by another thread.
  3. Queues are bounded to protect memory, so a full queue must either block or drop, and dropping low-severity events first keeps the lines that matter.
  4. The most valuable lines are often produced in a flood (one bug, one message, a million times), so sampling and rate limiting by message bound volume without losing the fact that it happened.
  5. Text is cheap to write but expensive to search, so structure is added at write time where it costs nanoseconds rather than at query time with regex parsing.

Diagram

flowchart LR
  C["log call"] --> E{"level enabled?"}
  E -- "no" --> X["return (ns)"]
  E -- "yes" --> R["build record + context fields"]
  R --> S{"sampler / rate limit"}
  S -- "suppressed" --> N["count for summary"]
  S -- "keep" --> Q["bounded async queue"]
  Q -- "nearly full" --> D["drop DEBUG/INFO"]
  Q --> W["writer thread: encode JSON"]
  W --> P["stdout pipe (64 KiB)"]
  P --> A["node agent"]

Worked example

A payments API handles 3,000 requests per second across 30 pods and logs about 12 lines per request: entry and exit at INFO, three repository calls at DEBUG (left on since an incident a year ago), cache hits, and a provider call. At an average of 450 bytes, that is 3,000 times 12 times 450 = 16 MB per second, 1.4 TB per day raw. At a managed ingest price of around 0.50 dollars per GB, the bill is about 21,000 dollars a month.

The team makes three changes: DEBUG off in production with a per-request override header for on-call; entry, exit and cache lines replaced by one canonical line per request with 35 fields (about 1.2 KB); and the provider's retry WARN rate-limited by message to 20 per 10 seconds with a "suppressed N" summary.

New volume: 3,000 times 1.2 KB is 3.6 MB per second, about 310 GB per day, roughly 4,700 dollars a month. Investigations got faster: "which merchants saw p99 over 2 seconds on the new build" is one group-by on the canonical line.

Three weeks later a provider outage produced 9,000 retry warnings per second. A previous outage like it had filled every pod's stdout pipe and blocked request threads, turning a provider problem into an API outage. This time each pod logged 2 warnings per second plus summaries counting the suppressed thousands.

In the wild

Trade-offs

OptionStrengthsWeaknessesChoose when
Synchronous loggingLines survive until the crash; simpleRequest threads block on slow I/OLow volume, CLIs, batch jobs
Async, bounded, drop low levelsRequest path never blocks; keeps WARN and ERRORLoses lines on SIGKILL and under floodsMost online services
Many small lines per requestEasy to add; tells a story in orderExpensive; hard to aggregateLocal debugging, startup and shutdown
One canonical line per requestCheap per request; every query is a group-byMust accumulate context; lost if the process dies mid-requestHigh-traffic request handlers
Sample or rate-limit by messageBounds floods; preserves countsLoses individual instancesHot-path warnings, retry loops

Pitfalls in production

Leadership lens

Check yourself

  1. Why is logger.debug("user=%s", user) cheaper than logger.debug(f"user={user}") when DEBUG is disabled?

    Show answer

    The f-string formats user (calling its __str__) before the call, while the %s form passes arguments unformatted and the logger returns after the level check without formatting.

  2. A service with a synchronous stdout logger becomes unresponsive when the node's log agent crashes. Explain the chain.

    Show answer

    The agent stops draining the container runtime, the 64 KiB pipe fills, write(2) blocks, and every request thread that logs blocks on it, so the service stalls even though its own code is fine.

  3. Why should rate limiting of repeated warnings emit a "suppressed N" summary instead of silently dropping?

    Show answer

    The count is the signal during an incident; silent dropping makes a 10,000-per-second flood look like 2 warnings per second, hiding the scale of the problem.

  4. When is one canonical line per request worse than several lines?

    Show answer

    When the process may die mid-request (a crash or OOM), since the line is written at the end and is lost, or for long-running jobs where you need progress before completion.

Sources and further study

Primary

Systems docs

Books

Other curricula

Watch

Free resources

Open in the interactive app: practice, quiz, mock interview →