Logging: Wake me up in the middle of the night!

WakeMeUpInTheMiddleOfTheNight! Wie ich die Welt des Loggings neu strukturieren wollte. Gedanken über die Abstraktheit von Log Levels und welche Auswirkungen die Wahl des falschen Levels haben kann.

Wir alle haben schon Log-Meldungen geschrieben. Egal ob Debug, Info, Warn oder Error, im Grunde geht es immer nur um eine Sache: Informationen!
Das Debug Log, das uns Entwicklern hilft, nachzuvollziehen, was unser Programm gerade macht, oder das Error Log, das dem Betrieb Informationen gibt, warum das Programm abgestürzt ist.
Aber gerade im produktiven Betrieb sind Log-Meldungen manchmal mehr Anweisung als Information.
Wenn ein Programm abstürzt, dann gilt es, Maßnahmen zu ergreifen. Reicht es, das Programm einfach neu zu starten? Muss die Konfiguration geändert werden? Sind Eingabedaten fehlerhaft? Ist ein Fremdsystem nicht verfügbar bzw. die Resilienz falsch eingestellt? Oder handelt es sich vielleicht um einen kritischen Bug, der von einem Entwickler „ASAP“ gefixt werden muss?
Gerade wenn letzterer Fall am Wochenende oder in der Nacht eintritt, kann man eben nicht mal schnell ins Büro nebenan zum Kollegen aus der Entwicklungsabteilung gehen, nein, dann muss man ihn aus dem Bett klingeln. Und wehe, wenn der schlecht gelaunte und unterkoffeinierte Entwickler dann feststellen muss, dass die Error-Meldung eigentlich nur ein Warning oder gar eine Info ist, weil der Kollege mal wieder nicht verstanden hat, wie man Log Level richtig verwendet. Man kennt’s.

Büro statt Bier

Ich selbst war auch schon in genau so einer Situation! Das neue, große Release sollte am Samstag ausgerollt werden. Entwicklung und Betrieb (DevOps gab’s da noch nicht) haben im Vorfeld geübt und diverse Fehlerszenarien besprochen und Reaktionen geplant. Es wurden Handbücher geschrieben, wie in welchem Fall zu handeln ist. Zeitpläne wurden erstellt und Rufbereitschaften wurden zugewiesen.
Und so kam es, dass der Zeitplan vorsah, das Rollout gegen 10 Uhr Vormittags zu beginnen und bis 18 Uhr abgeschlossen zu haben. Und für exakt diesen Zeitraum hat man mir eine Rufbereitschaft zugeteilt.
Da sitze ich nun, brav daheim auf dem Sofa, das Handy neben mir und bereit, im Notfall ins Büro zu fahren und die Brände zu löschen.
Als die Uhr dann 17:30 Uhr schlug und nichts geschehen war, habe ich mir zuversichtlich ein Bier aufgemacht: „Wenn bis jetzt nichts explodiert ist, wird auch jetzt auch nichts mehr passieren“.
Und dann fing das Handy an zu klingeln: „Büro“.
Nein! Das darf doch jetzt nicht wahr sein! Das gute Bier!
„Hallo Holger, du musst bitte ins Büro kommen, wir brauchen Hilfe!“
Um keine weitere Zeit zu verlieren bestätige ich kurz, leg auf und springe sofort ins Auto, fahre fast zu schnell ins Büro, stürme zum Kollegen, der mich angerufen hat und frage nach, was denn passiert ist, welche Fehlermeldung denn komme.

Ja, gar keine.

Sie fangen jetzt, um 17:45 Uhr, erst an zu deployen. Und ich soll halt dann schon mal im Büro sein, einfach nur zur Sicherheit, falls was passiert.

…

Der Begriff „Rufbereitschaft“ lässt scheinbar ziemlich viel Spielraum zur Interpretation übrig. Wie ich meinen Frust darüber kundgetan habe, nun, das ließ hingegen gar keinen Interpretationsspielraum übrig.

