Checkout is failing. The alert says elevated 5xx on POST /v1/orders. I open the log viewer, filter service:checkout AND level:error, and get 4,000 lines of "upstream request failed". I still cannot tell the on-call engineer whether we broke it or the payment provider did.
That was the whole problem. We had structured logs. We did not have observability.
The three questions you answer in the first minute
An incident has a clock on it. In the first minute, three questions decide everything downstream:
Is it us or the dependency? Since when? Who is affected?
Our logs answered none of them. "upstream request failed" names no upstream. Nothing recorded the provider's HTTP status, its error code, or our timeout budget. Nothing recorded the start of the breakage, so I guessed from the alert timestamp. Nothing recorded the customer, so "who is affected" became a support-ticket lottery.
I have watched a four-person team spend forty minutes on that guesswork. The fix was not a logging library. It was deciding which fields must exist on every log line that touches an outbound call.
High-cardinality context beats log formatting
The industry argument about logs versus metrics versus traces misses the point. Format is cheap. Context is what you can query.
A JSON log line with "message": "request failed" is a plaintext string wearing braces. A line you can actually use carries the request identity, the caller, the dependency, the outcome, and the duration:
logger.error(
"upstream request failed",
extra={
"trace_id": trace_id,
"request_id": request_id,
"tenant_id": tenant_id,
"route": "POST /v1/orders",
"upstream": "payments-api",
"upstream_status": resp.status_code,
"upstream_error_code": body.get("code"),
"attempt": attempt,
"timeout_ms": 2000,
"duration_ms": elapsed_ms,
},
)
tenant_id is the field that ends arguments. Cardinality is the reason people strip it out โ a million tenants is a million series in your metrics backend, and that cost is real. But logs are not metrics. You can afford tenant_id in a log line for thirty days. You cannot afford to not know which customers are broken.
The rule I use now: anything I have ever needed to group by during an incident belongs on the log line. That list ends up short and stable. Tenant, route, upstream, status, error code, attempt, trace ID.
Correlation IDs across service boundaries
A trace_id that dies at the first network hop is decoration. The field has to survive the hop and be readable by a human at 3 a.m.
Concretely: accept an inbound trace header, generate one if it is missing, propagate it on every outbound call, and log it on both sides. In Go, that is one context value and one HTTP header.
func WithTrace(ctx context.Context, r *http.Request) context.Context {
id := r.Header.Get("traceparent")
if id == "" {
id = newTraceID()
}
return context.WithValue(ctx, traceKey{}, id)
}
func InjectTrace(ctx context.Context, req *http.Request) {
if id, ok := ctx.Value(traceKey{}).(string); ok {
req.Header.Set("traceparent", id)
}
}
The failure mode I hit was subtle: the gateway generated a trace ID, the checkout service read it, and the payments client created a fresh one because it built a new http.Request from scratch. Two traces, zero correlation. On the dashboard it looked like coverage.
Then the query becomes boring, which is the goal. One ID, every service, ordered by time:
SELECT ts, service, event, upstream, upstream_status, duration_ms
FROM logs
WHERE trace_id = '4bf92f3577b34da6a3ce929d0e0e4736'
ORDER BY ts;
If your log store cannot run that query in under a second, you do not have the capability you think you have.
Sampled logs lie about the tails
We sampled at ten percent to control cost. Then the incident happened in the unsampled ninety percent, and the one line that explained it โ the timeout on attempt three, from the one region with a bad route โ was not there.
Sampling is fine for volume. It is wrong for the signal you need when something breaks. Keep every error-level line unsampled, keep slow-request lines unsampled above a threshold you choose, and sample the boring successes. That asymmetry is what makes tail analysis possible.
If you want to know whether your sampling is hiding the answer, measure it: take a known incident window, disable sampling for it, and count how many of the decisive lines were absent under your normal policy. I did this once and found the answer line missing in nearly every sampled case.
"We log a lot" is not "we can answer a question"
The honest test is not volume. Write down the questions from the first minute of your last incident. Is it us or the dependency? Since when? Who is affected? Then run each one as a query against your log store, timed, using only what your services emit today.
If a question takes four minutes of clicking, that is the gap. Close it by adding the field, not the log line. Formatting was never the problem.
I write about production failures in Postgres, queues, and distributed systems.
Subscribe by email ยท RSS ยท Bluesky
