Wide Events in C#: Ein Event pro Request

Ein Checkout scheitert ohne Spur: Dutzende Log-Zeilen kosten Zeit, liefern aber keinen Kontext. Die Lösung sind Wide Events. Statt Code-Schritte fragmentiert zu protokollieren, bündeln Sie alle relevanten Daten in einem einzigen Event pro Request. So gelingt echte Observability in C#.

An einem Donnerstagnachmittag landet ein Ticket in der Warteschlange:

„Kunde meldet, dass der Checkout heute Nachmittag fehlgeschlagen ist. Eine Bestellnummer liegt nicht vor. Können Sie das prüfen?"

Der weitere Verlauf ist absehbar. Sie öffnen Ihr Log-Werkzeug, filtern auf den Checkout-Service, erweitern den Zeitraum auf zwei Stunden, denn „heute Nachmittag" ist kein genauer Zeitpunkt. Anschließend beginnen Sie zu lesen. Irgendwann finden Sie das hier:

Vier Zeilen. Alle vier sind zutreffend. Keine einzige hilft dabei, das Problem zu finden.

Um welchen Warenkorb ging es? Was lag darin? War der Kunde Teil des neuen Pricing-Flows, der am Dienstag ausgerollt wurde? War das der erste Versuch oder der vierte? Was genau hat das Payment-Gateway geantwortet, als es zu dem Fehler kam?

Der entscheidende Punkt: Der Prozess kannte all diese Informationen. Jede einzelne davon lag zum Zeitpunkt der jeweiligen Log-Zeile im Speicher und im Scope. Wir haben nur nie danach gefragt. Wir haben protokolliert, was der Code tut, und nicht, was mit dem Request passiert. Die interessanten Informationen sind damit unwiederbringlich verloren. Genau hier setzen Wide Events an – und mit ihnen ein anderes Verständnis von Observability.

Wer mit .NET arbeitet, hat einen der empfohlenen Schritte vermutlich längst gemacht: Message Templates statt String-Interpolation:

Und die Daten dann strukturiert per JSON in einer Datei oder einem anderen Log-Sink abgelegt. Damit ist OrderId ein echtes Feld, auf das sich filtern lässt, statt eines Teilstrings, bei dem man hoffen muss, dass er genauso geschrieben wurde wie vom Kollegen, der die Zeile implementiert hat. Das ist ein echter Fortschritt und absolut richtig.

Entscheidend ist aber, was sich dabei nicht geändert hat. Das Format ist besser geworden, die Einheit nicht. Die Einheit des Loggings ist nach wie vor ein Moment in der Ausführung des Codes: eine Zeile, die feuert, wenn der Kontrollfluss sie erreicht, und die nur das kennt, was genau dort im Scope liegt. Zwanzig strukturierte Zeilen pro Request sind immer noch zwanzig Fragmente, die im Störungsfall manuell zusammengesetzt werden müssen: im Kopf, unter Zeitdruck, in einer Codebasis, die man zuletzt vor sechs Monaten angefasst hat.

Hinzu kommt ein praktisches Problem unter Last: Ein Service verarbeitet viele Requests gleichzeitig, sodass sich ihre Log-Zeilen chronologisch vermischen. Zwischen „Request gestartet" und „Payment fehlgeschlagen" stehen dann Einträge aus Dutzenden anderer Vorgänge. Eine Request- oder Trace-ID macht die Zeilen zwar grundsätzlich korrelierbar, setzt aber voraus, dass sie durchgängig an jeder relevanten Stelle mitgeführt wird. Selbst dann muss man zunächst den passenden Request identifizieren, anschließend nach seiner ID filtern und danach mehrere Fragmente in die richtige Reihenfolge bringen. 

Ein Wide Event ist ein einzelner, strukturierter Datensatz pro abgeschlossener Arbeitseinheit, meist ein Request, der erst am Ende emittiert wird, wenn das Gesamtergebnis feststeht. Statt zwanzig verstreuter Log-Zeilen entsteht eine zusammenhängende, gezielt abfragbare Einheit: Ergebnis, Dauer, beteiligte Dependencies, Kunden- und Geschäftsdaten in einem einzigen Eintrag.

Die Idee ist nicht neu: Unter Namen wie Canonical Log Lines beschreibt sie etwa Stripe seit Jahren. Unter dem Schlagwort Observability 2.0 hat sie zuletzt neuen Auftrieb bekommen. Eine aktuelle Diskussion dazu liefert zudem der Artikel Logging Sucks – Your Logs Are Lying To You von Boris Tane.

Der Kern der Idee besteht darin, neu zu definieren, was überhaupt ein protokollierungswerter Moment ist: Ein Request erreicht den Service, verrichtet Arbeit und verlässt ihn wieder. Diese Lebensdauer ist ein zusammenhängender Vorgang. Entsprechend sollte sie als genau ein Vorgang protokolliert werden. Das Event wird erst dann emittiert, wenn alle Informationen vorliegen.

Zwei Begriffe sind an dieser Stelle zentral:

1. Kardinalität: Bezeichnet die Anzahl der unterschiedlichen Werte, die ein Feld annehmen kann. Environment hat beispielsweise drei mögliche Werte (Development, Staging, Production), CustomerId womöglich zwei Millionen. Felder mit hoher Kardinalität sind genau jene, mit denen sich dieser eine Request gezielt isolieren lässt statt nur ähnlicher Requests. Gleichzeitig sind es genau die Felder, von deren Nutzung bei klassischen Log-Indizes traditionell abgeraten wird.

2. Dimensionalität: Bezeichnet die Anzahl der Felder pro Event. Sie bestimmt, wie viele verschiedene Fragen sich im Nachhinein beantworten lassen. Sechs Felder beantworten sechs Fragen. Sechzig Felder beantworten auch Kombinationen, an die vorher niemand gedacht hat. Das ist der eigentliche Punkt, denn im Störungsfall weiß man vorher nie, welche Informationen zur Problemlösung nötig sind.

