Structured logging

A log is the only record of what a service actually did, written by the service itself, at the moment it did it. When something goes wrong in production, logs are usually the first thing opened and often the last thing that explains it — provided they were written to be searched, carry enough context to connect one line to the next, and cost little enough that nobody turned them off.

This lesson is about those three properties: levels that mean something, structure that a query can use, and a correlation id that survives every hop.

#SLF4J and a backend

Java services log through SLF4J, a facade, with a backend underneath that does the writing — Logback by default in Spring Boot, or Log4j2. Code depends only on the facade:

private static final Logger log = LoggerFactory.getLogger(OrderService.class);
 
log.info("payment failed for order {}", orderId);

The {} placeholder matters. The message is assembled only if the level is enabled, and the argument's toString is never called otherwise. That is worth a measurement, because the difference is not small. One million DEBUG calls, with DEBUG switched off as it is in production, each one describing a 20-field order:

round 0, 1,000,000 disabled debug calls: concatenated 558 ms   lazy supplier 5 ms
round 1, 1,000,000 disabled debug calls: concatenated 349 ms   lazy supplier 0 ms

That run used java.util.logging — the JVM this lesson's examples ran on has no SLF4J or Logback installed, so the SLF4J, MDC and Logback snippets here are reference code, not output. The JDK logger has the same choice: a string built with + is built before the logger checks the level, so a disabled DEBUG line still costs a few hundred nanoseconds of string building and garbage. The lazy form costs effectively nothing once the JIT has seen it. A hot loop with a concatenated DEBUG line pays that on every iteration, for output nobody will see.

#Levels that mean something

A level is a promise about what the reader should do with the line. If it is not used consistently, nobody can filter by it, and alerting on ERROR becomes noise.

Two rules that keep that table honest:

• An expected outcome is not an error. A declined card, a validation failure, a 404 for a missing resource are normal traffic. Logging them at ERROR fills the error dashboard with things nobody should fix.
• Log an exception once, where it is handled. Catching, logging and rethrowing at every layer produces the same stack trace five times, and makes one failure look like five.

#Why a grep is not enough

Text logs are written for eyes. Here is a small one:

2026-09-13T10:00:01Z INFO  OrderService - payment failed for order 1041 (card declined)
2026-09-13T10:00:02Z INFO  OrderService - payment failed for order 10412 (card declined)
2026-09-13T10:00:03Z WARN  OrderService - retrying order 1041, attempt 2
2026-09-13T10:00:04Z INFO  OrderService - order 21041 shipped

Find everything about order 1041:

$ grep "order 1041" app.log
2026-09-13T10:00:01Z INFO  OrderService - payment failed for order 1041 (card declined)
2026-09-13T10:00:02Z INFO  OrderService - payment failed for order 10412 (card declined)
2026-09-13T10:00:03Z WARN  OrderService - retrying order 1041, attempt 2

Order 10412 is in the result, because "order 1041" is a prefix of "order 10412". A plain grep 1041 finds all four lines. Every text search has this shape of problem — the same value phrased differently in different messages, substrings of other values, numbers inside timestamps — and it gets worse with every developer who writes a message a slightly different way.

The same events as structured logs, one JSON object per line:

{"ts":"2026-09-13T10:00:01Z","level":"INFO","logger":"OrderService","msg":"payment failed","orderId":1041,"reason":"card_declined","correlationId":"req-7f3a"}
{"ts":"2026-09-13T10:00:02Z","level":"INFO","logger":"OrderService","msg":"payment failed","orderId":10412,"reason":"card_declined","correlationId":"req-91bc"}
{"ts":"2026-09-13T10:00:03Z","level":"WARN","logger":"OrderService","msg":"retrying payment","orderId":1041,"attempt":2,"correlationId":"req-7f3a"}
{"ts":"2026-09-13T10:00:04Z","level":"INFO","logger":"OrderService","msg":"order shipped","orderId":21041,"correlationId":"req-02de"}

$ jq -c 'select(.orderId == 1041) | {ts, level, msg}' app.json
{"ts":"2026-09-13T10:00:01Z","level":"INFO","msg":"payment failed"}
{"ts":"2026-09-13T10:00:03Z","level":"WARN","msg":"retrying payment"}

Exactly the two lines, because orderId is a field with a value, not a sequence of characters in a sentence. And a question that a text log cannot answer at all becomes a one-liner:

$ jq -r 'select(.msg == "payment failed") | .reason' app.json | sort | uniq -c
   2 card_declined

On a real platform — Elasticsearch and Kibana, Loki, a cloud logging service — the same fields become filters, aggregations and dashboards. The sample files here were written by hand to show the difference; the commands ran against them as shown.

In Spring Boot 3.4 and later, structured output is a property — logging.structured.format.console=ecs (or logstash). Before that, the usual route is the Logstash Logback encoder in logback-spring.xml. SLF4J 2 adds a fluent API for fields on a single line:

log.atInfo()
   .addKeyValue("orderId", orderId)
   .addKeyValue("reason", "card_declined")
   .log("payment failed");

#Correlation ids and MDC

A single checkout produces lines from a controller, a service, a repository, an HTTP client and maybe three other services. Searching for the order id finds some of them. What connects all of them is a correlation id: generated once when the request enters the system, attached to every log line the request causes, and passed on to every service it calls.

Attaching it to every line by hand does not work; someone forgets. SLF4J's MDC (Mapped Diagnostic Context) does it for you: put a value in the MDC at the start of a request, and the logging backend adds it to every line written on that thread until it is removed.

// in a servlet filter, once per request
String id = Optional.ofNullable(request.getHeader("X-Request-Id")).orElse(UUID.randomUUID().toString());
MDC.put("correlationId", id);
try {
    chain.doFilter(request, response);
} finally {
    MDC.remove("correlationId");   // threads are pooled: a leftover id would label the next request
}

In a Spring Boot 3 service with Micrometer Tracing, traceId and spanId are placed in the MDC for you, and serve the same purpose — the distributed tracing lesson connects the two.

#The thread hop that loses it

The MDC is stored per thread. That is what makes it automatic, and it is also its trap. A small version of the mechanism — a ThreadLocal, which is what MDC uses underneath — with a request that hands work to a thread pool:

[main] correlationId=req-7f3a order received
[pool-1] correlationId=null charging card
[pool-1] correlationId=req-7f3a charging card

The second line ran on a pool thread, which has its own, empty context: the correlation id is gone, and that line can no longer be connected to its request. Every @Async method, CompletableFuture.supplyAsync, executor submission and reactive operator that switches threads does this unless something carries the context across.

The third line is the fix: capture the context when the task is submitted, restore it on the worker thread, and clear it afterwards:

static Runnable withContext(Runnable task) {
    String captured = correlationId.get();
    return () -> {
        String previous = correlationId.get();
        correlationId.set(captured);
        try { task.run(); } finally { if (previous == null) correlationId.remove(); else correlationId.set(previous); }
    };
}

In a Spring application that is a TaskDecorator on the executor, using MDC.getCopyOfContextMap() and MDC.setContextMap(); with Micrometer, the context-propagation library does the same for tracing context and MDC together.