Logs, die man nachts um drei lesen kann

Es gibt einen Moment, den jeder kennt, der etwas betreibt: Irgendetwas ist kaputt, es ist spät, und man sitzt vor einem Protokoll, in dem alles steht — außer dem, was man wissen will.

Ich hatte diesen Moment im Herbst 2022 einmal zu oft und habe danach zwei Abende damit verbracht, mein Logging von Grund auf umzustellen.

Was vorher da war

console.log an Stellen, an denen ich einmal einen Fehler gesucht hatte. Über die Jahre gewachsen, ohne System:

console.log("hier");
console.log("gilde:", gilde.id);
console.log(fehler);

Das Grundproblem daran ist nicht der Stil, sondern dass man daraus nichts filtern kann. Alles ist derselbe Kanal, alles derselbe Detailgrad. Wenn zwanzig Nachrichten pro Sekunde durchlaufen, ist die eine wichtige nicht auffindbar.

Die vier Dinge, die in jede Zeile gehören

Ein Zeitstempel mit Zeitzone. Klingt selbstverständlich, ist es nicht — ich hatte Protokolle ohne. Und zwar in UTC, nicht in Ortszeit, sonst wird der Abgleich mit anderen Systemen zum Rätselraten.

Ein Schweregrad. Mindestens debug, info, warn, error. Ohne Grade kann man nichts ausblenden, und ohne Ausblenden gibt es keine Übersicht.

Ein Bereich. Woher kommt die Zeile? bot:befehl, bot:ereignis, web:auth, db. Damit lässt sich ein Problembereich isolieren, ohne die restlichen Zeilen zu lesen.

Der Zusammenhang als Daten, nicht als Text. Das ist der wichtigste Punkt. Statt Werte in einen Satz zu schreiben, gehören sie als Felder daneben:

log.error(
  { bereich: "bot:befehl", befehl: "warn", gilde: gildeId, fehler: fehler.message },
  "Befehl fehlgeschlagen"
);

Der Unterschied zeigt sich beim Suchen. Ein Satz lässt sich nur mit Textsuche durchkämmen. Felder lassen sich filtern — alle Fehler eines bestimmten Servers, alle Aufrufe eines bestimmten Befehls, alles zu einem bestimmten Nutzer.

Eine Kennung, die durch alles durchgeht

Die Änderung mit dem größten Effekt bei der Fehlersuche war eine Kennung pro Vorgang. Wenn jemand einen Befehl auslöst, bekommt dieser Aufruf eine Kennung, die in jeder Protokollzeile mitläuft, die dazu gehört — auch in denen aus tieferen Schichten.

[14:22:31] info  bot:befehl  vorgang=8f3c  Befehl gestartet befehl=stats
[14:22:31] debug db          vorgang=8f3c  Abfrage 12ms
[14:22:32] warn  bot:befehl  vorgang=8f3c  Antwort verzögert (1120ms)

Damit kann man einen einzelnen Vorgang aus einem Protokoll herausziehen, in dem hunderte gleichzeitig laufen. Ohne diese Kennung ist ein Protokoll unter Last praktisch unlesbar, weil sich die Zeilen verschiedener Vorgänge verschachteln.

Wenn dieselbe Kennung außerdem in der Fehlermeldung an den Nutzer auftaucht — „Da ist etwas schiefgelaufen (Kennung 8f3c)" — kann man aus einer Beschwerde direkt in die passenden Zeilen springen. Das ist eine der billigsten und wirksamsten Verbesserungen überhaupt.

Warum ich vollständige Fehlerobjekte inzwischen kritisch sehe

Lange Zeit habe ich in jedem catch das komplette Fehlerobjekt ausgegeben. Das wirkt gründlich und hat zwei Nachteile, die mir erst später klar wurden.

Erstens: Fehlerobjekte enthalten oft mehr, als man denkt. Ein Datenbankfehler kann die vollständige Abfrage samt Werten enthalten. Ein HTTP-Fehler kann Kopfzeilen mit Zugangsdaten mitbringen. Wer das ungefiltert schreibt, hat ein Datenleck im Protokoll.

