Distributed Tracing with OpenTelemetry - the Empire's courier routes

The metrics say the 95th percentile of response time rose from 200 ms to two seconds. You know that it is slow - but not where. A request passes through the authentication gate, the legions service, the database and an external payments API. Which of those links takes those two seconds?

Rome had a register of stations for this. A courier carrying a dispatch from Gaul to Rome reported at every mansio, and from those reports you could later read where he had lost a day. Distributed tracing does exactly that to a request.

Trace and span

Two terms that must be separated at once.

A trace is a request's whole road - from entry to exit, across every service. A span is a single operation within a trace - one database query, one external API call, one service method.

So a span is not an identifier of the whole request (that is the trace ID), not a format for exporting data, and not a visualisation tool. It is one stretch of the road, with its own start and end time.

Spans form a tree. For a request creating a legion it looks like this, from the root downwards:

1. POST /legiones - the root span, the whole HTTP request.
2. auth.verify - token verification.
3. legion.create - the business logic.
4. mongodb.insert - the write to the database.

The nesting is information in itself: since mongodb.insert sits inside legion.create, its time counts towards the parent's. When the root span takes two seconds and mongodb.insert takes one and a half - you already know where to look.

Configuration

We start OpenTelemetry before the application, in a separate file loaded first:

1const sdk = new NodeSDK({
2  resource: new Resource({
3    [SemanticResourceAttributes.SERVICE_NAME]: 'legion-api',
4  }),
5  traceExporter: new OTLPTraceExporter({
6    url: 'http://jaeger:4318/v1/traces',
7  }),
8  instrumentations: [getNodeAutoInstrumentations()],
9});
10
11sdk.start();

resource gives the service a name - it is how you recognise your spans among those from other services. traceExporter says where to send the data; here to Jaeger, the tool that draws a timeline out of it.

instrumentations is the most interesting part. getNodeAutoInstrumentations() switches on automatic tracing of popular libraries - HTTP, Express, MongoDB, Redis. You add not a line to your services, and spans for database queries appear by themselves.

Order matters: the SDK must start before you import Express or the database driver. Automatic instrumentation works by swapping those libraries at load time, and it cannot swap something already loaded.

A custom span

Auto-instrumentation covers infrastructure but knows nothing of your domain. To see legion.create in the tree, you create a span yourself:

1@Injectable()
2export class LegionService {
3  private tracer = trace.getTracer('legion-service');
4
5  async create(dto: CreateLegionDto) {
6    return this.tracer.startActiveSpan('legion.create', async (span) => {
7      try {
8        span.setAttribute('legion.name', dto.name);
9        span.setAttribute('legion.rank', dto.rank);
10
11        const legion = await this.repo.save(dto);
12
13        span.setStatus({ code: SpanStatusCode.OK });
14        return legion;
15      } catch (error) {
16        span.recordException(error);
17        span.setStatus({ code: SpanStatusCode.ERROR });
18        throw error;
19      } finally {
20        span.end();
21      }
22    });
23  }
24}

You create the tracer once, as a class field - the written order is private tracer, =, trace.getTracer('legion-service').

Five things happen inside. startActiveSpan opens a span and makes it active, so everything created within it - including spans from auto-instrumentation - nests underneath automatically. setAttribute adds data searchable later in Jaeger; this is where you put the identifiers you will hunt a specific case by. setStatus marks the outcome, recordException records an exception along with its stack trace.

The most important part is span.end() in the finally block. A span never ended is never exported at all - the same symmetry you know from connections and test hooks: what you opened you must close, including when an exception flew.

Context propagation

That leaves the question of how spans from different services end up in one tree. That is the job of context propagation - the automatic passing of a trace ID between services through HTTP headers.

When service A calls service B, the instrumentation adds a traceparent header carrying the trace's identifier and the current span's. Service B reads it and creates its spans as children of that one. Nobody copies anything by hand, synchronises databases or moves configuration files.

Hence the whole value of tracing in a distributed system: one tree spans every service, so those two seconds can be pinned on a specific link even when it lives in somebody else's service.

Summary

The couriers report at every station:

• metrics say that it is slow, tracing says where,
• a trace is a request's whole road; a span is a single operation within a trace - not a request identifier, not an export format, not a visualisation tool,
• spans form a tree from the root down: POST /legiones → auth.verify → legion.create → mongodb.insert,
• a child's time counts towards its parent's - which is why the tree points at the guilty link immediately,
• NodeSDK is configured by three things: resource with the service name, traceExporter with the recipient's address, instrumentations,
• getNodeAutoInstrumentations() traces popular libraries with no code changes - but the SDK must start before they are imported,
• the tracer: private tracer = trace.getTracer('name'),
• startActiveSpan nests everything created inside it; setAttribute adds searchable data, setStatus and recordException describe the outcome,
• span.end() belongs in finally - a span never ended is never exported,
• context propagation automatically passes the trace ID between services through HTTP headers - it does not copy logs or synchronise databases.

In the next lesson you will gather this whole module into one deployment project. For now remember: a metric shows a chart, a trace shows a route - and only on the route can you see at which station the courier lost a day.

1// Distributed Tracing - Imperium Courier Routes
2console.log("=== DISTRIBUTED TRACING ===\n");
3
4interface Span {
5  name: string;
6  traceId: string;
7  spanId: string;
8  parentSpanId: string | null;
9  duration: number;
10  status: 'OK' | 'ERROR';
11}
12
13// Simulation of the span tree
14const traceId = 'abc-123-def-456';
15const spans: Span[] = [
16  {
17    name: 'POST /legiones',
18    traceId,
19    spanId: 'span-001',
20    parentSpanId: null,
21    duration: 250,
22    status: 'OK',
23  },
24  {
25    name: 'auth.verify',
26    traceId,
27    spanId: 'span-002',
28    parentSpanId: 'span-001',
29    duration: 15,
30    status: 'OK',
31  },
32  {
33    name: 'legion.create',
34    traceId,
35    spanId: 'span-003',
36    parentSpanId: 'span-001',
37    duration: 180,
38    status: 'OK',
39  },
40  {
41    name: 'mongodb.insert',
42    traceId,
43    spanId: 'span-004',
44    parentSpanId: 'span-003',
45    duration: 45,
46    status: 'OK',
47  },
48  {
49    name: 'redis.set',
50    traceId,
51    spanId: 'span-005',
52    parentSpanId: 'span-003',
53    duration: 5,
54    status: 'OK',
55  },
56];
57
58console.log(`Trace ID: ${traceId}\n`);
59console.log("Span tree:");
60spans.forEach(s => {
61  const indent = s.parentSpanId === null ? '' :
62    s.parentSpanId === 'span-001' ? '  ' : '    ';
63  console.log(`${indent}${s.name} [${s.duration}ms] ${s.status}`);
64});
65
66// Key concepts
67console.log("\n=== CONCEPTS ===\n");
68const concepts = {
69  Trace: 'Full request journey (client -> response)',
70  Span: 'A single operation within a trace',
71  'Trace ID': 'Unique identifier of the whole request',
72  'Context Propagation': 'Passing traceId between services',
73};
74
75Object.entries(concepts).forEach(([k, v]) => {
76  console.log(`  ${k}: ${v}`);
77});
78
79console.log("\nBackends: Jaeger, Zipkin, Grafana Tempo");
80