Observability mit OpenTelemetry: Logs, Traces und Metriken

Man kann nicht reparieren, was man nicht sieht. Diesen Satz habe ich in den letzten Jahren in so vielen Post-mortems gehört, dass er fast schon abgedroschen klingt – und trotzdem stimmt er jedes Mal. Ein Request wird langsam, ein Service kippt unter Last, ein Fehler taucht nur bei jedem hundertsten Aufruf auf. Und dann stehe ich mit dem Team vor der Log-Aggregation und suche im Heuhaufen nach der einen Zeile, die erklärt, was passiert ist. Meistens ist sie nicht da. Oder sie ist da, aber ich kann sie nicht dem Request zuordnen, der das Problem ausgelöst hat.

Observability ist der Versuch, dieses Rätselraten durch Systematik zu ersetzen. Nicht durch mehr Dashboards, sondern durch die Fähigkeit, aus dem, was ein laufendes System nach außen gibt, jede Frage beantworten zu können – auch die, die ich mir vorher nicht überlegt habe. In der Praxis stützt sich das auf drei Signale: Logs, Traces und Metriken. Und der Standard, mit dem ich sie heute einheitlich erhebe, heißt OpenTelemetry.

Drei Signale, drei Blickwinkel

Bevor ich über Werkzeuge rede, lohnt sich die begriffliche Sauberkeit. Logs, Traces und Metriken sind keine drei Wege, dasselbe zu tun – sie beantworten unterschiedliche Fragen und haben unterschiedliche Kosten.

Logs sind diskrete Ereignisse mit Zeitstempel: "Bestellung 4711 abgelehnt, weil Lagerbestand null." Sie liefern das Detail, den konkreten Fall, den Debug-Kontext. Dafür sind sie teuer in der Retention und werden bei hoher Kardinalität schnell unübersichtlich.
Traces zeigen den Pfad eines einzelnen Requests durch das System: welcher Service ruft welchen, wie lange dauert jeder Hop, wo entsteht die Latenz. Ein Trace ist ein Baum von Spans, und er endet nicht an der Servicegrenze.
Metriken sind aggregierte Zahlenreihen über die Zeit: Requests pro Sekunde, Fehlerrate, Latenzverteilung. Sie sind billig zu speichern, eignen sich für Alarme und Trends – aber sie sagen mir nie, welcher Request langsam war, nur dass es welche gab.

Der Denkfehler, den ich immer wieder sehe, ist die Annahme, eines dieser Signale reiche aus. Metriken allein sagen mir, dass die Latenz gestiegen ist, aber nicht warum. Logs allein ertrinken im Volumen. Traces allein zeigen den Pfad, aber nicht den Trend über eine Woche. Erst zusammen ergeben sie ein Bild – und der eigentliche Gewinn entsteht dort, wo ich zwischen ihnen springen kann: von einer Latenzspitze in der Metrik zum konkreten Trace, von dort in die korrelierten Logs.

OpenTelemetry: einmal instrumentieren, überallhin exportieren

OpenTelemetry (kurz OTel) ist ein herstellerneutrales CNCF-Projekt, und genau diese Neutralität ist der Grund, warum ich es empfehle. Früher hieß Observability, sich an ein Backend zu binden: Das Agent-SDK des Anbieters wurde in den Code gewoben, und ein Wechsel bedeutete, die Instrumentierung neu zu schreiben. OTel trennt beides sauber. Ich instrumentiere meinen Code einmal gegen eine standardisierte API, und was hinten herauskommt, spreche ich über das OTLP-Protokoll aus. Ob die Daten dann in Jaeger, Tempo, Prometheus oder einem kommerziellen Backend landen, ist eine Konfigurationsfrage, keine Code-Änderung.

Ein Wort zum Reifegrad, denn der ist Mitte 2024 nicht überall gleich. Tracing ist in JavaScript stabil, Metrics ebenfalls. Das Logs-Signal ist in JS dagegen noch experimentell – @opentelemetry/api-logs und sdk-logs tragen den Alpha-Stempel und sind als Bridge für bestehende Logger gedacht, nicht als direkte Log-API für Anwendungscode. Praktisch heißt das: Ich schreibe meine Logs weiterhin mit dem Logger meiner Wahl und sorge selbst dafür, dass die Trace-Korrelation drinsteht. Dazu später mehr.

Das SDK aufsetzen – und zwar früh genug

