Structured Logs and Correlation

A log line is a record of one event, written by the code, read by a machine first and a human second. print(f"charged {order}") is neither: it cannot be filtered, it does not say which request it belongs to, and it prints the order object's repr with the buyer's email inside it. One JSON object per event, with a fixed set of typed fields, the request id on every line, and a redaction list applied by the logger itself, is what turns "show me everything that happened to order 4471 last Tuesday" from a grep across four hosts into one query that answers in under a second.

Stagedoor's logs were the first thing Marek rebuilt after the spring on-sale, because the night's questions could not be answered from them. Which two requests charged the buyer: unanswerable, neither carried an id. Why the emails were late: the worker wrote "email sent" 40 minutes after each checkout, into a file on worker-01 that nobody opened until the morning. This topic is the format, the id that joins the lines, what earns a line and what does not, the four levels and who each one is for, the processor that keeps secrets out, and the arithmetic that keeps an on-sale night's logs affordable.

One Line, One Event, JSON

The demonstrated line is the Payrail charge, the event Chapter 11 showed with the key redacted, now in its full shape. Every line Stagedoor writes has the same first five fields, in the same order, and then the fields that belong to the event.

{"ts": "2026-09-18T21:03:56.710Z", "level": "info", "event": "payrail.charge",
 "request_id": "01J8Q6M2K7V3Z9X4B0N5R8T1WC", "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736",
 "order_id": "9c1f6e2a-0b3d-4f8e-a7c2-5d9e1b4f3a60", "status": "charged",
 "amount_cents": 9000, "payrail_ref": "ch_7Kd...", "duration_ms": 412,
 "host": "api-01", "env": "production"}

The line says: at this instant, at info level, the event named payrail dot charge happened, inside this request and this trace, for this order, with the outcome charged, for 9,000 cents, with Payrail's reference, and it took 412 milliseconds on api-01 in production. Three things about its shape carry the whole design. The event is a stable dotted name, never a sentence: payrail.charge today, tomorrow and on every host, so that "how many charges in the last minute" is a count of one value rather than a regular expression over prose that somebody will reword. The fields are typed: 412 is a number the viewer can sort and graph, not the characters four one two inside a string, and the order id is a field with a name, not something to be found between "order" and "was". And the line is written to be read through the collector's viewer, filtered and grouped, never with tail; a human who needs it opens the viewer, types the request id, and reads seven lines instead of scrolling a terminal.

The process writes the line to standard output and nothing else, as Chapter 11 arranged. Where it goes from there, and how long it is kept, is the platform's job and Observability Deep Dive's subject. The service's job is to make every line worth collecting.

The Request Id on Every Line

The first middleware ring of Chapter 4 reads the client's X-Request-Id or generates one and puts it in the request context. From that moment no call site mentions it again: the logger has a processor that reads the context variable and adds request_id and trace_id to every line before it is rendered, so the storage layer, the Payrail client and the domain rules all write lines that carry the id without any of them knowing what a request is. That is the automatic stamping Chapter 4 promised, and it is the reason the id is on the access line, the charge line and the warning from the retry wrapper without three developers remembering three times.

The id leaves the process by two paths and comes back on both. The outbound client puts it in the X-Request-Id header of the Payrail call, so Payrail's support can find the charge from Stagedoor's id. The outbox row's payload carries it into the stream, and the worker rebuilds its context from the payload before its first log line, as Chapter 8 arranged. The demonstrated query is the one the night's question needs: every line for one request id, across hosts, in time order.

Seven lines, in order, from two processes on two hosts, and the join between them is the id and nothing else. On the spring on-sale night the same question was a grep on api-01, a grep on api-02, a guess about which one had served the request, and a separate grep on worker-01 by order id, because the job's lines carried no request id at all. On the second on-sale night the query above answered "where did this buyer's three minutes go" in one screen: 4 seconds in the API, three minutes between http.response and job.start, 4 seconds in the render. The gap is the queue, and Chapter 8 already knew that from its age gauge; the log is where the one buyer who wrote in is found.

What to Log

A line is written for an event that somebody will search for, and the list is short. The request's start and end, with method, route, status and duration: the access log of Chapter 4, one pair of lines per request. Every call that leaves the process, with its target, its status and its duration: the Payrail charge, and also each retry attempt, each breaker rejection, each pool acquire that waited longer than a second. Every state transition of a domain object: the order from pending to paid, the hold created and the hold expired, the ticket scanned. Every change of a breaker's state from Chapter 7, because a breaker that opened at 19:04 is the first line anyone reads in the postmortem. Every job's start and end in the worker, with the kind, the duration and the outcome.