Sechzig Felder in einer Zeile klingen zunächst nach viel. Zwanzig Log-Zeilen mit je acht Properties bedeuten allerdings mehr Daten, in schlechterer Struktur, verteilt über zwanzig Fragmente, die im Ernstfall erst wieder zusammengeführt werden müssen.

Das Muster ist ein Akkumulator mit Request-Scope: Er wird befüllt, während der Request durch die Schichten wandert, und genau einmal an der Grenze geschrieben.

Registriert wird die Klasse als Scoped, sodass alle Schichten innerhalb eines Requests dieselbe Instanz erhalten. Das eigentliche Logging wird in einer Middleware behandelt, die den kompletten Ablauf der Anfrage umfasst:

Es gibt nur diesen einen Ausgabepunkt im finally-Block, der unabhängig davon, ob der Request erfolgreich war, fachlich fehlgeschlagen ist oder eine Exception geworfen hat, ausgeführt wird und die Nachricht speichert.

Die Services und Handler, die die eigentliche Business-Logik ausführen, schreiben nun keine Logs mehr, sondern liefern ausschließlich Kontext:

Auch Drittanbieter-Abhängigkeiten lassen sich auf dieselbe Weise ergänzen, etwa um Status-Code oder Antwortzeit.

Wer bereits OpenTelemetry einsetzt, setzt dieselben Felder als Tags auf Activity.Current – dann ist das Wide Event der Span. Entscheidend dabei: OpenTelemetry ist ein Transportweg und eine Schema-Konvention. Es transportiert Telemetriedaten, entscheidet aber nicht über deren Inhalt. Auto-Instrumentierung kann für grundlegende Werte helfen, kann aber nie Informationen zu Business-relevanten Prozessen liefern.

Das bisherige Beispiel setzt stillschweigend voraus, dass die fachliche Arbeit mit der HTTP-Antwort abgeschlossen ist. In vielen Systemen – etwa in verteilten Microservice-Architekturen – stößt ein Request jedoch nur einen länger laufenden Prozess an: Eine Nachricht landet in einer Queue, mehrere Consumer arbeiten nacheinander oder parallel, ein externer Dienst antwortet später per Callback. Ein einziges Event für den ursprünglichen Request würde dann zwar den Start erklären, aber nicht den Ausgang des eigentlichen Vorgangs.

Die sinnvollere Einheit ist deshalb nicht grundsätzlich der Request, sondern eine abgeschlossene Arbeitseinheit. Der HTTP-Endpunkt emittiert ein Event darüber, dass der Checkout angenommen und eine Nachricht veröffentlicht wurde. Der Payment-Consumer erzeugt ein eigenes Event für die Verarbeitung dieser Nachricht. Ein nachgelagerter Versandprozess macht dasselbe. Jedes Event enthält den vollständigen Kontext seines lokalen Schritts und wird genau dann geschrieben, wenn dessen Ergebnis feststeht. Batch-Prozesse geben für jedes bearbeitete Item aus dem Arbeitspool ein Event aus.

Damit aus diesen Events wieder ein zusammenhängender fachlicher Ablauf wird, müssen die relevanten Identitäten jede Grenze überleben: etwa trace.id für die technische Korrelation, order.id oder workflow.id für den fachlichen Vorgang sowie message.id für die einzelne Nachricht. So bleiben die Schritte verbunden, ohne dass unterschiedliche Lebensdauern künstlich zusammengefasst werden müssen.

Auch Retries und teilweise Bearbeitung von Aufgaben werden so besser erklärbar. Statt viermal dieselben Log-Nachrichten hintereinander zu sehen, lässt sich eine retry.attempt-Eigenschaft auswerten und so wichtige Information über die Zuverlässigkeit der Logik gewinnen.

„Ein Event pro Request" ist damit eine nützliche Einstiegsregel, das Muster ist aber eher ein Wide Event pro abgeschlossener Arbeitseinheit. Die Größe einer Arbeitseinheit hängt dabei von der Anwendung und den implementierten Prozessen ab.

Es gibt dann noch einen naheliegenden Einwand: Sechzig Felder bei zehntausend Requests pro Sekunde erzeugen erhebliche Speicherkosten.

Die Antwort ist allerdings nicht, weniger Felder zu erfassen, sondern nur weniger Events aufzubewahren. Die Entscheidung sollte auf Basis dessen getroffen werden, was tatsächlich passiert ist. Diese Entscheidung kann fallen, wenn der Request schon komplett bearbeitet ist. Ein Beispiel:

Die Funktion bewahrt alle Events mit einem Fehlerfeld auf und zieht von den übrigen Requests eine zufällige Stichprobe von fünf Prozent. Weitere Regeln können gezielt langsame Requests oder fachlich besonders relevante Vorgänge berücksichtigen. Welche Kriterien dabei konkret gelten und wie sie gewichtet werden, hängt von den fachlichen Anforderungen und den entsprechenden Business-Entscheidungen ab. Voraussetzung dafür ist lediglich, dass die dafür benötigten Informationen im Event vorliegen.

Ein Hinweis für den Betrieb mehrerer Services in einem System: Die Entscheidung, ob eine Nachricht gespeichert oder verworfen wird, sollte für den gesamten Trace einheitlich getroffen werden. Ansonsten bleibt das Checkout-Event erhalten, während das erklärende Payment-Event nicht gespeichert wird. Die Weitergabe der Entscheidung über HTTP-Header kann funktionieren; diese Logik an einer zentralen Stelle zu implementieren führt allerdings zu besserer Nachvollziehbarkeit.