Solche extremen Fälle sind, zumindest bei mir, die Ausnahme. Ja tatsächlich gab es nur diesen einen Fall.
Aber wie kam es denn überhaupt dazu, dass man mich, der „Rufbereitschaft“ hat, ins Büro rief, um dann einen „Bereitschaftseinsatz“ zu haben, obwohl nichts vorgefallen war?
Im Nachhinein hat sich gezeigt, dass die Besprechungen aus dem Vorfeld mit Betriebskollegen geführt wurden, die dann am Rollout nicht teilnahem. Die Kollegen, die am Rollout teilnahmen, wussten nichts von den Besprechungen. Man kennt’s.

Zum Glück sind solche extremen Ereignisse, zumindest für mich, die Seltenheit. Ja, tatsächlich war dies der einzige Fall dieses Ausmaßes.
Doch schwächere Fälle sind da schon häufiger. Wie oft kommen Kunden und Kollegen auf mich zu und erzählen mir mit ganz unterschiedlichen Mienen von den Error Logs, die sie vom Betrieb gemeldet bekommen haben.
Hm, kryptische Meldungen, erzählen was von fehlenden Werten, Bedingungen, die nie erfüllt sein sollten, und von Sternkonstellationen, in denen der „Anti-Compiler“ kommt. Und dann taucht auch noch das „Safety Pig“ auf und erzählt was davon, wie diese Meldung alle Probleme automatisch beseitigen will (was sie natürlich nicht tut). Und das alles auf Error Level! Man kennt’s.

Schaut man dann mal in den Code, der diese kruden Log-Meldungen produziert, sieht man sehr schnell, dass es sich hier um Meldungen handelt, die gar nicht so kritisch sind. Artefakte von damals, „von vor dem großen Refactoring“, oder vom lieben Kollegen, der seine Debug-Meldungen grundsätzlich als Error loggt, weil der rote Text in der Konsole einfacher zu finden ist. Oder [generische Begründung für ein einfach nur falsches Log Level].

„Error“, was ist das überhaupt für ein Wort? Oder „fatal“? So fatal kann es ja gar nicht sein, das Programm kann ja immerhin noch die Log-Meldung schreiben. Da soll mich der Betrieb mal schön in Ruhe lassen! Ich habe Wichtigeres zu tun, als die Debug-Meldungen vom faulen Kollegen aus dem Error Log zu analysieren.

DevOps? Fehlanzeige!

Aber woher weiß der Betrieb das? Woher weiß der Betrieb, ob er mich in Ruhe lassen soll? Ja, mit DevOps ist das natürlich kein Problem. Betrieb und Entwicklung sind in einem Team und es findet ein reger Austausch statt. Der Betrieb kann Fehlermeldungen recht gut einschätzen und weiß, ob er den Entwickler sofort oder erst demnächst über die Meldung informiert.

Aber DevOps ist nicht in Unternehmen gegeben. Ja, teilweise ist DevOps sogar ein Unding und wird strikt verboten!
Wie das sein kann? Nun, DevOps erlaubt dem Entwickler Zugriff auf Produktivdaten, die in manchen Branchen unter strikten Zugriffsbeschränkungen liegen. Ich selbst durfte schon bei Banken und Behörden miterleben, wie sich diese Beschränkung im wahren Leben auswirkt. Und wehe, man muss einen Bug analyiseren, den ein Kunde im Produktivsystem hatte. Der Zugriff auf die Logs unterliegt schon höchsten Auflagen. Asterix‘ Passierschein A38 ist ein Kindergarten dagegen.

Okay, halten wir also fest: DevOps ist nicht überall gegeben und Entwicklung und Betrieb sind nicht nur zwei getrennte Teams, sondern IT-technisch getrennte Welten. Wie bekommt man es nun auf die Reihe, dass der Betrieb auch weiß, was er in welchen Fällen zu tun hat? Überlicherweiße über ein Handbuch.