The list has a negative half that matters as much. Not every function call: a line that says holds.create was entered and another that says it returned add two lines per request and answer no question the access log and the transition line did not. Not the body of the request or the response: the seat labels are in the order's transition line, and the rest of the body is the buyer's data in a store with a 30-day retention. Not a line per row processed: a reconciliation over 4,000 orders writes one line with a count and a duration, not 4,000 lines, and the disagreements it finds are the lines worth writing. The test for a candidate line is whether the person reading the seven lines above would be glad to see it between them, or would have to scroll past it.

Levels That Mean Something

A level is a statement about who should act, and there are four. error means a person should look: the unhandled exception that became a 500, the job that exhausted its deliveries and went to the dead-letter stream, the reconciliation that found an order Payrail charged and Stagedoor has as pending. warning means degraded but handled: the breaker opened, the retry budget ran out and the buyer got a clean 504, the seat map was served from a stale cache because Redis timed out. info is the list above, the events that happened as designed. debug is the developer's line, the SQL with its parameters, the cache key computed, the token's claims after parsing, and it is off in production and on in Marek's shell.

The level that goes wrong is error. Stagedoor's first version logged a declined card at error, and on an ordinary Saturday that was 140 error lines an hour with nobody looking, because a declined card is the buyer's problem, handled with a 402, and belongs at info as the outcome of a charge. When the Payrail key was wrong after a rotation and every charge failed, the real errors landed in the same stream at the same level and looked the same. An error that fires a hundred times an hour with nobody looking is a level chosen wrong, and the fix is to move the event down, not to mute the level. The count of error lines is a metric in the next topic, and it is only useful if the count is normally near zero.

Redaction at the Logger

Chapter 11 listed what must never reach a log line: the Authorization and Set-Cookie headers wherever a request is logged, any field named for a password, a card, a secret or a token, every SecretStr, and the buyer's email except its domain, which is enough to see that a delivery problem is one provider's. The place to enforce that is the logger's processor chain, which runs on every line from every call site before the JSON is rendered, so that the one call site that forgot cannot exist. The demonstrated processor is ten lines, and the mistake it prevents is the Payrail key sitting in the aggregator's index, searchable by anyone with a viewer login, for the length of the retention.

REDACTED = {"authorization", "set-cookie", "cookie", "password", "card", "card_number"}
REDACTED_SUFFIXES = ("_key", "_secret", "_token", "_password")

def add_request_ids(logger, method, ev):
    ctx = request_ctx.get(None)                   # Chapter 4's context variable; None in the shell
    if ctx:
        ev["request_id"], ev["trace_id"] = ctx.request_id, ctx.trace.id
    return ev

def redact(logger, method, ev):
    for key, value in list(ev.items()):
        name = key.lower()
        if name in REDACTED or name.endswith(REDACTED_SUFFIXES) or isinstance(value, SecretStr):
            ev[key] = "[redacted]"
        elif name == "email" and "@" in str(value):
            ev[key] = "*@" + str(value).split("@", 1)[1]   # keep the domain, drop the person
    return ev

structlog.configure(processors=[
    add_request_ids,
    structlog.processors.add_log_level,
    structlog.processors.TimeStamper(fmt="iso", key="ts"),
    redact,
    structlog.processors.JSONRenderer(),
])

A processor is a function that receives the event dictionary and returns it changed, and the logger runs the list in order on every line. The first one reads the request context and stamps the two ids; the next two add the level and the timestamp; then the redaction pass replaces the value of any field on the name list, any field whose name ends in key, secret, token or password, and any value that is a SecretStr, and trims an email to its domain; and the last one renders the dictionary as one JSON line. The order is deliberate: the ids are added before redaction so that they are subject to it too, and the renderer runs last so that nothing after it can add an unredacted field. The retry wrapper of Chapter 7 can log the whole outbound request object in its warning and the Authorization header comes out as the word redacted, which is the property Chapter 11 relied on when it said the key is in no log line anywhere.

Cost

A line per request at the on-sale peak of 3,000 requests a second is 3,000 lines a second, and the access line above is about 250 bytes, so the access log alone is 750 kilobytes a second, 2.7 gigabytes an hour, and 450 megabytes for the ten minutes of the on-sale itself. Add the outbound-call lines and the transitions and the night writes about twice that. The bill is the smaller problem. The larger one is the aggregator's indexer, which on the spring on-sale night fell an hour behind the stream and made the logs unsearchable during the only hour anyone needed them.

The fix is sampling with a rule, applied in the access-log ring before the line is written. Every 4xx and 5xx response is logged. Every response slower than 800 milliseconds, the checkout SLO's threshold from Topic 71, is logged. Of the successful, fast responses, 1 in 10 is logged, chosen by the request id so that the decision is the same for every line in that request. On the night that keeps about 390 lines a second instead of 3,000, 350 megabytes an hour instead of 2.7 gigabytes, and every line that describes something wrong. What the sampled log can no longer do is count: "how many checkouts succeeded between 21:00 and 21:10" is not a question for a log that kept 10 percent of them. That count is a metric, incremented for every request whether or not its line was written, and the next topic is where it lives.