Logging ist kaputt

• In modernen verteilten Systemen haben herkömmliche Logging-Ansätze eine strukturelle Grenze darin, die Wahrheit abzubilden
• Logs sind weiterhin auf die Single-Server-Umgebung von 2005 ausgelegt und verlieren dadurch den Kontext von Requests, die über mehrere Services, Datenbanken und Caches laufen
• Einfache Stringsuche versteht Struktur, Beziehungen und Korrelationen nicht und erschwert so die Ursachenanalyse
• Die Lösung besteht darin, pro Request ein einzelnes „Wide Event“ (oder „Canonical Log Line“) mit dem gesamten Kontext zu hinterlassen
• Dadurch werden Logs von reinem Text zu einem analysierbaren Datenbestand

---

Das grundlegende Problem von Logging

• Bestehende Logs wurden unter der Annahme des monolithischen Server-Zeitalters entwickelt und spiegeln die heutige verteilte Service-Architektur nicht wider
  • Ein einzelner Request durchläuft mehrere Services, DBs, Caches und Queues, doch Logs werden weiterhin aus Sicht eines einzelnen Servers geschrieben
• Im Beispiel entstehen pro Request 13 Zeilen; bei 10.000 gleichzeitigen Nutzern sind das 130.000 Zeilen pro Sekunde, von denen die meisten bedeutungslos sind
• Was man bei einem Problem braucht, ist Kontext, doch genau der fehlt in heutigen Logs

Die Grenzen der Stringsuche

• Wenn ein Nutzer meldet: „Die Zahlung funktioniert nicht“, ist es selbst bei einer Suche nach E-Mail oder user_id wegen der fehlenden einheitlichen Struktur schwer, brauchbare Ergebnisse zu bekommen
  • Dieselbe Benutzer-ID wird in zig verschiedenen Formen protokolliert, etwa als user-123, user_id=user-123 oder {"userId":"user-123"}
• Unterschiedliche Log-Formate zwischen Services machen das Nachverfolgen zusammenhängender Events unmöglich
• Das Kernproblem ist, dass Logs auf das Schreiben (write) ausgelegt sind und nicht für Abfragen (query) optimiert wurden

Definition zentraler Begriffe

• Structured Logging: Protokollierung als Key-Value-Format (JSON) statt als String
• Cardinality: Anzahl eindeutiger Werte eines Felds; bei user_id zum Beispiel sehr hoch
• Dimensionality: Anzahl der Felder in einem Log-Event; je mehr Felder, desto größer die Analysemöglichkeiten
• Wide Event / Canonical Log Line: Ein einzelnes Log-Event mit reichhaltigem Kontext pro Request
• Die meisten Logging-Systeme begrenzen Daten mit hoher Kardinalität aus Kostengründen, obwohl sie in der Praxis für Debugging am nützlichsten sind

Die Grenzen von OpenTelemetry

• OpenTelemetry (OTel) ist ein Protokoll- und SDK-Set, das nur einen Standard für Datenerfassung und -übertragung bereitstellt
• OTel übernimmt jedoch Folgendes nicht
  1. Es entscheidet nicht, was geloggt werden soll
  2. Es fügt keinen Business-Kontext (z. B. Abo-Stufe oder Warenkorbwert) automatisch hinzu
  3. Es verändert nicht die Denkweise von Entwicklern beim Logging
• Selbst bei Verwendung derselben Bibliothek unterscheidet sich die Debugging-Erfahrung drastisch zwischen bewusst mit Kontext angereicherter Instrumentierung und einfacher Instrumentierung
• OTel ist lediglich die Transportleitung (plumbing), und was hindurchfließt, müssen Entwickler selbst festlegen

Der Wide-Event-/Canonical-Log-Line-Ansatz