Ja, mit der Übergabe des Softwareartefakts muss auch ein sogenanntes Betriebshandbuch übergeben werden. In diesem steht dann drin, was man in welcher Situation zu tun hat. Oh, was waren das für wunderbare Meetings! Alle Entwickler, in einen winzigen Meetingraum gepfercht, alle schreiben sie durcheinander, spinnen wilde Geschichten zusammen. „Wenn der Fehler X auftritt, dann muss Aktion Y durchgeführt werden!“ ruft der eine. „Aber bei Vollmond ist es Aktion Z!“ ruft der andere. „Wir dürfen die Opfergaben für den großen Compiler nicht vergessen! Jeden Dienstag!“ ruft der Alte. „Was ist eigentlich die Frozen Zone?“ fragt der Neue. Moment, Frozen Zone hat mit dem Thema nix am Hut!

Und so entsteht ein wunderbares Werk, spannender als so mancher Krimi und definitiv fiktiver als der Herr der Ringe.

Gerade in Unternehmen, die nicht mit DevOps fahren (können), erlebt man auch oft den Faktor „historisch gewachsen“. Und so wachsen auch diese Betriebshandbücher mit, wuchern in den Gezeiten der stetigen Änderung und sind somit zum Teil nützlich, zum Teil Altpapier. Wir kommen der Problemlösung gefühlt nicht wirklich näher.

Clean Code to the logging rescue!

Ein wunderbares Buch, das viele Entwickler als Pflichtlektüre bezeichnen, ist „Clean Code“ von Robert C. Martin. Unter anderem schreibt Martin in dem Buch, dass Kommentare überflüssig sind, wenn man seinen Methoden und Variablen ordentliche und aussagekräftige Namen gibt. Also anstelle die Variable var1 zu definieren und per Kommentar zu erklären, dass es sich um die Postleitzahl des Kunden handelt, so kann man die Variable ja auch gleich postleitzahlKunde nennen. Dann braucht es den Kommentar zur Erklärung auch nicht. Das merken wir uns jetzt mal.

Was in den letzten Jahren auch ein immer größeres Thema wurde, ist das Domain-Driven-WasAuchImmer. Design, Development, Architecture. Egal, Hauptsache Domain-Driven! Was heißt das aber genau? Wir sprechen im Büro-Alltag alle eine bestimmte Sprache. Ich meine damit nicht Deutsch oder Englisch, sondern die Unternehmenssprache. Jeder kennt es, Abkürzungen, Begriffe, Namen. Jedes Unternehmen hat sein eigenes Vokabular, das jemand von außerhalb nicht versteht, wohingegen jeder im Unternehmen sofort weiß, was gemeint ist. Damit man sich im Code besser zurechtfindet und neue Kollegen auch leichter reinkommen, soll man die Domain-Sprache auch im Code verwenden.
Um auf das Beispiel vom vorherigen Absatz zurückzukommen: „postleitzahlKunde“.
Sicher werden viele Leser instinktiv an „customerPostalcode“ gedacht haben, überlicherweise setzt sich ja die englische Sprache im Code durch. Was, wenn der Begriff „postleitzahlKunde“ aber Domain-Sprache ist? Dann wird das auch so, auf Deutsch, im Code verwendet. Und so entstehen diese wunderbaren Methodennamen á la „verifyPostleitzahlKundeIsSomething“. Herrlich!

Also, durch „Clean Code“ erhalten wir klare und aussagekräftige Namen und Bezeichnungen im Code und mittels der Domain-Sprache versteht auch jeder das Gleiche darunter. Der Entwickler, der von der „postleitzahlKunde“ schreibt, versteht darunter das Gleiche wie der Betriebler, wie der ProductOwner, Projektleiter, Vertriebler, Kundenberater. Cool!

Und trotzdem verwenden wir für unsere Log Level diese abstrakten Begriffe.

Domain-Driven Logging?

Warum? Warum verwenden wir im Logging nicht auch die Domain-Sprache? Warum muss ich einen kritischen Fehler immer nur auf „error“ loggen? Wäre es nicht viel sinniger, etwas aus der Domain-Sprache zu nehmen?

log.systemAboutToCrash("Do this or that to avoid it.");

log.customerOrderProcessFailed("Customer order was sent, but XYZ happend and now the data is corrupt.")

