Wer kennt sie nicht: 40 MB große Log-Dateien (pro Tag) voller Müll? Und das von Systemen, die im normalen Betriebsmodus arbeiten? Ich möchte dem geneigten Leser mit diesem Artikel eine Vorstellung vermitteln, welches Level für Log-Nachrichten das richtige ist.
Die gängigen Log-Level
Schauen wir uns kurz die gängigen Log-Level an, um einen Überblick zu erhalten. Dabei unterscheiden wir nicht zwischen Log-Systemen und -Fassaden, denn relevant ist die API, die vom Entwickler verwendet wird.
| java.util.logging.* | log4j | Apache Commons Logging | SLF4J | LOGBack | |
| Level | FINEST | TRACE | TRACE | TRACE | TRACE |
| FINER | |||||
| FINE | DEBUG | DEBUG | DEBUG | DEBUG | |
| CONFIG | INFO | INFO | INFO | INFO | |
| INFO | |||||
| WARNING | WARN | WARN | WARN | WARN | |
| SEVERE | ERROR | ERROR | ERROR | ERROR | |
| FATAL | FATAL |
Die Übersicht macht eines deutlich: Alle Entwickler sind sich im Großen und Ganzen einig, dass es mindestens fünf verschiedene Kategorien von Nachrichten gibt. Es gibt Fehler, Warnungen, generelle Informationen, Informationen zur Fehleranalyse und noch welche zum Nachvollziehen von Programmflüssen. Ja, der eine oder andere nimmt es etwas genauer und bei wieder anderen kann man eigene Level definieren, die irgendwo zwischen den Meta-Leveln „ALL“ und „OFF“ liegen, doch im Prinzip sind alle Log-Level, bis auf die fünf gängigen, Quatsch.
Aber wie findet man jetzt das passende Level zu einer Nachricht? Die Antwort ist recht simpel: Mit gesundem Menschenverstand.
Wofür sind die Log-Levels?
ERROR
Wie der Name schon sagt, sollten in desem Level Fehler protokolliert werden – egal welcher Art. Technisch also mindestens die Throwable-Subklassen-RuntimeException und Exception, jedoch nicht Error (denn Error zählt zu „Lass das Programm besser abstürzen, das ist sicherer“). Aber grundsätzlich einen Fehler zu protokollieren, wenn man ihn gerade in der Hand hat, ist zu pauschal. Ein gutes Negativbeispiel ist die org.hibernate.LazyInitializationException, wo im Konstruktor im ERROR-Level protokolliert wird. Das wurde zwar inzwischen auf TRACE reduziert, gehört dort aber schlichtweg nicht rein. Auch ist es falsch, einen Fehler zu protokollieren und, ggf. verpackt, weiterzuwerfen – ein wohlbekanntes Anti-Pattern. Das Resultat ist ein Fehler, der zweimal protokolliert wird, nur beim zweiten Mal unter Umständen als Cause. Und wenn man einen Fehler vollständig behandeln kann, ist es nicht notwendig, ihn unter ERROR zu protokollieren, DEBUG ist da sinnvoller.
Ach ja, wenn man schon dabei ist, einen Fehler zu protokollieren, sollten alle Informationen enthalten sein, die Aufschluss über die Ursache geben könnten. Quellen sind ein guter Anfang (URLs, URIs, Dateipfade, Primär- oder Alternativschlüssel, etc.).
Und eine sprechende Nachricht sollte ebenfalls enthalten sein. Also nicht
LOG.error(e)
sondern
LOG.error(„Fehler beim Ermitteln der notwendigen Daten zur Berechnung der Konditionen [...]“, e)
WARN
Alles, was zu Fehlern im weiteren Programmfluss führen kann, aber nicht muss, kann unter WARN eingestuft werden. Ist z.B. eine Konfiguration unvollständig oder falsch bzw. fehlerhaft und man fällt auf ein Standardverhalten zurück, könnte man dies unter WARN melden. Sachverhalte, die die Ausführungsgeschwindigkeit reduzieren oder den Speicherverbrauch unnötig erhöhen, oder Komponenten, die nicht für den Produktiveinsatz gedacht sind, kann man auch gut und gerne als WARN mitteilen.
INFO
Ab hier wird es unscharf, denn letztendlich sind doch alles nur Informationen. Eine gute Faustregel ist hier: Weniger ist mehr. Das heißt nicht, dass man nicht protokollieren soll, sondern dass man sich über die Einstufung besonders gut Gedanken machen sollte, wann immer man im Begriff ist, zum Level INFO zu greifen.
Z.B. ist es durchaus interessant, in auf welchen Netzwerkschnittstellen ein Applikationsserver gebunden ist, aber einmal konfiguriert, interessiert einen diese Information nicht wieder.
DEBUG
Auch hier sagt der Name schon sehr viel über den Zweck aus. DEBUG dient der Analyse von Sachverhalten, zumeist Fehlern/Bugs, und daher protokolliert man prinzipiell alle Parameter, die der Nachvollziehbarkeit von Ergebnissen dienen (Vorsicht bei sensiblen Daten wie z.B. Passwörtern). Übrigens: Parameter können an dieser Stelle ganz wörtlich Funktions-/Methodenparameter oder Zwischenstände in Funktion/Methoden sein. Wichtig ist, dass sie aufschlussreich sind.
Bei DEBUG ist Vorsicht geboten: Methoden, die häufig aufgerufen werden und viel protollieren, können Log-Dateien unnötig aufblähen. Eine naheliegende Maßnahme könnte sein, das Log-Level nur für bestimmte Kategorien auf DEBUG zu setzen.
Tipp: Wer viel Wert auf die Geschwindigkeit seiner Applikation legt und viele DEBUG-Log-Statements schreibt (was grundsätzlich empfehlenswert ist), der sollte auf den +-Operator für Strings verzichten. Also nicht
LOG.debug(„Starte Berechnung der Konditionen mit Kunde#“ + kunde.getId() + „ und Vertrag#“ + vertrag.getId())
sondern
LOG.debug(„Starte Berechnung der Konditionen mit Kunde#{0} und Vertrag#{1}“, kunde.getId(), vertrag.getId())
Der Unterschied ist hier nur marginal, kann aber in Hochleistungssystemen ein (Geschwindigkeits-)Gewinn sein. Bei der ersten Variante wird die Nachricht mit String.concat (heutzutage mit StringBuilder) zusammengesetzt und dem Logger übergeben. Dieser prüft dann, ob im Level DEBUG überhaupt protokolliert wird. Ist das momentan nicht der Fall, war das Zusammensetzen unnötig, kostete aber dennoch Rechenzeit und Speicher. Bei der zweiten Variante werden dem Logger die Nachricht und ihre Parameter einzeln übergeben. Erst nach der Prüfung, ob momentan im relevanten Level protokolliert wird, wird die Nachricht zusammengesetzt. Als Gratiszugabe ist es lesbarer.
TRACE
TRACE kann man mit Brotkrumen vergleichen. Wann eine Methode betreten und/oder verlassen wird, ggf. welche Verzweigungen sie nimmt, wann eine Exception geworfen und/oder gefangen wird, wie lange ein Aufruf dauerte – all dies sind Informationen, die im Level TRACE zu protokollieren sind.
Hier ist es noch wichtiger als bei DEBUG, die Ausgabe einzuschränken, denn sonst werden aus den oben genannten 40 MB auch gut und gerne mal 40.000 MB.
Schlusswort
Logging im richtigen Level ist leider keine exakte Wissenschaft, aber mit etwas Gehirnschmalz (viel muss es wirklich nicht sein) kann man mit dem Standard-Log-Level-Schwellwert INFO saubere Log-Dateien erhalten, die schnell und zielgerichtet durchsucht werden können.
Und noch etwas: Die hier beschriebene Philosophie ist längst nicht für jeden selbstverständlich, und so findet man sich häufig in der Situation, dass man für Bibliotheken von Drittanbietern den Standard-Log-Level-Schwellwert auf WARN oder gar ERROR erhöht. Natürlich sollte sich eine solche Anpassung nur auf die Oberkategorie(n) von eben solchen Bibliotheken beziehen.