Die Instrumentierung beginnt mit dem Node-SDK. Der entscheidende Punkt, den ich in Reviews am häufigsten anmahne: Das SDK muss starten, bevor irgendein anderes Modul geladen wird. OTel funktioniert über Monkey-Patching der Bibliotheken – wenn http oder graphql schon geladen sind, bevor das SDK sie patchen konnte, bekomme ich einen No-op-Tracer und wundere mich über leere Traces. Deshalb lade ich die Instrumentierung über --require, nicht als regulären Import in app.ts.

// instrumentation.ts
import { NodeSDK } from '@opentelemetry/sdk-node';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { OTLPMetricExporter } from '@opentelemetry/exporter-metrics-otlp-http';
import { PeriodicExportingMetricReader } from '@opentelemetry/sdk-metrics';
import { Resource } from '@opentelemetry/resources';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';

const sdk = new NodeSDK({
  resource: new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: 'checkout-service',
    [SemanticResourceAttributes.SERVICE_VERSION]: '1.4.0',
  }),
  traceExporter: new OTLPTraceExporter({
    url: 'http://collector:4318/v1/traces',
  }),
  metricReader: new PeriodicExportingMetricReader({
    exporter: new OTLPMetricExporter({
      url: 'http://collector:4318/v1/metrics',
    }),
  }),
  instrumentations: [
    getNodeAutoInstrumentations({
      // File-system spans are noisy; turn them off.
      '@opentelemetry/instrumentation-fs': { enabled: false },
    }),
  ],
});

sdk.start();

process.on('SIGTERM', () => {
  sdk.shutdown().finally(() => process.exit(0));
});

Gestartet wird das Ganze so, dass die Instrumentierung garantiert zuerst läuft:

node --require ./instrumentation.js ./app.js

getNodeAutoInstrumentations() deckt eine überraschende Menge ab, ohne dass ich eine Zeile Business-Code anfassen muss: HTTP und HTTPS, Express oder Fastify, GraphQL, gRPC, gängige Datenbank-Clients. Für den Anfang bekomme ich damit einen vollständigen Request-Baum durch die Standard-Schichten praktisch geschenkt. Wer sich generell fragt, wie man einem laufenden Node-Prozess auf die Finger schaut, findet in Node.js debuggen und beobachten die Grundlagen, auf denen das hier aufbaut.

Manuelle Spans für die Business-Logik

Auto-Instrumentation kennt HTTP und GraphQL, aber sie kennt nicht meine Domäne. Ob ein Checkout durch die Bonitätsprüfung fällt oder am Lagerbestand scheitert, sieht kein generischer Instrumentation-Plugin. Genau dafür setze ich manuelle Spans – dort, wo die fachlich interessanten Entscheidungen fallen.

import { trace, SpanStatusCode } from '@opentelemetry/api';

const tracer = trace.getTracer('checkout', '1.4.0');

export async function processCheckout(order: Order): Promise<Receipt> {
  return tracer.startActiveSpan('checkout.process', async (span) => {
    span.setAttribute('order.id', order.id);
    span.setAttribute('order.item_count', order.items.length);

    try {
      await reserveStock(order);
      const receipt = await charge(order);
      span.setAttribute('payment.provider', receipt.provider);
      return receipt;
    } catch (err) {
      span.recordException(err as Error);
      span.setStatus({ code: SpanStatusCode.ERROR });
      throw err;
    } finally {
      span.end();
    }
  });
}

Drei Dinge sind hier wichtig. startActiveSpan macht den Span zum aktiven Kontext, sodass alles, was innerhalb des Callbacks passiert – auch die Spans der Auto-Instrumentation für reserveStock und charge – korrekt als Kinder eingehängt wird. recordException plus setStatus markiert den Span als fehlerhaft, was ihn im Backend auffindbar macht. Und span.end() im finally sorgt dafür, dass der Span auch im Fehlerfall geschlossen wird – ein vergessenes end() ist ein Leck, das im Backend als hängender Span sichtbar wird.

Bei den Attributen halte ich mich zurück. Die Bestell-ID gehört dazu, die item-Anzahl auch. Was nicht dazugehört, ist alles, was die Kardinalität sprengt oder sensibel ist – vollständige Warenkörbe, personenbezogene Daten, freie Texte.

Der Trace hört nicht an der Servicegrenze auf

