Trace One Request Across Services with a Correlation ID

Propagate a single x-request-id through gateway, service, and job tiers, then stitch per-service logs into one timeline to find the slow hop.

~25 minapiobservabilitylogging

Task

Inject a correlation ID at the edge, verify it propagates through every hop, and assemble a unified timeline from distributed logs.

When to use this

A checkout request takes nine seconds but every service dashboard shows sub-second latency, so nobody knows which hop swallowed the time.

Prerequisites

curl with header support
Access to aggregated logs via jq and grep, or a log console
A test route that calls at least two downstream services

Steps

1. Generate a unique ID and call the entry point with it as a header.

REQ_ID="req-$(date +%s)-$RANDOM"; curl -s -o /dev/null -D - "https://staging.example.com/api/checkout" -H "x-request-id: $REQ_ID" | head -3; echo "$REQ_ID" > /tmp/req-id

Expected output: The gateway responds and echoes the request ID in its own response headers, proving the edge accepted the identifier.

2. Search every service log tier for that ID and capture timestamps.

for svc in gateway orders payments inventory; do echo "== $svc =="; grep "$REQ_ID" /var/log/$svc/app.log | jq -r '"\(.ts) \(.level) \(.msg)\(if .upstream then " -> \(.upstream)" else "" end)'" | head -5; done

Expected output: Each tier prints at least one line carrying the same ID, with timestamps forming an increasing sequence.

3. Compute per-hop durations from the first and last timestamp per service.

grep "$REQ_ID" /var/log/*/app.log | jq -sr 'sort_by(.ts) | . as $l | $l | group_by(.service) | map({svc: .[0].service, first: (map(.ts)|min), last: (map(.ts)|max)}) | .[] | "\(.svc) \(.first) → \(.last)"'

Expected output: A per-service span table appears; one hop shows a multi-second gap between first and last event, naming the culprit.

4. Confirm the ID survives hops where middleware may drop unknown headers.

// proxy or fetch client: forward the header explicitly
const headers = { 'content-type': 'application/json' };
if (incoming['x-request-id']) headers['x-request-id'] = incoming['x-request-id'];
await fetch(downstream, { headers });

Expected output: Downstream logs now contain the same ID without manual injection, so propagation works through code, not luck.

Troubleshooting

Problem

Only the gateway logs the ID

Solution

An intermediate proxy strips unknown headers by default; add x-request-id to its allowed-headers list and restart it.

Problem

Timestamps look out of order across services

Solution

Clocks drift between hosts; compare date -u on each node and either fix NTP or record per-hop durations instead of absolute times.

Problem

Log lines exist but jq fails to parse

Solution

Some tiers emit plain text logs around the JSON lines; grep for the ID first, then pipe only matching lines through jq.

Limitations

Correlation IDs show sequence, not causation; pair them with spans when you need exact parent-child relationships.
Sampling logs by ID only works if the ID is logged at every tier, which middleware upgrades can silently break.

One ID to grep them all

Distributed latency problems hide between services. A single request ID, injected at the edge and propagated by every hop, turns a vague nine-second mystery into a grep command. The technique needs no tracing platform: logs, timestamps, and one unique string are enough to name the slow hop.

REQ_ID="req-$(date +%s)-$RANDOM"
curl -s "https://staging.example.com/api/checkout" \
  -H "x-request-id: $REQ_ID"

grep "$REQ_ID" /var/log/*/app.log \
  | jq -sr 'sort_by(.ts)
    | group_by(.service)
    | map({svc: .[0].service,
           spanMs: ((map(.ts)|max|tonumber) - (map(.ts)|min|tonumber))})
    | sort_by(-.spanMs)
    | .[] | "\(.svc): \(.spanMs) ms"'

Propagate in code, not in hope

A header that only the gateway writes is a dead end. Every outbound call must copy the incoming x-request-id explicitly, because HTTP clients never forward unknown headers automatically. Wrap the copy in one shared helper so upgrades cannot forget it.

Read the timeline before blaming a service

Sort all events by timestamp before computing per-hop durations. The service with the largest gap between its first and last event is the slow hop; the service with the largest gap before its first event is waiting on someone else. Those are different problems with different owners.