Zweitens: Es ersetzt kein Nachdenken. Ein catch, das alles ausgibt und weitermacht, sieht aus wie Fehlerbehandlung und ist keine. Die Frage, was in diesem Fall eigentlich passieren soll — abbrechen, wiederholen, Ersatzwert nehmen, Nutzer informieren — bleibt unbeantwortet.

Ich schreibe deshalb heute lieber die Fehlermeldung plus gezielt ausgewählte Felder, und der Verlaufsstapel nur bei Fehlern, die ich wirklich nicht erwartet habe.

Was ich mir angewöhnt habe

• Ein error bedeutet: Ich muss etwas tun. Wenn eine Zeile mit diesem Grad regelmäßig auftaucht und niemand handelt, ist entweder der Grad falsch oder das Problem ungelöst.
• warn ist für Dinge, die noch gut gehen, aber nicht sollten. Eine erschöpfte Wiederholung, eine langsame Antwort, eine veraltete Konfiguration.
• debug darf laut sein, ist aber im Normalbetrieb aus.
• Protokolle rotieren. Eine Datei, die unbegrenzt wächst, füllt irgendwann die Platte — und ein volles Dateisystem legt alles lahm, nicht nur das Protokoll.

Der Aufbau, den ich heute benutze

Damit dieser Eintrag praktisch bleibt, hier die tatsächliche Struktur, in der meine Protokolle entstehen.

Ein Protokollierer pro Bereich, mit fest gesetztem Bereichsnamen. Damit muss ihn niemand bei jedem Aufruf mitschreiben, und er ist überall gleich geschrieben.

Eine Vorgangskennung, die durch alle Schichten mitläuft. Sie entsteht ganz außen — beim Eingang einer Anfrage oder beim Start eines Befehls — und wird nach innen weitergereicht.

Feste Feldnamen für wiederkehrende Werte. Bei mir sind das immer dieselben: gilde, nutzer, dauer, fehler. Uneinheitliche Benennung macht Filter unbrauchbar.

Eine Maskierung, die vor der Ausgabe greift. Bekannte Geheimnisfelder werden ersetzt, unabhängig davon, wer die Zeile geschrieben hat.

Ein Ziel, nicht mehrere. Alles geht auf die Standardausgabe, und was damit passiert, entscheidet die Umgebung. In einem Container ist das die einzige sinnvolle Wahl.

Was ich über die Menge gelernt habe

Am Anfang habe ich zu wenig protokolliert, danach zu viel. Beides ist unbrauchbar, und der Ausweg ist keine Zahl, sondern eine Frage:

Würde ich diese Zeile lesen wollen, wenn ich ein Problem suche?

Zeilen, die im Normalbetrieb im Sekundentakt erscheinen, beantworten das mit nein. Sie erzeugen Rauschen, in dem die eine wichtige Zeile untergeht.

Meine Faustregel: Ein Vorgang erzeugt eine Zeile, wenn er abgeschlossen ist — mit Ergebnis und Dauer. Zwischenschritte nur bei Fehlern oder im ausdrücklichen Fehlersuchmodus. Ein Befehl, der drei Datenbankabfragen macht, schreibt eine Zeile, nicht vier.

Die Ausnahme sind Zustandsübergänge: Start, Herunterfahren, Verbindung verloren, Verbindung wiederhergestellt, Konfiguration neu geladen. Diese Zeilen sind selten und beantworten beim Suchen als Erstes die Frage, was das System zu diesem Zeitpunkt eigentlich getan hat.

Der eigentliche Perspektivwechsel

Was sich für mich verändert hat, war die Frage, für wen ich protokolliere.

Vorher habe ich für mich beim Programmieren geschrieben: Zeilen, die im Moment des Suchens hilfreich waren, und die danach stehen blieben. Danach habe ich für mich in sechs Monaten geschrieben, um drei Uhr nachts, ohne Erinnerung daran, wie dieser Codeabschnitt funktioniert.

Diese zweite Person braucht andere Dinge: Zusammenhang statt Zwischenstände, Kennungen statt „hier", Felder statt Sätze. Seitdem stelle ich mir beim Schreiben einer Protokollzeile vor, sie in einer Liste von zehntausend anderen zu finden — und formuliere sie so, dass ich sie dort auch verstehe.