Structured loggingmedium3-5 years

A correlation id set at the start of a request via `MDC.put("correlationId", id)` shows up correctly on most log lines, but occasionally a log line from a completely different request carries it. What's the mechanism, and why does it only ever seem to happen under load?

MDC is implemented as a thin wrapper over ThreadLocal, and a ThreadLocal's storage belongs to the thread, not to the request that happened to be running on it. A servlet container or executor's thread pool reuses OS threads across many requests because creating a thread is expensive — so if a request's filter sets MDC.put("correlationId", id) and never calls MDC.remove(...) in a finally block, the entry stays in that thread's ThreadLocalMap after the request finishes. The next request that happens to be handed the same pooled thread inherits whatever is still sitting there, silently, with no exception and no warning — it just logs under the wrong correlation id. It only shows up under load because that's when thread reuse actually happens fast enough, and across enough concurrent requests, for a leftover value to collide with a different request often enough to notice.

The lesson behind it →
More on Structured logging