Distributed Tracing & Correlation IDs

The claim under test

"We have correlation IDs, so we have tracing." It is said in design reviews constantly, usually by someone who has done real work to make it true: the filter exists, the header is honoured, the log pattern includes the ID. The claim is worth taking seriously precisely because the thing behind it is not a fake. It is a real capability. It is simply a different capability from the one the word "tracing" names.

Here is what the real capability looks like. One identifier, eleven log files, one grep:

$ grep -h "$CID" services/*.log | sort
api-gateway    12:04:31.108  INFO  [4f1c9a2e]  POST /orders
order-svc      12:04:31.121  INFO  [4f1c9a2e]  creating order
pricing-svc    12:04:31.147  INFO  [4f1c9a2e]  quote requested
pricing-svc    12:04:31.178  INFO  [4f1c9a2e]  quote returned
inventory-svc  12:04:31.195  INFO  [4f1c9a2e]  reserving stock
inventory-svc  12:04:31.601  INFO  [4f1c9a2e]  stock reserved
order-svc      12:04:31.607  INFO  [4f1c9a2e]  order accepted
api-gateway    12:04:31.608  INFO  [4f1c9a2e]  201 Created

Look at the two highlighted lines. They appear to show a 406 ms gap inside the inventory service, and an engineer will reach that conclusion in about four seconds. It happens to be right here, and the reasoning that produced it is not sound. Those two stamps share a host, so subtracting them is legitimate. The moment you subtract across services you are comparing two independent wall clocks, and NTP-disciplined clocks in a datacentre still routinely disagree by single-digit to low-double-digit milliseconds. On a request where the interesting difference is 20 ms rather than 400 ms, that skew is the whole answer.

There is a second, quieter problem. Nothing in that output says who called whom. Did the gateway call pricing, or did the order service? Was the inventory call issued inside the pricing call or after it? The lines are ordered by timestamp, which is a presentation choice, not a causal fact. Correlated logs are a flat set. Causality is a graph, and the graph is not in there to be recovered.

What a correlation ID genuinely gives you

It is worth being fair about this, because the pattern is undervalued by people who have just discovered tracing. A correlation ID solves a real and previously miserable problem: before it, a production incident meant opening eleven log files and eyeballing timestamps for lines that looked related. After it, one identifier collects them exactly.

The right way to hold this: a correlation ID is a join key. It makes a previously unjoinable dataset joinable. What it does not do is add the columns that the interesting queries need: duration, parent and kind. Adding those columns is what tracing is.

Ubiquitous deployment is the one that matters for this page. Dapper's authors understood from the start that a tracing system with a gap in it is not a slightly worse tracing system. The trace simply stops at the gap. That is the same failure mode that makes context propagation, further down, the part that actually breaks.

What a trace adds

A trace is not a better log line. It is a different data structure: a directed acyclic graph of spans, each of which is a timed unit of work that knows its own parent. OpenTelemetry's definition is the one the whole ecosystem now shares.

The documentation lists what each span carries: Name, Parent span ID (empty for root spans), Start and End Timestamps, Span Context, Attributes, Span Events, Span Links, Span Status. Four of those entries are the whole difference from a log line. Parent span ID gives you causality. Start and end timestamps , measured locally on one clock by the process doing the work, give you a duration that is trustworthy without any cross-host clock agreement at all. Attributes give you the dimensions to slice by. Span context is the part that travels.

Span events deserve a note, because they are the field most often skipped and they are the one that replaces scattered log.debug calls. An event is a timestamped annotation attached inside a span, so "cache miss, 340 ms into this 400 ms call" has a position on the timeline rather than merely a wall-clock stamp in a file. That is the difference between knowing a cache miss happened during the request and being able to see it land in the gap that the waterfall is asking you about. Span links serve the related purpose of joining a span to causes in other traces: a batch job processing forty messages links to forty producers, which a strict parent-child tree cannot express.

Put those together across four services and you get a picture that correlated logs cannot produce at any level of logging discipline:

Notice what the picture answers instantly and the log dump could not. The pricing call and the inventory call ran in sequence, not in parallel, visible from the bars, invisible in the log. The 382 ms is not "in the inventory service", it is in one query the inventory service issued; the service itself added 24 ms of its own. And the whole judgement rests on durations each process measured against its own monotonic clock, so no amount of NTP drift between hosts changes the conclusion.

Span kind

One span field deserves its own paragraph because it is the one most often left at its default. Span kind tells the backend what shape of relationship the span represents, which is how a UI knows to draw a queue hop differently from a function call. OpenTelemetry's definitions:

The CONSUMER definition contains the sentence that breaks naive tooling: a consumer span "may start long after the producer span has already ended". A trace is therefore not guaranteed to be a contiguous interval on a timeline. Systems that assume it is will silently drop your async work, which is one more reason the kind field is worth setting explicitly rather than leaving to a default.

The traceparent header, dissected

Every one of those spans needs to know its parent, and the parent usually lives in another process. The wire format for that hand-off is standardised. W3C Trace Context is a Recommendation, which is why an OpenTelemetry-instrumented Java service, a Go sidecar and a third-party API you do not control can all participate in one trace without agreeing on anything else.

Serialised, those four fields are hyphen-separated in the order version-trace-id-parent-id-trace-flags. This is the specification's own worked example, reproduced with its field decomposition:

Value = 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
base16(version)     = 00
base16(trace-id)    = 4bf92f3577b34da6a3ce929d0e0e4736
base16(parent-id)   = 00f067aa0ba902b7
base16(trace-flags) = 01  // sampled

Two consequences follow directly from the table, and both are worth saying out loud. First, trace-id is genuinely the same idea as a correlation ID, so a service that already has a correlation filter has built one quarter of the header, in a private format nobody else parses. Second, parent-id is not a variation on the same idea; it is a structurally different piece of information that changes at every hop and that no flat identifier can encode. That is the whole thesis of this page compressed into one row of a table.

Context propagation: where it actually breaks

This is the practical core of the page. Instrumenting a service to create spans is a dependency and a line of configuration. Getting the context to survive every hop is where real systems fail, and they fail silently: a broken hop does not error, it just produces two unrelated traces where there should have been one.

The same page notes that "The default propagator uses the headers specified by the W3C TraceContext specification", so on the easy path you configure nothing. The hard paths are the three below, in ascending order of how often they are missed.

1 · Outbound HTTP clients

An incoming request populates the context; an outgoing request has to carry it forward. With Spring Boot and Micrometer Tracing on the classpath, an auto-configured RestTemplate or WebClient gets this for free. The failure cases are specific and predictable: a client built with new RestTemplate() instead of the injected builder bypasses the instrumentation entirely; a declarative client such as Feign needs its own interceptor; and a raw HttpClient gets nothing at all. One un-instrumented client anywhere in the estate truncates every trace that passes through it.

2 · Thread pools and @Async

Both SLF4J's MDC and OpenTelemetry's Context are held in thread-locals. The instant work is handed to a pool, it runs on a thread that has neither. This is the failure that most often gets diagnosed as "logging is flaky", because the effect is that the ID is present at the start of a request and absent halfway through. Every scheduled task, every @Async method, every CompletableFuture.supplyAsync with an executor, every parallel stream is an instance of it.

The fix is to decorate the task rather than to remember at every call site: capture on the submitting thread, install on the worker, and clear afterwards so a pooled thread never leaks one request's identity into the next:

/**
 * @Async, and every other pooled hand-off, starts on a thread whose MDC
 * and ThreadLocal context are empty. Nothing warns you: the log lines
 * simply stop carrying the id halfway through the request.
 */