Der eigentliche Wert eines Traces zeigt sich, sobald mehrere Services beteiligt sind. Ein Request trifft das Gateway, das ruft den Checkout-Service, der spricht mit der Datenbank und nebenbei mit einem Payment-Provider. Damit das ein zusammenhängender Trace bleibt und nicht in vier unverbundene Fragmente zerfällt, muss der Trace-Context über die Grenzen wandern.

OpenTelemetry nutzt dafür standardmäßig den W3C-Trace-Context: einen traceparent-Header, der Trace-ID, Span-ID und Sampling-Entscheidung trägt. Die Auto-Instrumentation injiziert und extrahiert ihn bei HTTP-Aufrufen automatisch – der Empfänger hängt seine Spans an den Parent aus dem Header, und der Baum wächst über Prozessgrenzen hinweg weiter.

graph TD
    A[Client Request] -->|traceparent| B[API Gateway<br/>Span: http.request]
    B -->|traceparent| C[Checkout Service<br/>Span: checkout.process]
    C --> D[Span: db.query]
    C -->|traceparent| E[Payment Provider<br/>Span: payment.charge]
    B -.->|eine trace_id| F[(Ein Trace =<br/>Baum aus Spans)]
    C -.-> F
    D -.-> F
    E -.-> F

Interessant wird es dort, wo kein HTTP-Header existiert. In einer Lambda-Funktion oder bei einer Message-Queue gibt es keinen automatischen Transport für den Context. Dann muss ich ihn selbst durch die Event-Payload reichen – beim Absenden mit propagation.inject in die Nachricht schreiben, beim Empfang mit propagation.extract herausziehen und den Context aktiv setzen. Bei Serverless kommen zwei weitere Punkte dazu: Der Cold Start verlängert die Init-Phase, und vor dem Freeze der Funktion muss ich einen Force-Flush auslösen, sonst gehen die letzten Spans verloren, weil der Export sie nicht mehr rausschicken konnte.

Logs an Traces koppeln – über die trace_id

Jetzt zum Punkt, an dem Observability aus meiner Sicht steht und fällt: der Korrelation. Ein Log ohne Trace-Bezug ist eine Zeile im Nirgendwo. Ein Log mit trace_id und span_id ist ein Sprungbrett – von der Fehlermeldung direkt in den vollständigen Request-Pfad, der sie erzeugt hat.

Der aktive Span liegt im Context, und der Context wird in Node über AsyncLocalStorage getragen – das ist auch der Default-Context-Manager, den OTel intern verwendet. Ich muss also nur den aktiven SpanContext auslesen und seine IDs in jedes strukturierte Log hängen. Wie AsyncLocalStorage diesen impliziten Kontext durch asynchrone Aufrufketten trägt, habe ich in Async-Kontext mit AsyncLocalStorage im Detail beschrieben; hier ist es der Träger, der die Trace-Korrelation überhaupt erst möglich macht.

import { trace } from '@opentelemetry/api';

type Fields = Record<string, unknown>;

export function log(level: 'info' | 'warn' | 'error', msg: string, fields: Fields = {}): void {
  const span = trace.getActiveSpan();
  const ctx = span?.spanContext();

  const entry = {
    ts: new Date().toISOString(),
    level,
    msg,
    ...(ctx && { trace_id: ctx.traceId, span_id: ctx.spanId }),
    ...fields,
  };

  process.stdout.write(JSON.stringify(entry) + '\n');
}

Ein Aufruf wie log('error', 'stock reservation failed', { order_id: order.id }) mitten in der Business-Logik erzeugt jetzt eine JSON-Zeile, die dieselbe trace_id trägt wie der Span, in dem sie entstanden ist. Im Backend filtere ich später auf diese ID und habe Log und Trace nebeneinander. In der Praxis kapsle ich das nicht selbst, sondern lasse es einen etablierten Logger wie Pino über einen Mixin erledigen – das Prinzip bleibt dasselbe: den aktiven SpanContext auslesen und anhängen.

RED: Rate, Errors, Duration

Metriken sind die aggregierte Gesundheit des Systems, und ich fange nicht mit hundert Custom-Metriken an, sondern mit dreien. Die RED-Methode – Rate, Errors, Duration – deckt für jeden Service das Wesentliche ab: Wie viele Requests kommen rein, wie viele davon scheitern, wie lange dauern sie.

