A customer says their payment failed. You open the log search, type their email, and get back a handful of lines in three formats, none of which say why. Here's how a normal checkout handler ends up there:
Run it for one user and it reads like a story. Run it for real traffic, two checkouts a few hundred milliseconds apart, and this is what the log viewer shows:
Which payment attempt 1: declined is whose? Both lines are
identical, and neither carries a user, order or request ID. The
ticket says "declined, then it worked, but I paid twice", and you have
four lines that could belong to either customer.
Tagging every line with a request ID lets you reassemble one request, which helps, but you're still joining a dozen rows in your head, and you only get the fields someone typed on that line. The decline reason, the attempt number, the user's plan: if they weren't on the line, they existed in memory for a moment and then were gone.
Why "just use OpenTelemetry" doesn't fix it
#opentelemetry is a real answer to a
different question: how do you get logs, traces, and metrics off a box
and into a vendor without hand-rolling an exporter for each one. It
says nothing about what a log line should contain. Wrap the same
step-by-step logging in OTel spans and you get the same thirteen
disconnected fragments, now shipped over a standard protocol instead
of stdout. The problem was never the transport.
The fix: one wide event per request
The fix is a wide event: instead of a log line per step, build a single event object over the life of the request, adding fields to it as things happen, and emit it exactly once, at the end. Stripe calls the same idea a canonical log line: one row per request that's the authoritative record of what happened to it.
Each request builds its own event in its own closure, so there's nothing to interleave. At the end, one call writes every field that mattered as one row:
Same traffic, same viewer, one row per request. The level now tells
you the outcome before you read anything: error never completed,
warn completed with something off, debug was boring enough to
ignore.
The support ticket is now one query, userId = usr_412: first
attempt declined for insufficient funds, second succeeded, order
created. And the same fields answer the aggregate questions too
("decline rate for insufficient_funds this week?"), so logs and
dashboards stop being separate systems fed by separate code.
The event is only as good as its fields
The createEvent helper (full version in the snip)
is deliberately thin: an object, a .set(), an .emit(). All the
value is in which fields you set, and teams get that wrong in a
predictable direction.
| Field kind | Example | Usual instinct | Why that's wrong |
|---|---|---|---|
| Low cardinality (few values) | httpMethod, outcome | keep | fine, but rarely what you search by |
| High cardinality (many values) | userId, orderId, declineCode | drop, "too expensive" | these are exactly what an incident searches by |
| Failure-path detail | decline codes, retry count | set on success only | the failure path is where you need them |
The "drop high-cardinality fields" habit comes from string-search log
platforms that charged the most to index them. Column stores like
#clickhouse don't, so the habit no longer
earns its keep. Two more rules: a logger.info inside a helper or a
loop brings the interleaving back, so call event.set() there
instead; and at real volume, tail-sample: keep every error and slow
request, and sample the fast, boring successes down to a few percent.
The original handler wasn't wrong like a bug is wrong. It ran, it returned the right response, it logged at every step. It was wrong like a filing cabinet with no folders: everything is in the building somewhere, and finding it mid-incident is your problem. One event per request, built as the request runs and written once at the end, is the index.