@Configuration
public class AsyncContextConfig {

    @Bean
    public ThreadPoolTaskExecutor applicationTaskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setTaskDecorator(runnable -> {
            // Captured on the SUBMITTING thread…
            Map<String, String> submitter = MDC.getCopyOfContextMap();
            return () -> {
                // …and installed on the worker for this task only.
                if (submitter != null) MDC.setContextMap(submitter);
                try {
                    runnable.run();
                } finally {
                    MDC.clear();
                }
            };
        });
        executor.initialize();
        return executor;
    }
}

The OpenTelemetry side has a direct equivalent: Context.taskWrapping(Executor) returns an executor that propagates the active context across the hand-off. Use both, because they carry different things, and fixing one does not fix the other.

3 · Message buses

This is the boundary where the problem stops being a missing interceptor and becomes a contract change. A Redis pub/sub channel, a plain queue, a websocket frame, none of them have a header section you can slip traceparent into. The context has to travel inside the payload, which means the message envelope must have a slot for it, which means both publisher and consumer have to agree on that slot. You cannot add this unilaterally on one side.

Sampling: head, tail, and why 100% is not the goal

A trace is one to two orders of magnitude more data than a log line, because it is emitted per operation rather than per interesting event. At any real volume, retaining everything is a storage and egress bill nobody signed up for. Sampling is how the field made tracing affordable, and it is one of the design choices Dapper singled out: "the use of sampling and restricting the instrumentation to a rather small number of common libraries".

