Correlation IDs: Turning Lines Into a Story
Without a shared identifier, logs from five services are five unrelated piles sorted by time. With one id propagated through every hop — and stored in a dedicated field — they become one request's story, and the log line becomes a doorway into the trace.
Frame the diagnosis
Performance work starts from a symptom and a signal — never from a resource dashboard.
One id, every hop
The mechanism is simple: generate an id at the edge if the client did not supply one, attach it to every log line in that request's handling, pass it on every outbound call, and have each downstream service do the same. The result is that request_id=a91f3c selects exactly the lines belonging to that request, across every service, in one query.
It has to survive process boundaries, which is where implementations usually fall short. HTTP hops are easy — a header. Queue hops are the ones that get missed: a job enqueued during a request and executed twenty seconds later by a worker will lose the correlation unless the id was written into the message envelope, so the asynchronous half of the work becomes unattributable exactly when you are investigating a slow or failed background operation (see Carrying the Trace Across the Gap).
Two ids are worth carrying, not one. The trace id identifies the distributed trace and is what lets you jump from a log line to the waterfall (see Where the Request Actually Went). The request id is the user-facing handle — the value returned in an error response so a support ticket can name it, which API Design treats as a contract clause in Request IDs: The Contract's Correlation Clause. They are often the same value; when they are not, log both.
Why timestamp correlation is not a substitute
The tempting shortcut is to filter each service's logs to the same second and read across. At ten requests per second this feels like it works. At ten thousand it selects ten thousand candidate lines per service, and picking the right one is guesswork — worse, guesswork that produces a confident, wrong narrative.
Clock skew makes it worse. Services on different hosts disagree by milliseconds to seconds, so "the same instant" is not the same instant, and the ordering you infer across services can be simply backwards. Retries multiply the confusion further, since three attempts of the same logical operation are three separate lines with nearly identical content at nearly identical times.
With an id, none of this matters. The id is exact, ordering comes from the trace's parent-child structure rather than from wall-clock comparison, and retries are distinguishable by attempt number within the same correlated set.
1# "The customer says 14:03. Let us look at each service around then."2 3checkout-api 14:03:11.4xx 68,000 lines that minute4payment-svc 14:03:11.5xx 41,000 lines that minute5orders-db 14:03:11.6xx 120,000 lines that minute6 7# Which payment line belongs to WHICH checkout?8# - clock skew between hosts: ordering may be inverted9# - three retries look like three near-identical lines10# - you will find *a* consistent story; it may be someone else's1request_id="a91f3c"2 314:03:11.402 checkout-api event=request_started route=/checkout414:03:11.418 checkout-api event=payment_attempt attempt=1514:03:15.601 payment-svc event=provider_timeout duration_ms=4183614:03:15.610 checkout-api event=payment_attempt attempt=2714:03:19.788 payment-svc event=provider_timeout duration_ms=4178814:03:19.795 checkout-api event=payment_failed outcome=failure914:03:19.801 checkout-api event=job_enqueued job=send_failure_email1014:03:41.117 receipt-worker event=job_started # 20s later, still correlated11 12# 8 lines, exact, ordered, both retries visible.Timestamp correlation produces a story that is internally consistent and possibly about a different request. The id makes the selection exact and keeps the asynchronous tail attached.
From a log line to the trace, and back
The highest-value property of a trace_id field is the pivot. You find one interesting error line in the logs, and one click takes you to the full trace — every span, every duration, the critical path. Conversely, you find a slow span in a trace and jump to the log lines emitted inside it, which carry the detail a span attribute would be too expensive to hold.
This is what makes logs and traces complementary rather than redundant (see Metrics, Logs, Traces, Profiles). Traces are excellent at "where did the time go" and deliberately sampled, so most requests have no trace at all. Logs are excellent at "what exactly happened and why" and usually retained more completely. Correlation ids are the join key that lets each cover the other's gap.
Returning the request id to the client matters too. An error response carrying request_id: a91f3c lets a user paste one string into a support ticket that resolves an investigation in seconds instead of an hour of narrowing by timestamp and account. The cost is one field in the error body — see The Error Model: Structure Over Apology on the API side.
FROM A LOG LINE FROM A TRACE
level error span payment.charge
event payment_failed dur 4183ms <- slow
error_code provider_timeout trace 4bf92f3577b34da6
trace_id 4bf92f3577b34da6 ------+ span a1f9c33e2b
request_id a91f3c | |
| v
+-----------------------+ query logs where
v trace_id="4bf92f..."
open the trace: 11 spans, AND span_id="a1f9c33e2b"
critical path = payment.charge |
-> 4183ms of a 4.4s request v
event=provider_timeout
provider=acme_pay
attempt=1
upstream_status=504
neither signal alone answers "where did the time go AND why".Key points
- Generate a correlation id at the edge, propagate it on every hop, and store it in a dedicated field on every log line.
- Queue and background-job hops are where propagation is usually lost — the id must travel in the message envelope.
- Timestamp correlation appears to work at low traffic and silently produces wrong narratives at high traffic, especially with clock skew and retries.
- Carrying
trace_idalongsiderequest_idturns every log line into a doorway to the trace, and every span into a doorway to the logs. - Returning the request id in error responses turns a support ticket into a one-query investigation.
Follow the diagnosis
The causal chain, hop by hop — and the readings that invite the wrong conclusion.
- 1Edge → request: the gateway generates
a91f3cand passes it downstream in a header. - 2Service → queue: a job is enqueued, but the enqueue call does not copy the id into the message envelope.
- 3Queue → worker: the worker starts 20 seconds later with no inbound header and generates a fresh id — or none.
- 4Worker → logs: the asynchronous half of the request is logged under a different id and cannot be joined to the original.
- 5Investigator → conclusion: the synchronous path looks complete and healthy, and the failure in the background job appears to belong to no request at all.
- • "We have request ids" — verify continuity across queue and worker boundaries; the synchronous path is usually fine and the asynchronous one usually is not.
- • "The timestamps line up, so this is the same request" — at high traffic that is coincidence, and clock skew can invert the apparent ordering.
- • "The trace covers it" — traces are sampled; most requests have no trace, which is exactly why logs need their own correlation id.
- • "One id is enough" — when trace id and request id differ, logging only one breaks either the trace pivot or the support workflow.
Measure, fix, validate
An optimization is not finished until the metric that motivated it has moved.
- • Sample log lines and compute the fraction carrying a non-empty correlation id, broken down by service — the gaps are your propagation holes.
- • Trace one synthetic request end to end and confirm the id survives every hop, including queue and worker boundaries.
- • Check that error responses include the request id by inspecting a real failure payload.
- • Verify a log line can be pivoted to its trace, and a span back to its logs, in one step each.
- • Propagate the id in shared middleware for inbound and outbound calls so services cannot forget it.
- • Write the id into queue message envelopes and restore it at the start of job execution.
- • Log both `trace_id` and `request_id` as dedicated fields, never embedded in the message text.
- • Return the request id in error responses and surface it in the UI so users can quote it (see [[error-model]]).
- • Confirm the correlation-id coverage fraction is near 100% in every service, including workers.
- • Walk a synthetic request that crosses a queue and verify one query returns every line from both halves.
- • Check the pivot works in both directions on a real recent error.
- • Propagation must be threaded through every transport, and each new one is a place to forget it.
- • Two extra fields on every log line is real storage cost at high volume (see [[log-cost-and-sampling]]).
- • Client-supplied request ids are convenient and untrusted input — they must be validated in length and character set before being logged or echoed.
- • Alert when correlation-id coverage drops below a threshold in any service — a new code path without propagation shows up immediately.
- • Add a contract test asserting that outbound calls and enqueued messages carry the id.
- • Include propagation in the checklist for adding any new transport (a new queue, a new protocol, a new third-party client).
Accuracy
Performance numbers are conditional. These are the conditions.
- ILLUSTRATIVEThe ids, timings and per-minute line counts are invented. Real trace ids follow the W3C trace-context format; the shape shown is abbreviated for readability.
- ENVIRONMENT-SPECIFICHeader names and propagation formats depend on the tracing stack. W3C
traceparentis the interoperable default; older stacks use vendor-specific headers that do not interoperate.