Distributed Tracing z OpenTelemetry - szlaki kurierskie Imperium

Metryki mówią, że dziewięćdziesiąty piąty percentyl czasu odpowiedzi wzrósł z 200 ms do dwóch sekund. Wiesz że jest wolno - ale nie gdzie. Żądanie przechodzi przez bramę uwierzytelniającą, serwis legionów, bazę i jeszcze zewnętrzne API płatności. Które z tych ogniw zabiera te dwie sekundy?

Rzym miał na to spis stacji. Kurier wiozący depeszę z Galii do Rzymu meldował się w każdej mansio, a na końcu z tych meldunków dało się odczytać, gdzie stracił dzień. Distributed tracing robi dokładnie to samo z żądaniem.

Trace i span

Dwa pojęcia, które trzeba rozdzielić od razu.

Trace to cała droga jednego żądania - od wejścia do wyjścia, przez wszystkie usługi. Span to pojedyncza operacja w ramach trace - jedno zapytanie do bazy, jedno wywołanie zewnętrznego API, jedna metoda serwisu.

Span nie jest więc identyfikatorem całego żądania (tym jest trace ID), nie jest formatem eksportu danych ani narzędziem do wizualizacji. To jeden odcinek drogi, z własnym czasem rozpoczęcia i zakończenia.

Spany układają się w drzewo. Dla żądania tworzącego legion wygląda ono tak, od korzenia w głąb:

1. POST /legiones - root span, całe żądanie HTTP.
2. auth.verify - weryfikacja tokena.
3. legion.create - logika biznesowa.
4. mongodb.insert - zapis do bazy.

Zagnieżdżenie jest tu informacją samą w sobie: skoro mongodb.insert leży wewnątrz legion.create, to jego czas wlicza się w czas rodzica. Gdy root span trwa dwie sekundy, a mongodb.insert półtorej - wiesz już, gdzie szukać.

Konfiguracja

OpenTelemetry uruchamiamy przed aplikacją, w osobnym pliku ładowanym najwcześniej:

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 nadaje nazwę usłudze - to po niej rozpoznasz swoje spany wśród spanów z pozostałych serwisów. traceExporter wskazuje, dokąd wysyłać dane; tutaj do Jaegera, narzędzia, które rysuje z nich oś czasu.

instrumentations to najciekawszy element. getNodeAutoInstrumentations() włącza automatyczne śledzenie popularnych bibliotek - HTTP, Express, MongoDB, Redis. Nie dopisujesz ani linii w kodzie serwisów, a spany dla zapytań do bazy powstają same.

Kolejność ma znaczenie: SDK musi wystartować, zanim zaimportujesz Express czy sterownik bazy. Automatyczna instrumentacja działa przez podmianę tych bibliotek w locie, a nie podmieni czegoś, co już zostało załadowane.

Własny span

Auto-instrumentacja pokrywa infrastrukturę, ale nie wie nic o Twojej dziedzinie. Żeby zobaczyć w drzewie legion.create, tworzysz span sam:

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}

Tracer tworzysz raz, jako pole klasy - kolejność zapisu to private tracer, =, trace.getTracer('legion-service').

W środku dzieje się pięć rzeczy. startActiveSpan otwiera span i czyni go aktywnym, dzięki czemu wszystko, co powstanie w środku - także spany z auto-instrumentacji - zagnieździ się pod nim automatycznie. setAttribute dokłada dane wyszukiwalne później w Jaegerze; to tutaj wpisujesz identyfikatory, po których będziesz szukać konkretnego przypadku. setStatus oznacza wynik, recordException zapisuje wyjątek wraz ze śladem stosu.

Najważniejsze jest span.end() w bloku finally. Span bez zakończenia nie trafi do eksportu wcale - i to jest ta sama symetria, którą znasz z połączeń i haków testowych: co otworzyłeś, musisz zamknąć, także wtedy gdy poleciał wyjątek.

Przekazywanie kontekstu

Zostało pytanie, jak spany z różnych usług trafiają do jednego drzewa. Odpowiada za to context propagation - automatyczne przekazywanie trace ID między serwisami przez nagłówki HTTP.

Gdy serwis A woła serwis B, instrumentacja dokłada do żądania nagłówek traceparent z identyfikatorem trace'u i bieżącego spanu. Serwis B odczytuje go i tworzy swoje spany jako dzieci tamtego. Nikt niczego nie kopiuje ręcznie, nie synchronizuje baz ani nie przenosi plików konfiguracyjnych.

Stąd bierze się cała wartość tracingu w systemie rozproszonym: jedno drzewo obejmuje wszystkie usługi, więc dwie sekundy da się przypisać konkretnemu ogniwu, nawet gdy leży ono w cudzym serwisie.

Podsumowanie

Kurierzy meldują się na każdej stacji:

• metryki mówią że jest wolno, tracing mówi gdzie,
• trace to cała droga żądania; span to pojedyncza operacja w ramach trace - nie identyfikator żądania, nie format eksportu, nie narzędzie do wizualizacji,
• spany tworzą drzewo od korzenia w głąb: POST /legiones → auth.verify → legion.create → mongodb.insert,
• czas dziecka wlicza się w czas rodzica - dlatego drzewo od razu wskazuje winne ogniwo,
• NodeSDK konfigurują trzy rzeczy: resource z nazwą usługi, traceExporter z adresem odbiorcy, instrumentations,
• getNodeAutoInstrumentations() śledzi popularne biblioteki bez zmian w kodzie - ale SDK musi wystartować przed ich zaimportowaniem,
• tracer: private tracer = trace.getTracer('nazwa'),
• startActiveSpan zagnieżdża wszystko, co powstanie w środku; setAttribute dokłada dane do wyszukiwania, setStatus i recordException opisują wynik,
• span.end() należy do finally - span bez zakończenia nie trafi do eksportu,
• context propagation automatycznie przekazuje trace ID między serwisami przez nagłówki HTTP - nie kopiuje logów ani nie synchronizuje baz.

W następnej lekcji zbierzesz cały ten moduł w jeden projekt wdrożeniowy. A na razie zapamiętaj: metryka pokazuje wykres, trace pokazuje trasę - i dopiero na niej widać, przy której stacji kurier stracił dzień.

1// Distributed Tracing - Szlaki Kurierskie Imperium
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// Symulacja drzewa spanow
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("Drzewo spanow:");
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// Kluczowe pojecia
67console.log("\n=== POJECIA ===\n");
68const concepts = {
69  Trace: 'Pelna podroz zadania (klient -> odpowiedz)',
70  Span: 'Pojedyncza operacja w ramach trace',
71  'Trace ID': 'Unikalny identyfikator calego zadania',
72  'Context Propagation': 'Przekazywanie traceId miedzy serwisami',
73};
74
75Object.entries(concepts).forEach(([k, v]) => {
76  console.log(`  ${k}: ${v}`);
77});
78
79console.log("\nBackendy: Jaeger, Zipkin, Grafana Tempo");
80