There are two families, and the difference between them is when the decision is taken relative to knowing how the request turned out.

In general numeric terms: at a few hundred requests per second, head-based sampling in the 1–10% range keeps the bill sane and gives you a statistically fine picture of normal latency, and it is exactly the wrong tool for the incident you will actually be paged for, because a failure mode occurring in 1 in 10,000 requests is, at 1% sampling, retained 1 time in a million. Tail-based sampling inverts that: keep 100% of traces containing an error, 100% above a latency threshold, and a small percentage of everything else. You pay for it by emitting every span to a collector that must hold a whole trace in memory long enough to decide.

What this looked like in production

Doing it properly

Four tabs, in the order you would actually implement them. The first is the correlation filter, worth keeping even after you have traces, because a human-readable ID that a support agent can quote is a different affordance from a 32-character trace id. The last is where real spans come from.

/**
 * Step one, and a genuinely correct one: every log line emitted while this
 * request is on the stack carries the same identifier, with no call site
 * having to pass it around.
 */
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class CorrelationIdFilter extends OncePerRequestFilter {

    public static final String HEADER = "X-Correlation-ID";
    public static final String MDC_KEY = "correlationId";

    @Override
    protected void doFilterInternal(HttpServletRequest request,
                                    HttpServletResponse response,
                                    FilterChain chain) throws ServletException, IOException {
        String correlationId = request.getHeader(HEADER);
        if (correlationId == null || correlationId.isBlank()) {
            correlationId = UUID.randomUUID().toString();
        }
        MDC.put(MDC_KEY, correlationId);
        response.setHeader(HEADER, correlationId);
        try {
            chain.doFilter(request, response);
        } finally {
            // Servlet threads are pooled and reused. Without this removal the
            // id leaks into the next, unrelated request on the same thread.
            MDC.remove(MDC_KEY);
        }
    }
}

/**
 * Hop two. The id survives only if the caller copies it onto the next
 * request; nothing in a plain Spring application does this for you.
 */
@Configuration
public class OutboundPropagationConfig {

    /** Blocking clients: one interceptor on the shared RestTemplate bean. */
    @Bean
    public RestTemplate restTemplate(RestTemplateBuilder builder) {
        return builder.additionalInterceptors((request, body, execution) -> {
            String correlationId = MDC.get(CorrelationIdFilter.MDC_KEY);
            if (correlationId != null && !correlationId.isBlank()) {
                request.getHeaders().add(CorrelationIdFilter.HEADER, correlationId);
            }
            return execution.execute(request, body);
        }).build();
    }

    /**
     * Declarative clients need their own interceptor: a RestTemplate bean
     * does not cover Feign, and a single un-instrumented client silently
     * truncates the chain for every service downstream of it.
     */
    @Bean
    public RequestInterceptor feignCorrelationInterceptor() {
        return template -> {
            String correlationId = MDC.get(CorrelationIdFilter.MDC_KEY);
            if (correlationId != null && !correlationId.isBlank()) {
                template.header(CorrelationIdFilter.HEADER, correlationId);
            }
        };
    }
}

/**
 * A bus has no request headers, so the context must travel inside the
 * message itself. The envelope is now part of the contract.
 */
public record EventEnvelope(String type, String payload, Map<String, String> context) {}

@Component
@RequiredArgsConstructor
public class EventPublisher {

    private final StringRedisTemplate redis;
    private final ObjectMapper mapper;

    /** Producer side: serialise the active context into the envelope. */
    public void publish(String channel, String type, String payload) throws IOException {
        Map<String, String> carrier = new HashMap<>();
        W3CTraceContextPropagator.getInstance()
                .inject(Context.current(), carrier, (map, key, value) -> map.put(key, value));

        // Belt and braces: the flat id travels too, so plain log greps keep
        // working for anyone not yet reading the trace backend.
        carrier.put(CorrelationIdFilter.MDC_KEY, MDC.get(CorrelationIdFilter.MDC_KEY));

        redis.convertAndSend(channel,
                mapper.writeValueAsString(new EventEnvelope(type, payload, carrier)));
    }
}

/**
 * Consumer side. Rebuild the parent context, then start a CONSUMER span
 * whose parent lives in a different process. That edge is exactly the
 * causality a correlation id cannot express.
 */
@Component
@RequiredArgsConstructor
public class OrderEventListener implements MessageListener {

    private static final TextMapGetter<Map<String, String>> GETTER =
            new TextMapGetter<>() {
                @Override
                public Iterable<String> keys(Map<String, String> carrier) {
                    return carrier.keySet();
                }
                @Override
                public String get(Map<String, String> carrier, String key) {
                    return carrier == null ? null : carrier.get(key);
                }
            };

