Distributed Systems debuggen: Korrelation und Kausalität
Debugge verteilte Systeme mit Correlation IDs, Tracing-Kontextpropagierung, Log-Aggregation und kausaler Ordnung bis zur eigentlichen Ursache.
Ein Monolith zu debuggen ist schwierig. Ein verteiltes System zu debuggen ist exponentiell schwieriger, weil der Fehler im Service A entstehen, sich im Service B zeigen und erst im Service C sichtbar werden kann. Ohne eine Möglichkeit, Kausalität über Service-Grenzen hinweg nachzuvollziehen, bleibt dir nur, Timestamps mit grep zu durchsuchen und zu hoffen, dass die Uhren synchronisiert sind.
Correlation IDs, verteiltes Tracing und strukturierte Log-Aggregation verwandeln dieses Raten in eine systematische Untersuchung. Sie geben dir die Fähigkeit, einen einzelnen Request durch Dutzende von Services zu verfolgen und genau zu lokalisieren, wo etwas schiefgelaufen ist.
Correlation-ID-Propagation
Jeder Request, der in dein System eingeht, erhält eine eindeutige Correlation ID. Diese ID wird durch jeden Service-Aufruf, jede Message-Queue-Publikation und jeden Log-Eintrag weitergegeben und erzeugt einen Faden, den du ziehen kannst, um den gesamten Request-Lebenszyklus zu entwirren.
// ❌ Logs without correlation — impossible to connect
// [auth-service] User login successful
// [order-service] Order created for user 42
// [payment-service] Payment failed
// Which login led to which order? Which order's payment failed?// ✅ Correlation ID middleware that propagates across services
import { randomUUID } from "crypto";
import { Request, Response, NextFunction } from "express";
const CORRELATION_HEADER = "x-correlation-id";
const CAUSATION_HEADER = "x-causation-id";
interface RequestContext {
correlationId: string;
causationId: string;
parentSpanId?: string;
serviceName: string;
}
function correlationMiddleware(
serviceName: string
) {
return (
req: Request,
res: Response,
next: NextFunction
) => {
// Inherit correlation ID from upstream or create new one
const correlationId =
req.headers[CORRELATION_HEADER] as string ??
randomUUID();
// Causation ID tracks the immediate parent
const causationId =
req.headers[CAUSATION_HEADER] as string ??
correlationId;
const context: RequestContext = {
correlationId,
causationId,
parentSpanId: req.headers["x-parent-span"] as string,
serviceName,
};
// Attach to request for downstream use
(req as any).context = context;
// Include in response headers for debugging
res.setHeader(CORRELATION_HEADER, correlationId);
next();
};
}
// HTTP client that propagates context
class CorrelatedHttpClient {
constructor(private context: RequestContext) {}
async get(url: string): Promise<Response> {
const spanId = randomUUID();
return fetch(url, {
headers: {
[CORRELATION_HEADER]: this.context.correlationId,
[CAUSATION_HEADER]: spanId,
"x-parent-span": this.context.parentSpanId ?? "",
},
});
}
async post(
url: string,
body: unknown
): Promise<Response> {
const spanId = randomUUID();
return fetch(url, {
method: "POST",
headers: {
"Content-Type": "application/json",
[CORRELATION_HEADER]: this.context.correlationId,
[CAUSATION_HEADER]: spanId,
"x-parent-span": this.context.parentSpanId ?? "",
},
body: JSON.stringify(body),
});
}
}Der Unterschied zwischen Correlation und Causation IDs ist wichtig. Die Correlation ID bleibt über die gesamte Request-Kette gleich. Die Causation ID ändert sich bei jedem Hop und erzeugt eine Kette: Request A verursachte Aufruf B, der Aufruf C verursachte. Damit lässt sich der exakte Call-Graph rekonstruieren.
Strukturiertes Logging für Aggregation
Unstrukturierte Logs sind bei Skalierung Rauschen. Strukturierte Logs mit konsistenten Feldern ermöglichen Abfragen über Millionen von Einträgen aus Dutzenden von Services.
interface StructuredLog {
timestamp: string;
level: "debug" | "info" | "warn" | "error";
service: string;
correlationId: string;
causationId: string;
spanId: string;
message: string;
duration?: number;
error?: {
name: string;
message: string;
stack?: string;
};
metadata: Record<string, unknown>;
}
class CorrelatedLogger {
constructor(
private serviceName: string,
private context: RequestContext
) {}
info(message: string, metadata: Record<string, unknown> = {}): void {
this.emit("info", message, metadata);
}
error(
message: string,
error: Error,
metadata: Record<string, unknown> = {}
): void {
this.emit("error", message, {
...metadata,
error: {
name: error.name,
message: error.message,
stack: error.stack,
},
});
}
private emit(
level: StructuredLog["level"],
message: string,
metadata: Record<string, unknown>
): void {
const log: StructuredLog = {
timestamp: new Date().toISOString(),
level,
service: this.serviceName,
correlationId: this.context.correlationId,
causationId: this.context.causationId,
spanId: this.context.parentSpanId ?? "",
message,
metadata,
};
// Single-line JSON for log aggregation systems
console.log(JSON.stringify(log));
}
}
// Usage in a request handler
function handleOrder(req: Request, res: Response) {
const logger = new CorrelatedLogger(
"order-service",
(req as any).context
);
logger.info("Processing order", {
orderId: req.body.orderId,
itemCount: req.body.items.length,
});
// Later, if something fails:
// logger.error("Payment processing failed", paymentError, {
// orderId: req.body.orderId,
// paymentProvider: "stripe",
// });
}Mit dieser Struktur kannst du dein Log-Aggregationssystem mit correlationId = "abc-123" abfragen und jeden Log-Eintrag aus jedem Service für diesen spezifischen Request sehen, sortiert nach Timestamp.
Zusammenbau verteilter Traces
Einzelne Spans aus jedem Service müssen zu einer vollständigen Trace zusammengesetzt werden, die den gesamten Request-Zeitstrahl zeigt.
interface Span {
traceId: string;
spanId: string;
parentSpanId: string | null;
serviceName: string;
operationName: string;
startTime: number;
duration: number;
status: "ok" | "error";
tags: Record<string, string>;
logs: SpanLog[];
}
interface SpanLog {
timestamp: number;
message: string;
fields: Record<string, unknown>;
}
class TraceAssembler {
private spans: Map<string, Span[]> = new Map();
addSpan(span: Span): void {
const existing = this.spans.get(span.traceId) ?? [];
existing.push(span);
this.spans.set(span.traceId, existing);
}
assembleTrace(traceId: string): {
rootSpan: Span | null;
tree: SpanNode[];
totalDuration: number;
criticalPath: Span[];
errors: Span[];
} | null {
const spans = this.spans.get(traceId);
if (!spans || spans.length === 0) return null;
const rootSpan =
spans.find((s) => s.parentSpanId === null) ?? null;
const tree = this.buildTree(spans);
const criticalPath = this.findCriticalPath(spans);
const errors = spans.filter((s) => s.status === "error");
const totalDuration = rootSpan?.duration ?? Math.max(
...spans.map((s) => s.startTime + s.duration)
) - Math.min(...spans.map((s) => s.startTime));
return { rootSpan, tree, totalDuration, criticalPath, errors };
}
private buildTree(spans: Span[]): SpanNode[] {
const nodeMap = new Map<string, SpanNode>();
const roots: SpanNode[] = [];
for (const span of spans) {
nodeMap.set(span.spanId, { span, children: [] });
}
for (const span of spans) {
const node = nodeMap.get(span.spanId)!;
if (span.parentSpanId) {
const parent = nodeMap.get(span.parentSpanId);
if (parent) {
parent.children.push(node);
} else {
roots.push(node);
}
} else {
roots.push(node);
}
}
return roots;
}
private findCriticalPath(spans: Span[]): Span[] {
// The critical path is the longest chain of sequential spans
return spans
.filter((s) => s.status === "error" || s.duration > 500)
.sort((a, b) => b.duration - a.duration);
}
}
interface SpanNode {
span: Span;
children: SpanNode[];
}Clock Skew und kausale Ordnung
Verteilte Systeme können sich für die Reihenfolge nicht auf Wall-Clock-Timestamps verlassen, weil Uhren driften. Lamport-Timestamps oder Vektoruhren etablieren kausale Ordnung ohne synchronisierte Uhren.
class LamportClock {
private counter: number = 0;
tick(): number {
return ++this.counter;
}
receive(remoteTimestamp: number): number {
this.counter = Math.max(this.counter, remoteTimestamp) + 1;
return this.counter;
}
current(): number {
return this.counter;
}
}
// Use in service-to-service communication
class CausalMessageClient {
private clock: LamportClock;
constructor(private serviceName: string) {
this.clock = new LamportClock();
}
send(
destination: string,
payload: unknown
): { payload: unknown; timestamp: number; sender: string } {
const timestamp = this.clock.tick();
return {
payload,
timestamp,
sender: this.serviceName,
};
}
receive(message: {
payload: unknown;
timestamp: number;
sender: string;
}): { payload: unknown; localTimestamp: number } {
const localTimestamp = this.clock.receive(
message.timestamp
);
return {
payload: message.payload,
localTimestamp,
};
}
}Wenn Ereignis A den Lamport-Timestamp 5 und Ereignis B den Timestamp 8 hat, weißt du, dass B nicht A verursacht hat. Diese partielle Ordnung reicht aus, um "happens-before"-Beziehungen zu etablieren, die Wall-Clock-Zeit nicht garantieren kann.
Wichtige Erkenntnisse
Verteiltes Debuggen erfordert bewusste Instrumentierung — ohne Correlation IDs und strukturiertes Logging ist das Nachverfolgen eines Requests über Services hinweg nahezu unmöglich. Propagiere sowohl Correlation IDs (konstant über den gesamten Request) als auch Causation IDs (ändern sich bei jedem Hop), um den exakten Call-Graph zu rekonstruieren, der zu einem Fehler geführt hat. Verwende strukturiertes JSON-Logging mit konsistenten Feldern über alle Services hinweg, damit Log-Aggregationsabfragen das gesamte System abdecken. Setze verteilte Traces aus einzelnen Spans zusammen, um den vollständigen Request-Zeitstrahl zu visualisieren, den kritischen Pfad zu identifizieren und zu erkennen, wo Latenz auftritt. Verlass dich in verteilten Systemen nicht auf Wall-Clock-Timestamps für die Ereignisreihenfolge — verwende Lamport-Uhren oder Vektoruhren, um kausale Beziehungen aufrechtzuerhalten, die Clock Skew überleben. Die Investition in Observability-Infrastruktur amortisiert sich beim ersten Mal, wenn du einen Cross-Service-Fehler in Minuten statt Stunden diagnostizierst und die exakte Kette von Ereignissen vom Trigger bis zum Symptom nachverfolgst.
