Distributed Tracing (OpenTelemetry)

The problem: one click, five processes, where did the time go?

A user clicks "transfer." That single action becomes: SPA → gateway → transfer-service (HTTP) → RabbitMQ → account-service (debit) → RabbitMQ → transfer-service → RabbitMQ → account-service (credit) → … . When it's slow or fails, "check the logs" means grepping five services and reconstructing the order by hand. Logs tell you what happened in one process; they don't show you one request's path across all of them.

The pattern

Distributed tracing gives every operation a span (name, start, duration, attributes) and threads them onto one trace by propagating a trace context (W3C traceparent: trace-id + parent span-id) across every hop. OpenTelemetry (OTel) is the vendor-neutral standard for producing that data: SDKs auto-instrument HTTP/DB/broker clients, and an OTLP exporter ships spans to a collector, which forwards them to a trace store (Tempo) that Grafana visualises as a flame graph.

  service (OTel SDK) ──OTLP──► otel-collector ──► Tempo (traces)
                                      │
                                      └──► Prometheus exporter (metrics)
  promtail ──► Loki (logs)  ◄── pivot by correlationId / traceId ──► Grafana

Where it lives in our code

• .NET services (gateway, account-service): Program.cs → AddOpenTelemetry().WithTracing(...), gated on Otel:Endpoint. AspNetCore + HttpClient + EFCore instrumentation, plus account-service adds .AddSource("MassTransit") (MassTransit ships its own ActivitySource). OTLP/gRPC to the collector on :4317.
• transfer-service (Node): transfer-service/src/tracing.ts — a NodeSDK started before any other import (the bare import './tracing' is the first line of main.ts) so auto-instrumentation can patch http/express/mongodb/amqplib as they load. OTLP/HTTP to the collector on :4318. Gated on OTEL_EXPORTER_OTLP_ENDPOINT.
• Collector: observability/otel-collector-config.yaml — OTLP in (gRPC + HTTP), traces → Tempo, metrics → Prometheus exporter.
• Trace store + UI: observability/tempo.yaml, Grafana datasource observability/grafana/provisioning/datasources/datasources.yaml (Tempo↔Loki correlation wired).

The honest finding: the async hop breaks the live trace

This is the most interesting — and most truthful — part. Synchronous hops stitch perfectly: a GET /api/transfers/:id is one trace spanning gateway → transfer-service → MongoDB, because traceparent flows over HTTP automatically. Verified in Tempo: one trace, all the spans.

The async saga hop does not stitch into one trace. We verified empirically (search Tempo for account-service + messaging.system=rabbitmq): every consumed message is the root of its own new trace (account.transfer-requested receive, etc.), not a child of the originating POST. The POST /api/transfers trace ends at ~60ms when the 202 returns — long before the saga runs.

Why: the transactional outbox. The event isn't published during the request; it's written to a Mongo outbox row and published later by a timer (OutboxPublisher, every 500ms). By publish time the originating span's context is gone — there's no live Activity/span to propagate. On the consume side, MassTransit starts a fresh trace from its own conventions rather than the raw traceparent we inject into the AMQP header. So the trace is severed exactly at the durability boundary that makes the saga reliable.

What we do about it (rather than fake a single trace):

1. OutboxService.enqueue captures the active span's traceId/spanId into the envelope metadata (the slot already existed). OutboxPublisher re-injects a traceparent AMQP header from those ids — so a consumer that did read it could link back, and the ids are durably recorded either way.
2. The correlationId is the real cross-service pivot. One correlationId is born at the gateway and rides every HTTP call, every event, and every log line of the saga. We verified one correlationId selects logs from gateway + transfer-service + account-service in Loki. From any span you pivot to Loki by correlationId and see the whole saga's logs in order, across the outbox gap that the trace can't cross.

This is a genuine, well-known limitation of tracing across store-and-forward async boundaries — and naming it honestly is worth more than a demo that pretends the gap isn't there.

Trace context propagation, summarised

Hop	Carrier	Stitches into one trace?
SPA → gateway → service	HTTP traceparent	✅ yes
service → DB	client instrumentation	✅ yes (child spans)
service → RabbitMQ → service	outbox timer breaks live context	❌ separate traces; pivot by correlationId

Interview Q&A

Q: Trace vs. span vs. trace context? A span is one timed operation. A trace is the tree of spans for one logical request. Trace context (traceparent) is the trace-id + parent span-id propagated across process boundaries so a callee's spans attach to the caller's trace. No propagation → no tree, just disconnected spans.

Q: Why does the trace break at RabbitMQ but not at HTTP? HTTP is synchronous: the live span is on the stack when the client call is made, so traceparent is injected from a real context. The outbox publishes on a timer, detached from the request — there's no active span to propagate. The durability mechanism (write-then-publish-later) is exactly what severs the in-band context. You either accept separate traces linked by a business key, or use span links to reference the originating span id you stored.

Q: So how do you debug a slow saga across that gap? Pivot on correlationId. It's on every log line in Loki and on the stored metadata.traceId. You lose the single flame graph but keep a complete, ordered, cross-service narrative — which for an async saga is usually what you actually need.

Q: Why a collector instead of services exporting straight to Tempo? Decoupling. Services speak one protocol (OTLP) to one endpoint and stay ignorant of the backend. The collector handles batching, retries, fan-out (traces→Tempo, metrics→Prometheus), and lets you swap backends without touching app code. It's also where you'd add sampling/redaction centrally.

Q: Tracing every request is expensive — sampling? In production, tail-based sampling at the collector (keep all errors and slow traces, sample the boring fast ones) gives you the interesting traces without storing everything. This demo samples 100% because volume is tiny; the collector is the natural place to add a sampling policy.

Q: MassTransit ships its own spans — how do they show up? .AddSource("MassTransit") registers its ActivitySource with our tracer, so its publish/consume spans export through the same OTLP pipeline. They form correct per-message traces; they just don't (here) chain back across the outbox to the initiating HTTP trace.

Try to break it

1. Sync trace stitches: GET /api/transfers/:id through the gateway, find the trace in Grafana → Tempo. One trace: gateway → transfer-service → mongodb.
2. Async trace breaks (the point): POST a transfer, then search Tempo for { resource.service.name = "account-service" }. The debit/credit consume spans are roots of separate traces, not children of your POST. That's the outbox gap, observed.
3. correlationId saves the day: copy the transfer's correlationId, query Loki {correlationId="..."} → log lines from gateway, transfer-service, and account-service, in order. The pivot the trace can't give you.
4. Prove the bootstrap order matters: move import './tracing' below the Nest imports in main.ts, rebuild — auto-instrumentation patches too late and HTTP/Mongo spans vanish. Put it back first.