Twelve lines, three rows

Three users check out at the same time. One payment fails. Here is what a line per step leaves in your log:

checkout started user_id=u_1
checkout started user_id=u_2
checkout started user_id=u_3
cart loaded user_id=u_2 items=3
cart loaded user_id=u_3 items=3
charging card last4=4242
cart loaded user_id=u_1 items=3
payment failed
charging card last4=4242
charging card last4=4242
order created id=o_u_3
order created id=o_u_1

Nothing in those twelve lines says which user’s payment failed. payment failed sits between u_2 and u_3, and it is not next to either one for any reason except scheduling. You can work it out by elimination, since three checkouts produced two order created lines and u_2 is the one missing, but that is reasoning from absence. It works here because there are three requests. At four hundred it stops working.

None of those lines is badly written, and every one of them carries a real fact. They were written separately, and the log has no way to put them back together.

One row per operation

The same three checkouts, logged as wide events:

{"level":"error","service":"checkout","duration_ms":3.27,"op":"checkout","user":{"id":"u_2"},"cart":{"items":3},"payment":{"last4":"4242"},"error":{"message":"Payment failed","status":402,"code":"CARD_DECLINED","why":"Issuer declined the charge","fix":"Try a different payment method","type":"WidelogError"}}
{"level":"info","service":"checkout","duration_ms":6.45,"op":"checkout","user":{"id":"u_3"},"cart":{"items":3},"payment":{"last4":"4242"},"order":{"id":"o_u_3"}}
{"level":"info","service":"checkout","duration_ms":9.87,"op":"checkout","user":{"id":"u_1"},"cart":{"items":3},"payment":{"last4":"4242"},"order":{"id":"o_u_1"}}

Twelve lines became three rows, and the failed one names itself. u_2 failed, the issuer declined it, the cart had three items, it took 3.27ms to find out, and whoever reads this at 3am is told what to try next.

Nothing was stitched together to get there. Four different functions wrote those fields during the request, and they landed in one object because use_logger() reads a contextvars slot instead of taking a logger argument. Concurrency is what makes line logs ambiguous, and keeping concurrent work straight is what contextvars is for.

The failure nobody reported

{"level": "warn", "op": "checkout", "retries": 2, "status": 200}

That user got a clean 200. Their order went through, they noticed nothing, and they will not be filing a ticket. The pricing service reset the connection twice on the way, and the row says so.

A wide event covers the whole operation, so the row exists whether the checkout succeeded, failed, or succeeded on the third try. You get all of this without writing extra instrumentation:

• a denominator, so an error rate is errors / operations rather than errors / guesswork
• degraded paths that still returned 200, such as retries and fallbacks
• duration_ms on every row, so a latency regression shows up without a separate metric

A line-per-step setup records that retry only if somebody thought to log the retry. Here it is in the row because the row covers the operation either way.

Two bugs wearing the same face

Both of these reached the user as 500, and both say RuntimeError: checkout failed:

outer=RuntimeError   root=KeyError       at services/cart.py:35
outer=RuntimeError   root=TimeoutError   at services/gateway.py:35

One is a cache miss and one is a payment gateway that stopped answering. At the surface they look identical, and they need different people woken up.

error.causes is the chain behind the error, following __cause__ before __context__, so raise ... from exc gives you the real origin rather than whatever happened to be in flight. Because causes[-1].type is a field rather than a substring of a message, you can group on it, count it, and page on it. That means alerting on the root cause instead of on a symptom that fifty unrelated bugs all produce.

The stack entries point at your code, since widelog filters its own frames out before recording them. The first line you read is never the logging library’s.

Handing it to a model

Everything above applies as much to a model reading the log as to a person. Two of these properties matter more when the reader is a model.

A model asked to explain the twelve-line version will answer. It will pick a user, describe the failure with some confidence, and be wrong a fraction of the time, because interleaved lines are exactly the shape that invites a plausible guess. One row leaves nothing to guess at.

Redaction matters for a different reason. Look back at the wide events: payment.last4 is there and the idempotency token is not, because keys ending in token, password, secret, authorization, apikey, and cookie are replaced at any depth before anything is written. Pasting logs into a model that somebody else hosts is a decision about where your credentials end up, and that decision gets much easier when the credentials were never in the log.

why and fix help as well, because you wrote them. A model reading CARD_DECLINED with why: Issuer declined the charge is repeating something you already knew rather than forming a hypothesis about it.

What this does not do

widelog produces the evidence and never looks at it. There is no alerting, no aggregation, no anomaly detection, and no sampling. Those belong to whatever you point sink at.

There is also no correlation identifier across services. Within one process the contextvars slot keeps a request’s fields together, and on Lambda the X-Ray trace_id is picked up for you, but a failure spanning three services gives a reader no key to join on unless you set one yourself. If that is your shape, put a request id on the event at the edge and thread it through, and the rows will line up.