• Statt Logging danach auszurichten, „was der Code tut“, sollte man erfassen, „was mit dem Request passiert ist“
• Für jeden Request wird pro Service ein einzelnes umfangreiches Event erzeugt
  • Es kann mehr als 50 Felder enthalten, darunter Request-, Nutzer-, Zahlungs-, Fehler- und Umgebungsinformationen
• Das Beispiel-JSON enthält user_id, subscription_tier, service_version, error_code und damit den vollständigen Debugging-Kontext
• So lässt sich mit einer einzigen Suche sofort analysieren, warum Zahlungen von Premium-Nutzern fehlschlagen

Query-Nutzung von Wide Events

• Wide Events werden nicht per einfacher Textsuche behandelt, sondern über strukturierte Datenabfragen
• Auf Basis hochkardinaler und hochdimensionaler Daten wird Debugging auf dem Niveau von Echtzeitanalysen möglich
• Beispiel: Eine Query wie „Aggregiere die Fehlerrate bei Zahlungen von Premium-Nutzern der letzten Stunde nach Fehlercode“ lässt sich sofort ausführen

Implementierungsmuster

• Das Event wird über den gesamten Lebenszyklus eines Requests hinweg aufgebaut und am Ende genau einmal ausgegeben
  • In der Middleware werden Basisfelder wie request_id, timestamp, method und path initialisiert
  • Im Handler werden Nutzer-, Warenkorb-, Zahlungs- und Fehlerinformationen schrittweise ergänzt
• Am Ende wird mit logger.info(event) ein einzelnes JSON-Event protokolliert

Kostenkontrolle durch Sampling

• Wenn pro Request 50 oder mehr Felder geloggt werden, steigen die Kosten stark an, daher ist Sampling nötig
• Einfaches zufälliges Sampling birgt das Risiko, Fehler zu übersehen
• Vorgeschlagen wird eine Tail-Sampling-Strategie
  1. Fehler (z. B. 500er) werden immer gespeichert
  2. Langsame Requests (ab p99) werden immer gespeichert
  3. Sitzungen von VIP-Nutzern oder mit bestimmten Flags werden immer gespeichert
  4. Der Rest wird nur zu 1–5 % zufällig gesampelt
• So lassen sich Kosten senken und zugleich kritische Events erhalten

Häufige Missverständnisse

• Structured Logging ≠ Wide Event: Ein JSON-Format allein reicht nicht aus, entscheidend ist der Kontext
• OpenTelemetry im Einsatz ≠ vollständige Observability: Standardisiert wird nur die Erfassung, was aufgezeichnet wird, bleibt Aufgabe der Entwickler
• Nicht dasselbe wie Tracing: Tracing zeigt den Ablauf zwischen Services, Wide Events liefern Kontext innerhalb eines Services
• Die Trennung „Logs für Debugging, Metriken für Dashboards“ ist unnötig — Wide Events decken beide Anwendungsfälle ab
• Die Annahme, hochgradig kardinale Daten seien teuer, ist veraltet; moderne Datenbanken wie ClickHouse oder BigQuery verarbeiten sie effizient

Die Wirkung der Einführung von Wide Events

• Debugging wandelt sich von Archäologie zu Analytics
• Statt zur Suche nach „fehlgeschlagener Nutzerzahlung“ die Logs von 50 Services mit grep zu durchsuchen,
  entsteht ein analysegetriebener Ansatz auf Basis einer einzigen Query, etwa: „Zeige die Fehlerrate von Zahlungen bei Premium-Nutzern nach Fehlercode“
• Das Ergebnis: Logs werden von einem Werkzeug, das die Unwahrheit sagt, zu einem Datenbestand, der die Wahrheit liefert

[GN⁺]

Hacker-News-Kommentare