import { metrics } from '@opentelemetry/api';

const meter = metrics.getMeter('http-server');

const requestCounter = meter.createCounter('http.server.requests', {
  description: 'Total number of HTTP requests',
});
const errorCounter = meter.createCounter('http.server.errors', {
  description: 'Total number of failed HTTP requests',
});
const latencyHistogram = meter.createHistogram('http.server.duration', {
  description: 'HTTP request duration in milliseconds',
  unit: 'ms',
});

export function recordRequest(route: string, statusCode: number, durationMs: number): void {
  const attributes = { route, status_class: `${Math.floor(statusCode / 100)}xx` };
  requestCounter.add(1, attributes);
  if (statusCode >= 500) {
    errorCounter.add(1, attributes);
  }
  latencyHistogram.record(durationMs, attributes);
}

Diese drei Aufrufe stecken in einer Middleware und laufen für jeden Request. Der Counter für die Rate, der Counter für die Errors, das Histogram für die Duration – letzteres, weil mich bei Latenz nicht der Durchschnitt interessiert, sondern die Verteilung, das p95 und p99. Ein Durchschnitt von 80 Millisekunden versteckt, dass jeder zwanzigste Nutzer zwei Sekunden wartet.

Wichtig ist bei den Attributen die Zurückhaltung. Ich labele mit route und einer Statusklasse – Werte mit begrenztem, überschaubarem Wertebereich. Was ich nicht tue: die volle URL mit eingebetteter Bestell-ID als Label verwenden, oder die User-ID. Jede eindeutige Label-Kombination erzeugt eine eigene Zeitreihe, und unbegrenzte Werte lassen die Kardinalität explodieren, bis das Metrik-Backend in die Knie geht. Kardinalität gehört in Traces, nicht in Metriken.

Die Fallstricke, die mich Zeit gekostet haben

Ein paar Fehler sehe ich so regelmäßig, dass ich sie hier ausdrücklich nenne. Der teuerste ist das erwähnte Logging ohne Korrelation – Logs, die zwar strukturiert sind, aber keine trace_id tragen. Sie sehen ordentlich aus und nützen im Ernstfall trotzdem wenig, weil ich sie keinem Request zuordnen kann. Der zweite ist die zu späte SDK-Initialisierung, die das Monkey-Patching ins Leere laufen lässt.

Der dritte betrifft das Sampling. In Produktion jeden Trace zu erfassen ist selten sinnvoll – das Volumen und die Kosten explodieren. Also samplen. Aber naives Head-Sampling, das blind jeden hundertsten Trace behält, verwirft mit hoher Wahrscheinlichkeit gerade die Fehler-Traces, die ich sehen will. Ich setze deshalb auf ParentBased(TraceIdRatio): Die Sampling-Entscheidung fällt am Anfang, wird über den traceparent-Header propagiert und bleibt für den gesamten Trace konsistent – kein Service entscheidet für sich allein, sodass ich keine halben Traces bekomme. Der vierte Fallstrick ist die schon erwähnte Kardinalitätsfalle bei Custom-Metriken.

Fazit

Observability ist keine Frage des richtigen Dashboards, sondern der Fähigkeit, jede Frage an ein laufendes System beantworten zu können – auch die, die ich mir vorher nicht gestellt habe. Die drei Signale liefern dafür die Rohdaten: Logs für das konkrete Ereignis, Traces für den Request-Pfad, Metriken für die aggregierte Gesundheit. Ihre eigentliche Kraft entfalten sie erst in der Korrelation, wenn ich von der Metrik-Spitze zum Trace und von dort zum Log springen kann, ohne die Werkzeuge zu wechseln.

OpenTelemetry macht diesen Ansatz herstellerneutral: Ich verkable meinen Code einmal gegen eine standardisierte API und entscheide später und getrennt davon, wohin die Daten fließen. Auto-Instrumentation bringt mich schnell in die Nähe, manuelle Spans decken die Domäne ab, die Trace-Context-Propagation hält alles über Servicegrenzen zusammen, und die Kopplung von Logs an die trace_id über AsyncLocalStorage schließt den Kreis. Fangen Sie klein an – drei RED-Metriken, Auto-Instrumentation, korrelierte Logs – und bauen Sie von dort aus. Am Tag, an dem der nächste Incident kommt, werden Sie froh sein, das System sehen zu können, bevor Sie es reparieren.