Correlation IDs & Structured Logging

The problem: one user action, five processes

"Why did transfer X fail?" touches: an HTTP request in transfer-service, an outbox publish, a RabbitMQ hop, a consumer in account-service, an event back, a state change. Each process logs independently — without a shared key, reconstructing the story means matching timestamps by eye across services. That stops working at the second service and never works under load.

The pattern

Mint a correlationId at the edge (first HTTP request), then propagate it unchanged through every hop — HTTP headers, event envelopes, AMQP properties — and stamp it on every log line. One grep then yields the entire distributed story, in order.

Two ids, two jobs:

• correlationId — business flow identity: one transfer saga = one id, across all services. Coarse, human-friendly, lives in the envelope.
• messageId — message identity: unique per message, the dedupe key. (idempotent-consumer.md)

OpenTelemetry's traceId/spanId now add timing and parent-child structure on top (see distributed-tracing-otel.md): the gateway starts a trace and it flows over HTTP automatically. But the outbox breaks the live trace at the RabbitMQ hop — the publish happens on a timer with no active span — so the async saga ends up as separate per-message traces. That's exactly why correlationId still matters: it's the one id that survives the store-and-forward gap, born at the gateway and carried on every event and log line. We stash traceId/spanId in metadata (the slots were always there) for best-effort linking, but correlationId is the durable cross-service pivot — one id selects gateway + transfer-service + account-service logs in Loki for a whole saga.

How it flows through our code

POST /transfers (X-Correlation-Id or minted)            correlation.middleware.ts
  └─ stored in AsyncLocalStorage for the request        correlation.storage.ts
      └─ TransfersService reads it → transfer doc + envelope.correlationId
          └─ OutboxPublisher mirrors it into the AMQP correlationId property
              └─ MassTransit consumer: envelope.CorrelationId → structured log props
                  └─ every published account event reuses the SAME id
                      └─ AccountEventsHandler wraps handling in ALS.run({correlationId})
                          └─ pino mixin stamps it on every log line automatically

Key implementation ideas:

• AsyncLocalStorage (correlation.storage.ts) is Node's context that survives await — the modern replacement for cls-hooked from the original plan. Nobody passes the id through 7 function signatures; the logger pulls it from ambient context (app.module.ts pino mixin).
• On .NET, CorrelationIdMiddleware pushes it into Serilog's LogContext; consumers log it as a structured property from the envelope.
• Structured JSON logs on both sides (Serilog RenderedCompactJsonFormatter / pino): logs are queryable data ({"correlationId": "...", "service": "account-service", ...}), not prose. This is what makes Loki ingestion work with zero app changes — promtail lifts correlationId straight out of the JSON into a label. (Heads-up the two stacks spell it differently: pino emits correlationId, Serilog emits CorrelationId; promtail coalesces both — see observability/promtail-config.yaml.)

Trade-offs

• ALS has a small per-context cost and can lose context across exotic callback libraries — measure before blaming it, but know the failure mode.
• Logging the id on every line costs bytes; logging it on some lines costs debugging sessions. Pay the bytes.
• The id is only as good as its propagation discipline: one service that mints a fresh id mid-flow breaks the chain. Contract tests + code review are the defence.

Interview Q&A

Q: Correlation id vs trace id — why both? TraceId (OTel) is infrastructure-grade: per-request, with spans, timing, sampling — and sampled away under load. CorrelationId is business-grade: per saga, never sampled, stable across the async boundary where many tracing setups stumble (a queue hop breaks naive HTTP-header propagation). Mature systems carry both; the envelope has slots for both.

Q: How does the id survive an async hop through RabbitMQ? It's in the message — envelope field plus AMQP correlationId property. The consumer re-establishes ambient context from the message (ALS.run / LogContext.Push) before handling. The rule: context never survives a process boundary implicitly; you re-hydrate it from the payload.

Q: Why structured logging instead of formatted strings? grep scales to one machine; queries scale to a fleet. {"level":"error","correlationId":X} can be indexed, aggregated, alerted on. A formatted string can only be read. Also: structured properties make the SAME log statement cheap to correlate (CorrelationId is a field, not word #7 of a sentence).

Q: A user reports a stuck transfer. Walk me through it. GET /transfers/:id → read correlationId and stateHistory (which step did it stop at?). docker compose logs | grep <correlationId> → both services' view, interleaved. If the last event published got no reaction, check the consumer's queue depth and the parking lot. Total: minutes, no guesswork — that's what the pattern buys.

Try to break it

1. Run a transfer with your own id: curl -H 'X-Correlation-Id: deadbeef-0000-4000-8000-000000000001' -X POST http://localhost:3001/transfers ..., then docker compose logs | grep deadbeef — the full two-service saga, one grep.
2. Run two transfers concurrently and grep each id — interleaved in real time, perfectly separated in the logs. That's ALS doing its job under concurrency.
3. Comment out the mixin in app.module.ts, restart, and try to debug exercise 2 again. (Put it back.)