• Der Text war schwer zu lesen und wirkte, als wäre er mit AI unterstützt worden. Trotzdem war die Botschaft wertvoll, und etwas mehr Kürze wäre wohl besser gewesen.
  Dazu hatte ich in letzter Zeit folgende Gedanken.

  • Da es im gesamten Stack Authentifizierung gibt, habe ich begonnen, in jede Log-Zeile die user id aufzunehmen. Dadurch ist es viel einfacher geworden, die gesamte Erfahrung eines Nutzers nachzuvollziehen
  • Fehler getrennt von Request-Logs in separaten Zeilen zu protokollieren, ist umständlich. Man kann zwar nach Trace filtern, aber Abfragen wie „Zeig mir nur Fehler im Zusammenhang mit 5xx-Requests“ sind schwer zu bauen
  • Es reicht nicht, nur solchen Kontext hinzuzufügen; man muss die Kollegen auch darüber schulen, dass es neue Felder gibt. Ich habe oft gesehen, dass Leute unnötig leiden, weil sie es nicht wissen
  • Wenn man in bessere Tracing-Tools investiert, wird Debugging auf einem Niveau möglich, das mit einfachen Logs nicht machbar ist. Im Grunde ist das eine Erweiterung der Idee, die user id im Trace zu verwenden
  • Wenn es in der Codebasis bereits das Konzept einer request ID gibt, kann man damit das Verhalten eines Nutzers noch konkreter verfolgen
  • Wenn man TID serviceweit verbindlich macht, kann jedes Team mit einer einzigen TID die komplette Transaktion verfolgen
  • Solche Kommentare im Stil von „Das riecht nach AI“ werden wohl bald zu einer kulturell kritisierten Haltung werden

• Bei diesem Thema kommt man an Charity Majors nicht vorbei. Sie verbreitet seit über 10 Jahren die Konzepte „wide events“ und „observability“ und hat Honeycomb.io auf genau dieser Philosophie aufgebaut.
  Heute lässt sich dieser Ansatz mit verschiedenen Tools umsetzen. Wichtig ist, wide events mit structured logs oder traces zu erfassen und Werkzeuge mit starker Visualisierung wie Zeitreihen und Histogrammen zu nutzen

  • Den Begriff „observability“ selbst hat sie allerdings nicht geprägt. Das Konzept wurde schon seit Jahrzehnten in verschiedenen Bereichen verwendet. Sie ist eine einflussreiche Praktikerin, aber nicht die Urheberin des Begriffs
  • Ihr Blog und die Hintergrundgeschichte von Honeycomb sind für Leute aus der Branche absolut lesenswert. Das war eines der ersten Teams, das den Wert dieses Ansatzes erkannt hat
  • Der Text klang ihrem Stil so ähnlich, dass ich am Ende fast mit Werbung für Honeycomb gerechnet hatte — umso überraschender, dass es nicht so war
  • Im .NET-Ökosystem hat Nick Blumhardt schon sehr früh mit structured logging gearbeitet, und Seq sowie Serilog haben das unterstützt
  • Ihre Inhalte sind gut, aber niemand hat „observability“ als Marke vereinnahmt. Respekt ist angebracht, überzogene Behauptungen aber nicht

• Ich stimme einem Teil der Aussagen zu, aber beim Ansatz, nur ein einziges wide event zu hinterlassen, gibt es Fallstricke. Wenn mitten im Request eine Ausnahme oder ein Timeout auftritt, bleibt unter Umständen gar nichts übrig.
  Außerdem gehen Logs des Standard-Logging-Frameworks der Sprache oder von Abhängigkeiten verloren.
  Deshalb sollte das besser als zusätzliche Ebene über bestehenden Logs verwendet werden. Man vergibt IDs auf Request-/Session-Ebene und aggregiert dann z. B. in ClickHouse

  • Wenn die Sichtbarkeit der Zwischenschichten ein Problem ist, dann sind die Events schlicht nicht wide genug. log.error(data) und wide_event.attach(error, data) sind im Kern dasselbe
  • Logs wie „connection X:Y accepted at Z ns“ und „closed at Z ns“ sind beim Debugging langsamer Systeme äußerst nützlich
  • Ich habe das in einem PHP-Framework mit einem LoggerInterface gelöst. Ausnahmen werden von einem globalen Handler abgefangen und in breiter Form in der DB gespeichert. Etwas Boilerplate ist nötig, aber es funktioniert so gut, dass ich es inzwischen vermissen würde

