Structured Logging

Written for a human reading one line

A line reading payment failed for user after retry is written for a human reading one line. Nobody reads one line.

Picture what you actually do during an incident. You ask questions across millions of lines. How many payments failed in the last hour, for which merchants, with which error codes.

Against free-form text those questions become regular expression archaeology, and your expression breaks the day somebody rewords the message.

Write every line as an object with named fields instead: the level, the service, the route, the user, the error code, how long it took, and a timestamp. Now your questions become queries, and you filter by error code and group by merchant in seconds.

Be boringly consistent, because that is what makes it work. The field is always the same name, never three variations on it, and the value is always a number, never a number with units glued on. Most teams enforce that with a shared library so nobody hand-rolls the format.

The field that pays the rent

Add the field that pays the biggest rent: a correlation identifier. Generate one at your edge, return it in the response, pass it to every downstream call in a header, and stamp it on every line the request produces in every service.

See what that buys you. One filter reconstructs a request's entire life across ten services. Without it, matching lines across services by timestamp is guesswork, and guesswork at 3am produces wrong conclusions.

Push it further with one wide line per request, emitted at the end, carrying fifty or more fields covering everything that happened. Instead of piecing together twelve separate lines, you query one dense record.

Adopt that habit if you adopt only one from this lesson, along with the correlation identifier that ties those wide lines together across services.

// Unsearchable. During an incident you are asking questions across
// millions of lines, and this answers none of them.
log.error("payment failed for user after retry");

// Named fields, so the question becomes a query.
log.error("payment_failed",
    kv("request_id", ctx.requestId()),   // the same id in all ten services
    kv("order_id", order.id()),
    kv("merchant_id", order.merchantId()),
    kv("error_code", e.code()),
    kv("attempt", attempt),
    kv("duration_ms", elapsed.toMillis()));

// Generate the id at the edge, return it in the response, and pass
// it downstream. One filter then reconstructs the whole request
// across every service, instead of guessing by timestamp.
headers.set("X-Request-Id", ctx.requestId());

Worked example

Marta is on call at a food delivery company when checkout errors spike at dinner rush. The checkout service logs plain text, so she spends 40 minutes building a grep chain across three message formats, and her regex silently misses the lines a teammate reworded last quarter, which sends her down a wrong path blaming the payments provider. The real culprit is one restaurant chain whose menu payload grew past a size limit. After the postmortem the team moves to structured lines. Each one is a JSON object, a plain-text format of named fields, carrying merchant_id, error_code and payload_bytes. Two months later a near-identical incident hits, and the on-call runs one Kibana query, groups errors by merchant_id, and identifies the offending merchant in under 3 minutes. Same class of bug, 40 minutes down to 3, purely because the logs became queryable.