Distributed Logging: MDC, Correlation IDs and Trace IDs

The goal from chapter 15: search for one ID and get every log line, from every service, for one request. Three tools get there: MDC, a correlation ID, and the trace ID.

MDC

MDC (Mapped Diagnostic Context) is a per-thread key-value map. Whatever you put in it is attached to every log event created on that thread afterwards:

MDC.put("payment_id", "P123");

The logging framework reads it:

• Pattern encoders show MDC only when asked. %X prints the whole map (key1=value1, key2=value2); %X{payment_id} prints one value.
• LogstashEncoder (chapter 18) adds every MDC entry as a JSON field by default (includeMdc is true).

<appender name="CONSOLE_WITH_MDC" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d %level %logger - %msg - %X{payment_id}%n</pattern>
    </encoder>
</appender>

<appender name="CONSOLE_WITH_ALL_MDC" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d %level %logger - %msg - %X%n</pattern>
    </encoder>
</appender>

<appender name="CONSOLE_WITH_JSON" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LogstashEncoder">
        <includeMdc>true</includeMdc>       <!-- the default -->
    </encoder>
</appender>

@GetMapping("/payments")
public String getPayments() {
    MDC.put("payment_id", "P123");
    MDC.put("user_id", "U1234");
    log.info("payment is successful");
    MDC.clear();
    return "successfully fetched all payments";
}

The same event, three ways:

... INFO c.e.PaymentController - payment is successful - P123
... INFO c.e.PaymentController - payment is successful - user_id=U1234, payment_id=P123
{"@timestamp":"...","message":"payment is successful",...,"user_id":"U1234","payment_id":"P123"}

Always clean up: log pollution

Why MDC.clear()? MDC belongs to the thread, and server threads come from a pool: after a request finishes, its thread serves the next one. If the first request leaves values in the MDC, the next request on that thread inherits them.

Remove the clear() from the endpoint above, call it, then call another endpoint that sets nothing:

payment is successful           - user_id=U1234, payment_id=P123
next request on some thread     - user_id=U1234, payment_id=P123     <- not this request's data!

The second request's log line now claims to belong to user U1234 and payment P123. This is log pollution, and it sends investigations down the wrong path. Clean up in a finally block, so it happens even when an exception is thrown:

MDC.put("payment_id", paymentId);
try {
    ...
} finally {
    MDC.remove("payment_id");     // or MDC.clear() if you own the whole map
}

MDC and new threads

Because MDC is per thread, a new thread starts with an empty MDC: the parent's values do not follow. An @Async method (from the Spring Boot book) runs on another thread:

@RestController
public class PaymentController {

    @Autowired
    PaymentService paymentService;

    @GetMapping("/payments/async")
    public String getPaymentsAsync() {
        MDC.put("payment_id", "P123");
        log.info("before async");
        paymentService.processPayment();          // runs on another thread
        MDC.remove("payment_id");
        return "successfully fetched all payments";
    }
}

@Component
public class PaymentService {

    Logger log = LoggerFactory.getLogger(PaymentService.class);

    @Async
    public void processPayment() {
        log.info("Async-Payment processed successfully");
    }
}

[http-nio-8081-exec-1] before async                          - traceId=39ad..., payment_id=P123
[task-1]               Async-Payment processed successfully  -                    <- empty

The async line has no MDC at all, not even the trace ID: it cannot be linked to its request.

Copying MDC with a TaskDecorator

A TaskDecorator (a Spring feature, unrelated to the logging framework) wraps every task submitted to an executor. It runs decorate on the submitting thread, so it can read that thread's MDC there and restore it on the worker thread:

@Component
public class MdcTaskDecorator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable runnable) {
        // on the parent (submitting) thread: copy its MDC
        Map<String, String> contextMap = MDC.getCopyOfContextMap();

        // the wrapper runs on the child thread
        return () -> {
            if (contextMap != null) {
                MDC.setContextMap(contextMap);
            }
            try {
                runnable.run();           // the real task
            } finally {
                MDC.clear();              // the pool thread is reused
            }
        };
    }
}

Registered as a bean, it is applied automatically to Spring Boot's default task executor (the one @Async uses). For your own ThreadPoolTaskExecutor, call executor.setTaskDecorator(...). Now:

[task-1] Async-Payment processed successfully - traceId=39ad..., spanId=3524..., payment_id=P123

Correlation IDs

How do you find all the logs of one request? Give each request a unique ID and attach it to every log event it produces. That is a correlation ID, and MDC is the natural place for it.

A servlet filter (filters are covered in the Spring Boot book) is the right place: it runs once per request, before any controller code:

@Component
public class CorrelationIdFilter extends OncePerRequestFilter {

    public static final String CORRELATION_ID = "correlationId";
    public static final String CORRELATION_HEADER = "X-Correlation-Id";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
                                    FilterChain filterChain) throws ServletException, IOException {

        String correlationId = request.getHeader(CORRELATION_HEADER);
        if (correlationId == null || correlationId.isBlank()) {
            correlationId = UUID.randomUUID().toString();   // none from the caller: create one
        }

        try {
            MDC.put(CORRELATION_ID, correlationId);
            response.setHeader(CORRELATION_HEADER, correlationId);   // return it to the caller
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove(CORRELATION_ID);
        }
    }
}