• Die Präsentation und die interaktiven Beispiele waren hervorragend. Am Ende lässt sich das aber auf „Fügt strukturierte Tags zu Logs hinzu“ zusammenfassen.
  Bei wide logs fühlt sich der Nutzen im Verhältnis zu der zusätzlichen Komplexität und schlechteren Lesbarkeit nicht besonders groß an.
  Oft reicht schon grep "uid=user-123" application.log — muss man da wirklich noch die Versandart des Nutzers mitschreiben?
  (Zur Info: Im Android-Brave-Browser funktionierten die Checkboxen nicht)

  • Bei JSON-Logs kann man immer noch mit grep '"uid": "user-123"' suchen. Mit der Option --context sieht man außerdem die umgebenden Zeilen

• Ich habe in der Halbleiterfertigung mit Systemen gearbeitet, die tausende Teilnehmer auf Message-Bussen hatten. Dabei fielen 300–400 MB Logs pro Stunde an, aber das ließ sich mit grep und CLI-Tools allein gut beherrschen.
  Logs waren nur die Zeitreihe von Ereignissen, und Detailanalysen liefen über Oracle-Abfragen. Logs sind ein Werkzeug, um die Kausalität von Vorfällen zu verstehen

  • Logs dienen zum Erfassen einer Timeline, nicht dazu, sämtliche Daten von Request und Response zu enthalten. Zu viele Informationen machen das Verständnis eher schwerer.
    Logs sagen, „wann“ und „was“ passiert ist; das „warum“ findet man in der Kombination aus Code, Daten und Ereignissen
    Persönlich finde ich Interfaces wie den ELK-Stack für intuitive Exploration eher unpraktisch. Logs muss man wichtig intuitiv lesend verfolgen können
  • 400 MB Logs pro Stunde sind eigentlich nicht besonders viel. Deshalb kommt man mit einfachem grep gut zurecht

• Der Rat am Ende des Textes, „alle Fehler, Ausnahmen und langsamen Requests zu loggen“, ist eine gefährliche Idee.
  Wenn etwa eine Abhängigkeit langsam wird, kann sich das Log-Volumen leicht verhundertfachen.
  In Störungssituationen sollte ein Service eher weniger Arbeit leisten, um sich zu erholen — eine Log-Explosion führt dagegen leicht zu Kaskadenausfällen

  • Bei Cloudflare nutzt man adaptives Sampling. Log-Batches werden nach Feldern in Buckets eingeteilt, und aus jedem Bucket behält man nur die Quadratwurzel oder den Logarithmus der eingehenden Log-Anzahl.
    Je höher das Log-Volumen, desto stärker passt sich die Sampling-Rate automatisch an, sodass das System nicht überlastet wird
  • Solche magischen Schwellenwerte sind riskant. Werte wie P(99) sollten dynamisch aktualisiert werden. Wenn ein OTEL provider regelmäßig die realen Werte abruft, ist das sicherer
  • Produktivsysteme sollten so entworfen sein, dass die Log-Erfassung entsprechend der Nachfrage skaliert. Schon lokales Buffering auf Platte hilft enorm
  • Bei Services mit hohem Traffic kann man gesunde Requests sampeln, etwa mit trace_id mod 100 == 0
  • Wenn Logs zum Bottleneck werden, ist das System falsch entworfen. Effizientes Logging kann hunderte Millionen Ereignisse pro Sekunde verarbeiten