    private final ObjectMapper mapper;
    private final Tracer tracer;

    @Override
    public void onMessage(Message message, byte[] pattern) {
        EventEnvelope envelope = read(message);

        Context parent = W3CTraceContextPropagator.getInstance()
                .extract(Context.current(), envelope.context(), GETTER);
        MDC.put(CorrelationIdFilter.MDC_KEY,
                envelope.context().get(CorrelationIdFilter.MDC_KEY));

        Span span = tracer.spanBuilder(envelope.type())
                .setParent(parent)
                .setSpanKind(SpanKind.CONSUMER)
                .startSpan();
        try (Scope ignored = span.makeCurrent()) {
            handle(envelope);
        } catch (RuntimeException e) {
            span.recordException(e);
            span.setStatus(StatusCode.ERROR);
            throw e;
        } finally {
            span.end();
            // Listener threads are pooled as well. Leak the key here and the
            // next message is logged under the previous message's id.
            MDC.remove(CorrelationIdFilter.MDC_KEY);
        }
    }
}

/**
 * With Micrometer Tracing on the classpath, Spring Boot already opens a
 * SERVER span per request and injects W3C headers on its own outbound
 * clients. What is left is naming the work that matters inside a service.
 */
@Service
@RequiredArgsConstructor
public class ReservationService {

    private final Tracer tracer;                 // io.micrometer.tracing.Tracer
    private final ReservationRepository repository;

    /**
     * Declarative. One annotation, one span, but it is inert unless an
     * ObservedAspect bean exists, which is the commonest reason @Observed
     * appears to do nothing at all.
     */
    @Observed(name = "inventory.reserve", contextualName = "reserve-stock")
    public Reservation reserve(String sku, int quantity) {
        return repository.reserve(sku, quantity);
    }

    /** Manual, when you need attributes the annotation cannot express. */
    public Reservation reserveManually(String sku, int quantity) {
        Span span = tracer.nextSpan().name("inventory.reserve");
        try (Tracer.SpanInScope scope = tracer.withSpan(span.start())) {
            span.tag("inventory.sku", sku);
            span.tag("inventory.quantity", String.valueOf(quantity));
            return repository.reserve(sku, quantity);
        } catch (RuntimeException e) {
            span.error(e);
            throw e;
        } finally {
            span.end();
        }
    }
}

@Configuration
class ObservationConfig {

    @Bean
    ObservedAspect observedAspect(ObservationRegistry registry) {
        return new ObservedAspect(registry);
    }
}

management:
  tracing:
    enabled: true
    sampling:
      # Head-based: decided once at the root and carried in trace-flags, so a
      # trace is never half-recorded. 10% of requests, each one whole.
      probability: 0.10
    propagation:
      type: w3c
  otlp:
    tracing:
      endpoint: http://otel-collector:4318/v1/traces

# Put the trace and span ids into every log line. This is what closes the
# loop: a slow span in the UI leads straight back to its own log lines.
logging:
  pattern:
    level: "%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]"

The adoption checklist

The ticked items are the properties a system needs before "we have tracing" is a true statement. The unticked ones are the states that get mistaken for it.

• Every service emits and accepts traceparent, not only a private header.
• Every outbound client is instrumented, including hand-constructed ones and declarative clients such as Feign.
• Every pooled hand-off restores context: a TaskDecorator on the executor, not a reminder in a code review.
• Message envelopes carry trace context as part of the schema, and the consumer starts a CONSUMER span parented to it.
• traceId and spanId appear in the log pattern, so a span links back to its lines and back again.
• A sampling policy was chosen deliberately: head-based percentage, or tail-based with an always-sample-errors rule.
• An integration test asserts propagation at each boundary type, because nothing else will tell you when it breaks.
• Correlated logs and no backend: you can find the request, not the latency.
• Spans exist but the async boundary is unhandled: you have two traces per workflow and no way to know it.
• Sampling left at 100% "for now": the retention bill will make the decision for you, badly and later.

Canonical sources

• W3C: Trace Context · the traceparent format, field sizes and the worked example quoted above.
• OpenTelemetry: Traces · what a span carries, and the five span kinds.
• OpenTelemetry: Context propagation · context, propagators, and W3C TraceContext as the default.
• OpenTelemetry: Sampling · head vs tail, with each one's stated downside.
• Google: Dapper (2010) · the origin of the field: low overhead, application-level transparency, ubiquitous deployment.