Beides sind kritische Fehler. Im ersten Fall steht der Ausfall einer Instanz bevor, was meine Systemverfügbarkeit gefährdet. Im zweiten Fall ist eine Kundenbestellung korrupt und kann nicht durchgeführt werden, was einen finanziellen Schaden verursachen kann. Der erste Fehler ist also ein kritischer „Technik“-Fehler, der zweite dagegen ein kritischer „Business“-Fehler. Beide sind kritisch, mehr haben sie aber nicht gemein.

Gerade erst gestern habe ich die Dokumentation zu einem Alamierungssystem gelesen, das ich im Kundenprojekt anbinden soll. Auch dieses arbeitet nur mit den abstrakten Log-Leveln und beschreibt diese mit einem kurzen Absatz. Nun ratet mal!
Die Log Level sind aus einem rein technischen Blickwinkel beschrieben!
Ein Business-Fehler ist daher nach der allgemeinen Formulierung „Alle anderen Probleme“ zu kategorisieren. „Minor“.
In diesem Projekt wäre ein Business-Fehler zum Beispiel, dass ein Prozess auf einem IBM-Host-System nicht gestartet werden konnte. Diese Prozesse führen kritische Aktionen für die Kunden meines Auftraggebers durch. Im Fehlerfall muss mit Strafen in Millionenhöhe gerechnet werden. Wenn nicht schlimmer. Und trotzdem wäre es nach der Dokumentation nur ein „minor“ Fehler.

Hier müssen wir nun individuell mit dem Team, welches das Alamierungssystem betreut, klären, welche Level was bewirken. Denn auch wir wollen nicht der Entwickler sein, der die Info auf Error loggt, weil er zu faul ist, seine Log-Level sauber zu setzen.
Nebenbei bemerkt: An diesem Alameriungssystem, von dem ich hier ständig schreibe, hängt eine Rufbereitschaft! Sollte ich also eine Warnung mit dem falschen Level an das System schicken, so wird jemand nachts aus dem Bett geklingelt. Das möchte ich doch tunlichst vermeiden.

Also, wie sieht denn nun die Lösung für das Problem aus?

log.wakeMeUpInTheMiddleOfTheNight("Hello World")

log.customerOrderFailed("...")

log.informationForTheNextMorning("Something happend. Nothing serious. But serious enough to be important")

Domain-Driven-Logging, DDL! Oh, Moment, DDL steht für Data Definition Language und kommt aus dem Bereich der Datenbanken. Nein, mit der Domain-Sprache wollten wir doch alle das Gleiche verstehen…
Domain-Driven-Log-Level, DDLL! Ja, das klingt gut! DDLL, laut Google sollte es da keine Verwechslungsgefahr geben! Okay, ich rufe hiermit DDLL ins Leben!
Und jetzt? Mir ist kein Logging-Framework bekannt, das so eine Funktion unterstützen würde und ich werde jetzt auch nicht anfangen, mein eigenes Logging-Framework zu schreiben!

Wrapping (!) it up

Ja, das ist nun ein doch etwas ernüchterndes Ende für diesen Blogpost. Aber leider sehe ich zum jetzigen Zeitpunkt nur eine wirklich praktikable Lösung, die auch nur halb-praktikabel ist: einen Wrapper. Man wrappt das Logging-Framework weg, verwendet im Code die Domain-Sprache und unten drunter doch nur wieder die abstrakten Level. Damit können wir im Code den „Domain-Driven“-Aspekt weiter ausbauen. Doch im Betrieb tauchen weiterhin nur „Warn“ und „Error“ und Co auf. Hier haben wir leider keine Besserung geschaffen.
Aber auch, wenn ich mit diesem Post keine richtige Lösung für das Problem bieten kann, so kann ich doch hoffentlich zum Diskutieren und Nachdenken anregen. Der Einzug der Domain-Sprache in die Welt des Loggings. Und wer weiß, vielleicht verirrt sich ja auch der eine oder andere Entwickler der gängingen Logging-Frameworks auf meinen Artikel und findet Anregung und Motivation in neuen Features. In Domain-Driven-Features. Es würde mich sehr freuen.