• In moderner Software ist es schwer, mit einem einzelnen Log vollständig zu beschreiben, „was passiert ist“.
  Deshalb braucht man vertikale Korrelation (Vertical correlation) und horizontale Korrelation (Horizontal correlation).
  Zwischen oberen und unteren Schichten im Stack sollte derselbe Korrelationswert geteilt werden, und bei Kommunikation zwischen Systemen braucht man Korrelation zwischen den Peers.
  Solche Werte in APIs oder Protokolle einzubauen, ist schwierig, aber wenn man Transaktions-IDs früh mitplant, wird vollständiges Tracing möglich

• Für einen einzelnen Text eine eigene Domain zu registrieren, halte ich für wenig nachhaltig.
  Da jedes Jahr Verlängerungsgebühren anfallen, sind ein persönlicher Blog oder eine Subdomain aus meiner Sicht sinnvoller.
  So etwas wie logging-sucks.boristane.com fände ich beispielsweise gut

  • Tatsächlich dienen diese Domain und der Text wohl der Werbung für das Observability-SaaS des Autors. Man braucht zwar ein Cloudflare-Konto, aber da das kostenlos ist, wirkt es wie eine langfristige Marketingstrategie. Trotzdem war es nützlich, und ich habe ohnehin ein CF-Konto und werde es wohl ausprobieren
  • Dieser Text steht in einem ähnlichen Kontext wie Simon Willisons „Give people something to link to“
  • Das ist weniger ein Blogpost als eher eine Lead-Generation-Seite für digitales Marketing. Die Service-Werbung ist ziemlich eindeutig

• Zur Aussage „Logs sind ein Relikt aus dem monolithischen Zeitalter“ denke ich, dass lokale Logs weiterhin sinnvoll sind.
  Ihre ursprüngliche Aufgabe ist es, die Vorgänge eines lokalen Prozesses festzuhalten; um zu verstehen, was auf anderen Servern passiert, braucht man Transaction Tracing.
  Schon mit Logs an den richtigen Stellen kann man die eigentliche Ursache finden

  • Logs dienen allerdings nicht nur der Ursachenanalyse, sondern liefern auch Business-Insights wie wer betroffen war, Zusammenhänge zwischen Performance und Eingaben oder die Auswirkungen von Sicherheitslücken.
    Logs mit reichhaltigem Kontext lassen sich zusammen mit Analyse-Engines auch für Produktverbesserungen nutzen
  • Auf die Aussage „Ein Request durchläuft 15 Services und 3 Datenbanken“ kam auch die Reaktion, dass man solche Komplexität lieber vermeiden sollte
  • Ich habe das Gefühl, dass APN/Kibana allein für Log-Analysen schon ausreicht

• Der Aussage „Logge nicht, was der Code tut, sondern was mit dem Request passiert“ stimme ich zu, aber der Autor wirkte auf mich unerfahren.
  Ich nenne das „bug parts logging“ und denke, dass dabei Frühwarnsignale wie Pfade, Häufigkeiten und Zeiten enthalten sein sollten.
  Logging ist nicht dasselbe wie Metriken oder Audit. Wenn Logging fehlschlägt, muss die Verarbeitung weitergehen; ein fehlgeschlagenes Audit ist dagegen kritisch.
  Wie beim „historian“-Konzept in SCADA-Systemen sollte man Beobachtbares (observables) und Bewertendes (evaluatives) unterscheiden.
  Feingranulare Ereignisse eines Kraftstoffsensors sind etwa für Diagnosen nützlich, aber für die Frage „Reicht es bis zum Ziel?“ unnötig.
  Am Ende ist entscheidend, klar zu definieren, was beobachtet und was bewertet werden soll

  • Ich unterstütze die „vereinheitlichte Theorie der Beobachtbarkeit“. Logs, Metriken und Audits sind letztlich alles nur Bitströme und lassen sich verlustfrei ineinander umwandeln.
    Speicherung, Transformation und Abfrage unterscheiden sich zwar, aber Konsumptionspunkte und Mechanismen können gleich entworfen werden.
    Dadurch wird das Systemdesign einfacher, und langfristig gespeicherte Logs lassen sich später erneut verarbeiten