• A caller may send its own X-Correlation-Id; otherwise one is generated.
• Every log line of the request carries correlationId=... (with %X or JSON).
• The response header lets a client, or a support ticket, quote the ID.

For this to work across services, every call to another service must forward the header, and every service needs the filter. That is a lot of plumbing, and tracing already does it.

Trace ID or correlation ID?

	Trace ID (tracing)	Correlation ID (logging)
Identifies	one request, across services	one request's log lines
Shows	which service called which, timings, statuses	the detailed log events
Does not show	log details	the call path between services

Both are unique per request, so they can be the same value, and in practice they usually are.

With tracing enabled (chapter 15), the trace ID is already in the MDC. Micrometer Tracing puts traceId and spanId into the MDC while a span is active. And because the traceparent header is propagated to downstream services, every service logs the same trace ID with no extra code:

order-service      [http-nio-8081-exec-1] order side, calling inventory - traceId=e4de146d..., spanId=f6e5c45c...
inventory-service  [http-nio-8082-exec-1] inventory side                - traceId=e4de146d..., spanId=08a7621f...

Search the log platform for traceId = e4de146d... and you get every line from both services, in order. That is distributed logging.

The setup is chapter 15's, in every service:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>
<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-tracing-bridge-otel</artifactId>
</dependency>
<dependency>
    <groupId>io.opentelemetry</groupId>
    <artifactId>opentelemetry-exporter-otlp</artifactId>
</dependency>

spring.application.name=order-service
management.tracing.sampling.probability=1.0
management.otlp.tracing.endpoint=http://localhost:4318/v1/traces

plus a log pattern with %X (or %X{traceId}), or JSON logs, which include it automatically.

Keeping a correlation ID filter anyway

A filter is still useful, as a thin layer on top of the trace ID:

• to return the ID to the caller in a response header;
• to have an ID even when tracing is disabled or the request is not sampled.

So reuse the trace ID when there is one, and generate a UUID only when there is not:

@Component
public class CorrelationIdFilter extends OncePerRequestFilter {

    public static final String CORRELATION_ID = "correlationId";
    public static final String CORRELATION_HEADER = "X-Correlation-Id";

    @Autowired
    private Tracer tracer;

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
                                    FilterChain filterChain) throws ServletException, IOException {

        Span span = tracer.currentSpan();                  // null when tracing is off
        String uniqueId = (span != null) ? span.context().traceId()
                                         : UUID.randomUUID().toString();
        try {
            MDC.put(CORRELATION_ID, uniqueId);
            response.setHeader(CORRELATION_HEADER, uniqueId);
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove(CORRELATION_ID);   // remove only our key: tracing manages traceId/spanId
        }
    }
}

Two details:

• Check the span for null, not just the trace ID: with tracing off, tracer.currentSpan() itself is null, and currentSpan().context() would throw.
• Use MDC.remove(key) rather than MDC.clear() here, so the filter does not wipe traceId and spanId, which tracing manages.

The tracing filter runs before ordinary filters, so a span already exists when this one runs. The response now carries X-Correlation-Id: 3d884d0b..., the same value as the trace ID in every log line and in Jaeger.

Next: One more problem appears once a service runs as several instances: a scheduled job that should run once runs on every instance. Chapter 20 starts the module on distributed schedulers.

Check yourself

1. What is MDC?
2. How do you show MDC values with a pattern encoder, and with LogstashEncoder?
3. What is log pollution, and how do you prevent it?
4. Why does an @Async method log without the request's MDC?
5. How does a TaskDecorator carry MDC into another thread, and where does each part run?
6. How is a TaskDecorator bean applied to @Async?
7. What is a correlation ID, and why is a filter a good place to set it?
8. What do a trace ID and a correlation ID each give you?
9. How does the trace ID get into every service's logs without custom code?
10. Why keep a correlation ID filter when tracing is on?
11. Why check tracer.currentSpan() for null, and why use MDC.remove instead of MDC.clear in that filter?

Answers

1. A per-thread key-value map whose entries are attached to every log event created on that thread.
2. %X (all entries) or %X{key} (one value) in the pattern; LogstashEncoder adds all entries as JSON fields by default.
3. Server threads are reused; MDC left from one request appears in the next request's logs. Remove the entries in a finally block.
4. It runs on a different thread, and each thread has its own, initially empty, MDC.
5. decorate runs on the submitting thread and copies its MDC; the returned wrapper runs on the worker thread, sets the copied MDC, runs the task, and clears the MDC afterwards.
6. Spring Boot applies a TaskDecorator bean to its auto-configured task executor, which @Async uses.
7. A unique ID per request attached to every log line (via MDC). A filter runs once per request before any controller code, and can read an incoming header and set a response header.
8. The trace ID gives the call path and timings across services; the correlation ID lets you find a request's detailed log lines.
9. Micrometer Tracing puts traceId and spanId into the MDC while a span is active, and the traceparent header carries the trace to downstream services, which do the same.
10. To return the ID to callers in a response header, and to have an ID when tracing is disabled or the request is not sampled.
11. With tracing off, currentSpan() is null and calling context() on it throws. MDC.clear() would also remove traceId and spanId, which tracing manages.