Ich bin zurück aus dem Urlaub (seit einer Woche schon, aber man kommt ja zu nichts) und muss jetzt erst einmal ein paar Themen aufarbeiten, die mir in letzter Zeit Gedanken gemacht haben. Das erste davon ist: logging.
Ich schaue mir wöchentlich die Seite This Week in Rust an. Dort werden aktuelle Entwicklungen der Programmiersprache rust sowie alle möglichen Artikel zu rust verlinkt. In Ausgabe 487 von vor ein paar Wochen war dieser Artikel über logging verlinkt. Darin werden einige Ratschläge gemacht, denen ich wirklich widersprechen muss.
Hier stimme ich zu
Zuerst einmal stehen in dem Artikel durchaus ein paar Aussagen, denen ich so zustimme. Logging kann sehr hilfreich zur Fehlersuche sein. Nicht in jeder Situation kann man das Programm einfach in einem Debugger laufen lassen. Und ein Loggingframework kann helfen, übersichtlichere logs zu schreiben (aber es sollte relativ klein und simpel sein, sonst passiert so etwas wie bei log4j.
Aber hier stimme ich nicht zu
Aaaaber… In dem Artikel wird empfohlen:
You should log as much as possible.
Every time you make a decision, you should log it. Every time you query a URL or build a string of some kind, you should log it. Every time you load a config parameter, you should definitely log it.
Nun ist anzumerken, dass es hier um ein debug-loglevel geht, also eins, das im Produktivbetrieb nicht aktiv ist. Aber dazu später mehr.
Aber der Grundaussage kann ich nicht zustimmen. Konfigurationsparameter loggen? Geschenkt, sofern es keine secrets sind. Angefragte URLs loggen? Von mir aus. Jeden string loggen? Bitte nicht. Jede Entscheidung loggen? Um Himmels Willen, nein!
Ich habe meine Erfahrung mit Services, die zu viel loggen. Da schaltet man log-level debug ein und sieht dann vor lauter Logmeldungen nicht mehr das, was man eigentlich untersuchen möchte. In der Regel sind die Informationen, die man wirklich braucht, sowieso nicht dabei. Logzeilen sausen vor deinen Augen vorbei, zu schnell, als dass du irgendetwas erkennen kannst, zu viele, als dass man sie im Nachhinein durchlesen kann.
Loglevel
Ein kleiner Exkurs zu logleveln: Die meisten Logging-Bibliotheken unterstützen das Konzept von „logleveln“: Auf der einen Seite wird jeder Logmitteilung ein Level zugewiesen. Auf der anderen Seite wird global gesetzt, auf welchem Level gelogged wird. Im laufenden Programm werden dann immer nur die Logmeldungen tatsächlich geschrieben, die mindestens so schwerwiegend wie das globale loglevel sind.
Als Beispiel: Wenn es die loglevel „error“, „warning“, „info“ und „debug“ gibt, und das globale loglevel auf „warning“ gesetzt ist, werden nur logmeldungen mit level „error“ und „warning“ gelogged.
Wie das globale loglevel gesetzt wird, ist unterschiedlich. Das geht von statisch (zur compilezeit wird entschieden, welche Logmeldungen es in den Code schaffen) über konfigurierbar (das loglevel steht in einer Konfigurationsdatei und wird beim Start des Programms gelesen) bis dazu, zur laufzeit konfigurierbar zu sein (man kann das loglevel ändern, ohne das Programm neu zu starten).
Debuggen auf Produktivsystemen
Üblicherweise ist das loglevel auf Produktivsystemen „error“ oder „warning“. Den ganzen Debug-Müll, den man der obengenannten Empfehlung nach generieren würde, würde hier also nicht gelogged werden.
Also muss man sie, wenn man auf Fehlersuche ist, erst aktivieren. Wenn wir ein Produktivsystem debuggen möchte — viel Spaß. Als erstes müssen wir das Loglevel ändern. Bei statischen logleveln müssen wir neu bauen und neu deployen. Bei konfigurierbaren logleveln müssen wir die Konfiguration ändern und gegebenenfalls das Programm neu starten.
Angenommen, das Programm ist ein Webservice. Umkonfigurieren wäre hier der Idealfall. Aber heutzutage wird ja alles in Docker-Container verpackt und deployed. Also muss man am Ende doch den ganzen Container neu bauen, um die Konfiguration zu ändern. Und dann ist der Unterschied zu „wir müssen neu compilieren“ auch nicht mehr so groß.
Wenn man aber sowieso neu bauen und deployen muss, kann man es sich auch sparen, grundsätzlich jedes Detail zu loggen. Stattdessen kann man hier eingreifen und nur die Teile loggen, die für das Problem relevant sind.
Denn ansonsten hat man den oben erwähnten Wust von Logmeldungen, von denen nur sehr wenige relevant sind (und die wirklich interessanten Teile vermutlich trotzdem fehlen). Außerdem kann es vorkommen, dass aus Versehen irgendwo sensible Daten gelogged werden. Je mehr gelogged wird, desto größer die Wahrscheinlichkeit, dass das passiert.
Aber was soll ich denn jetzt loggen?
Was soll ich loggen? Einfach: Fehler. Und zwar auf loglevel „error“. Und es dürfen keine Fehler gelogged werden.
Klingt widersprüchlich, ist es aber nicht. Mit „Fehler“ meine ich keine Benutzerfehler, sondern entweder Fehler im Programm oder Laufzeitfehler, die verhindern, dass der Service korrekt läuft. Eine essentielle Datei ist nicht da? Fehler loggen. Irgendwo wird ein ungültiger Zustand erreicht? Fehler loggen. Wenn man dem Benutzer trotzdem noch eine sinnvolle Antwort geben kann, gerne, aber trotzdem Fehler loggen.
Die Idee dahinter ist folgende: Das sind Fehler, die das Programm nicht selber beheben kann, die also Programmier- oder Konfigurationsfehler sind. Hier muss jemand draufschauen. Wenn ein Fehler gelogged wird, muss er entweder behoben werden (wenn es wirklich ein Fehler ist) oder er darf nicht gelogged werden (weil es nicht wirklich ein Fehler ist).
Die Logdatei bleibt so übersichtlich. Wenn sie leer ist, ist alles in Ordnung. Wenn nicht, muss etwas getan werden. Man muss sich nicht erst durch Gigabytes von Logmeldungen quälen um zu sehen, ob etwas nicht stimmt.
Warum keine Warnungen loggen?
Ok, also im Normalbetrieb werden nur Fehler gelogged, beim Debuggen auch Debugmeldungen. Was ist mit Warnungen?
Warnungen werden nicht gelogged. Warnungen sind eine halbgare Sache. Muss jetzt etwas getan werden? Oder nicht? Darf ich die Warnung ignorieren? Hier gibt es keine klare Handlungsstrategie. Eine Warnung bedeutet „Hier ist etwas ungewöhnliches passiert, das vielleicht ein Problem ist, vielleicht aber auch nicht, aber ich (das Programm) kann normal weitermachen“.
Was man für solche Fälle wirklich haben möchte, ist ein Monitoring-System. Also etwas, dass zählt, wie oft man in diesen ungewöhnlichen Zustand kommt. Passiert es ein Mal? Vermutlich kein Problem. Passiert es gehäuft? Dann kann es auf Probleme hinweisen, z.B. Programmierfehler, Konfigurationsfehler, Usability-Probleme oder sogar ein Angriff.
Aber im Log haben Warnugen nichts zu suchen.
Und das info-Loglevel?
Reine Informationen sollten auch nicht ständig gelogged werden, sondern nur, wenn es zu Problemen kommt. Dann ist es egal, ob auf dem loglevel debug oder dem loglevel info.
Eine Anekdote mit Gigabytes an Logdaten
Bei meinem vorherigen Arbeitgeber hatten wir ein paar Fälle, wo zu viel gelogged wurde. In einem oder zwei Fällen wurde das auch richtig teuer, weil dabei pro Tag Gigabyteweise Logdaten durch die Gegend geschickt wurden. Die Teams in diesen Projekten haben dann einiges an Aufwand betrieben, um die Datenflut auf ein erträgliches Maß zu reduzieren. Das war erfolgreich, am Ende war aus der Logflut ein Logtröpfeln geworden.
Auch in einem meiner Projekte wurde zu viel gelogged, allerdings nicht Gigabytes pro Tag. Wir haben das stetig zurückgebaut, bis es erträglich wurde. Insbesondere im Frontend hat ein Kollege sehr viel Wert darauf gelegt, dass in der Javascript-Console nichts gelogged wird. Das macht das Debuggen, wenn man dann temporär ein paar Logmeldungen einbaut, viel erträglicher.