Best Practices und Anti-Pattern beim Logging in Java und anderen Sprachen
Logging ist ein wichtiges Instrument, aber es ist nicht einfach, das richtige Maß der zu protokollierenden Informationen zu finden.
- Hendrik Ebbers
Ein Thema, mit dem sich früher oder später jeder (Java-)Developer auseinandersetzen muss, ist Logging. Während bei kleinen Beispielprogrammen, dem Lernen der Programmiersprache oder dem schnellen Debuggen von Code ein System.out.println ausreichen mag, ist das für den Produktivbetrieb einer Software ein ganz klares No-Go. An dieser Stelle muss der Output einer Anwendung gewissen Qualitätsmerkmalen genügen, damit er zur Überprüfung, Überwachung und Analyse der Anwendung genutzt werden kann. Aus diesem Grund gibt es eine ganze Fülle an Logging-Frameworks und APIs, und für Entwickler ist es hier oft nicht leicht zu Entscheiden welche Strategie hier die richtige ist.
Aus diesem Grund habe ich mich dazu entschlossen, eine Reihe an Best-Practice-Beiträgen zum Thema Logging zu schreiben. In diesem Beitrag starte ich mit den generellen Grundlagen von Logging. In naher Zukunft wird nicht nur eine Übersicht der verschiedenen Logging-Frameworks im Java Ökosystem geben, sondern auch ein Einblick, wie man das Thema Logging in großen Softwarearchitekturen betrachten muss. Abgerundet wird das Themenpaket Logging mit einem Einblick in "Centralized Logging" und moderne Tools, die eine bessere Aufbewahrung und Analyse von Logging erlauben.
Logbuch des Captain, Sternzeit irgendwann um 2022
Wie manche bereits bei der Überschrift ahnen können, möchte ich einmal kurz über die wirklich grundlegende Dokumentation von Logging sprechen. Denn der Begriff hängt tatsächlich mit dem Logbuch aus der Seefahrt zusammen. Das Logbuch soll generell dazu dienen, Ereignisse aufzuschreiben, die während einer Seefahrt passieren. Und genau das machen wir mit Logging in einer Anwendung auch: Wir schreiben zu bestimmten Ereignissen während der Lebenspanne der Anwendung Nachrichten nieder. Ob diese nun technisch in eine Log-Datei geschrieben oder nur auf der Konsole ausgegeben werden, lassen wir einmal außen vor. Wichtig ist allerdings, dass alle diese Nachrichten Metadaten wie beispielsweise den Zeitpunkt des festzuhaltenden Ereignisses beinhalten.
Genau wie in der Seefahrt gibt es verschiedene sehr gute Gründe, warum man in einer Anwendung auf Logging setzen sollte. Anhand der Historie in einem gut gepflegten Log kann man erkennen, warum bestimmte Ereignisse ausgelöst wurden. Das ist in der IT vor allem sinnvoll, um zu erkennen, wie es zu Fehlern während der Laufzeit einer Anwendung kam. Aber nicht nur in diesen Problemfällen kann Logging hilfreich sein. Generell kann man sagen, dass man aus Logging Informationen über die Nutzung und den Ablauf der Software erfährt. Hierdurch kann man aus der Vergangenheit der Software für zukünftige Integrationen lernen. Wenn man im Logging beispielsweise erkennt, dass 97 % aller Benutzer den "Like"-Button unserer Software erst nach längerer Nutzung betätigen, kann man sich überlegen, ob dieser prominenter in der Software platziert werden muss.
Um die genannten Vorteile aus dem Logging einer Anwendung ziehen zu können, muss es allerdings auch sinnvoll in die Anwendung eingebunden sein. Um dies etwas zu konkretisieren, schauen wir uns im folgenden einmal generelle Best Practices und Anti Pattern beim Logging an.
Was soll ich wann und wie loggen?
Um besser zu verstehen, wie wir Logging konkret in unserer Anwendung nutzen sollten, ist es sinnvoll, sich genau zu überlegen, was im Idealfall über einen Logger ausgegeben werden soll. Hier sehe ich drei verschiedene Kategorien, die eigentlich immer geloggt werden sollten:
- Wichtige Ereignisse innerhalb der Anwendung (z.B. Start der Anwendung oder Ablauf eines zyklischen Jobs),
- Informationen, die von außerhalb kommen (z.B. Import von Daten über eine REST-Schnittstelle),
- Unerwartetes beziehungsweise fehlerhaftes Verhalten der Anwendung (z.B. beim fehlerhaften Einlesen einer Datei).
Aber auch bei diesen Kategorien sollte man es mit dem Logging nicht übertreiben. Hier muss man aufpassen, dass man Informationen nicht in einem Loop loggt. Auch wenn Nutzereingaben als Input von außerhalb gelten, sollte man nicht jeden Tastendruck direkt loggen. Das folgende Beispiel zeigt einen Auszug aus einem problematischen Log-Verlauf, in dem genau das passiert ist:
08:34:23 User mutates id field with new value 'J'
08:34:23 User mutates id field with new value 'JA'
08:34:23 User mutates id field with new value 'JAV'
08:34:23 User mutates id field with new value 'JAVA'
Man kann sich gut vorstellen, wie schwierig es wird, wichtige Informationen aus einer Log-Datei mit solchen Einträgen zu extrahieren.
Ähnlich verhält es sich mit Log-Nachrichten, die zu viele Informationen enthalten. Auch wenn wir wissen, an welchem Tag ein User Geburtstag hat, müssen wir diese Informationen nicht in unsere Log-Nachrichten unterbringen:
08:34:23 User 'Max' with birthday '01/01/1970' \
mutates id field with new value 'JAVA'
Während der Benutzername in der Nachricht sicherlich für eine spätere Analyse interessant sein kann, um diese Nachricht in Relation zu anderen Log-Einträgen zu bringen, so ist das Geburtsdatum eher störend und macht das Lesen der Nachrichten für das menschliche Auge nur komplizierter.
Ein dritter wichtiger Punkt, den man beim Erstellen von Log-Nachrichten immer im Hinterkopf haben sollte, ist die Datensensibilität. Während wir in den bisherigen Meldungen immer die Änderung einer ID im Log gesehen haben, sollte folgende Nachricht nie in einem Log-File auftauchen:
08:34:23 User 'Max' mutates password with new value '12#Agj!j7
In diesem Fall würde das Logging eine echte Sicherheitslücke der Anwendung darstellen. Solche sensitiven Daten wie das Nutzerpasswort dürfen selbstverständlich nie in Log-Nachrichten ersichtlich sein.
Basierend auf den bisherigen Erkenntnissen sehen folgende Log-Nachrichten sinnvoll und gut aus:
08:34:23 User 'Max' mutates id field with new value 'JAVA'
08:34:23 User 'Max' mutates password
Neben diesen Tipps sollte man auch immer schauen, dass man den Sourcecode einer Anwendung nicht so sehr mit Log-Aufrufen vollstopft, dass der Sourcecode am Ende nicht mehr sinnvoll zu lesen und verstehen ist. Folgender Ausschnitt aus einem Java-Programm zeigt, was passiert, wenn man es mit den Logging-Aufrufen übertreibt:
LOG.log("We start the transaction");
manager.beginTransaction();
LOG.log("DB query will be executed");
LOG.log("DB query: select * from users");
long start = now();
users = manager.query("select * from users");
LOG.log("DB query executed");
LOG.log("DB query executed in " + (now() - start) + " ms");
LOG.log("Found " + users.size() + " entities");
manager.endTransaction();
LOG.log("Transaction done");Hier ist der Code und dessen genaue Funktion kaum zu erkennen. Fehlen die Logging-Aufrufe schaffen wir das aber auf einen einzigen Blick:
manager.beginTransaction();
users = manager.query("select * from users");
manager.endTransaction();Nun soll man aber natürlich nicht das gesamte Logging außen vor lassen, und vielleicht ist genau dies eine Stelle, bei der man gerne viele Informationen im Logging sehen möchte. In diesem Fall muss man die Logging-Aufrufe geschickter in die Struktur und die API der Anwendung integrieren. Alle Informationen, die wir im ersten Beispiel gesehen haben, könnten auch direkt innerhalb der beginTransaction-, query- und endTransaction-Methoden geloggt werden. So wird die Business-Logik von den Logging-Aufrufen gesäubert und wir bekommen trotzdem alle Informationen.
Sollte es aus verschiedenen Gründen nicht möglich sein, dass Logging direkt in der API unterzubringen, kann man auch Komplexität in Verbindung mit Logging relativ einfach in wiederverwendbaren Lambdas oder Methoden "verstecken". Das folgende Beispiel zeigt eine generische Funktion, die eine Query innerhalb einer Transaktion ausführt und alle benötigten Informationen weiterhin als Log-Nachrichten weitergibt.
final Function<String, T> queryInTransaction = query -> {
LOG.log("We start the transaction");
manager.beginTransaction();
LOG.log("DB query: " + query);
long start = now();
T result = manager.query(query);
LOG.log("DB query found " + result.size() + " entities in "
+ (now() - start) + " ms");
manager.endTransaction();
LOG.log("Transaction done");
return result;
}Das führt dazu, dass wir in der Business-Logik unsere Aufrufe in einer lesbaren Form mit maximalem Logging aufrufen können:
LOG.log("Loading all users from database");
users = queryInTransaction("select * from users");Jedem, der schon einmal mit Logging-Frameworks gearbeitet hat, fehlt in den bisherigen Beispielen sicherlich das Logging-Level als wichtiges und zentrales Element. Dieses wollen wir uns zum Abschluss einmal genauer anschauen. Auch wenn unterschiedliche Logger nicht immer die gleichen Level definieren, haben doch alle die gleiche Funktionalität: auf einer eindimensionalen Skala wird durch das Level angegeben, wie wichtig die Nachricht im Kontext aller Nachrichten ist.
Wie beispielhaft im Bild gezeigt, gehen wir einmal davon aus, dass wir in unserem Logging drei verschiedene Level nutzen können (Anmerkung: Je nach konkretem Logging-Framework gibt es einige mehr). Im Level ERROR wollen wir alles fehlerhafte Verhalten der Anwendung loggen, während wir den Level INFO für generelle Informationen über den Ablauf und Status der Anwendung nutzen. Mit dem DEBUG-Level loggen wir Detailinformationen, die nur in Ausnahmefällen wichtig sind. Java-Quellcode der die verschiedenen Level im Logging einsetzt, könnte somit wie folgt aussehen:
try {
LOG.info("Loading all users from database");
users = query("select * from users");
LOG.debug("Found " + users.size() + " users in db");
} catch (Exception e) {
LOG.error("Error while loading all users");
}Zur Laufzeit der Anwendung kann man das Level des Loggers nun konfigurieren und somit filtern, welche Nachrichten wirklich im Log landen sollen. In der Regel filtert man hier die Nachricht im DEBUG-Level heraus und nimmt diese nur bei Fehleranalysen oder ähnlichen Szenarien in das Log mit auf. Der Vorteil ist, dass man den Sourcecode der Anwendung nicht ändern muss, um mehr Informationen zu erhalten. Nur die Konfiguration muss angepasst werden, und das kann je nach genutztem Logging-Framework sogar dynamisch zur Laufzeit passieren. Zusätzlich lässt sich eine solche Filterung auch nutzen, um unterschiedliche Informationen in einem Test- beziehungsweise Produktivsystem zu loggen.
Ein finales Logging-Konzept
Basierend auf den in diesem Blog-Post aufgezeigten generellen Regeln lassen sich bereits Definitionen für das Logging einer Anwendung oder einer kompletten Systemlandschaft erarbeiten. Wichtige Fragen, die man sich beim Erstellen von Regeln zum Logging stellen sollte, sind unter anderem:
- Wer wird das Log-File lesen?
- Was möchte man aus den Logs erfahren / extrahieren?
- Was möchte man NICHT aus den Logs extrahieren?
- Soll es Unterschiede im Logging in verschiedenen Umgebungen (Test / Produktion) geben?
Wie beschrieben, gibt es verschiedene Punkte, die beim Logging zu beachten sind. Generell ist es sinnvoll, ein Konzept zum Umgang mit Logging zu definieren. Hier kann man Richtlinien und Best Practices zum internen Umgang mit Logging definieren und festhalten. In ein solches Konzept gehören auch technische Aspekte wie präferierte Libraries oder Pattern. Diese werden wir uns im nächsten Teil der Reihe zu Java-Logging genauer anschauen.
(rme)
