Teil 1 von 1 aus der Serie "Things every developer should know"

Hin und wieder beobachte ich in Anwendungen Logverhalten, das kontraproduktiv ist: Überlange Logdateien auf Produktionssystemen, in denen Informationen stehen, die das produktive Arbeiten eher behindern als unterstützen. Grund genug, sich mit einer Selbstverständlichkeit, wie dem Loggen, etwas genauer auseinander zu setzen.

Dabei ist es sehr wichtig, sich auf die konsistente Verwendung der Loglevel im Team zu einigen. Am besten eignen sich hierzu in der Community bereits etablierte Verwendungen als Vorlage.
Im Folgenden möchte ich einige der relevanten Aspekte anhand referenzierter Artikel zum Thema zusammentragen.

Hierzu ziehe ich die folgenden lesenswerten Artikel zu Rate:

Gliederung der Log-Level

Eine weit verbreitete Gliederung der Loglevel hat die Log4j-API:

FATAL
The FATAL level designates very severe error events that will presumably lead the application to abort.

ERROR
The ERROR level designates error events that might still allow the application to continue running.

WARN
The WARN level designates potentially harmful situations.

INFO
The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.

DEBUG
The DEBUG Level designates fine-grained informational events that are most useful to debug an application.

TRACE
The TRACE Level designates finer-grained informational events than the DEBUG

In einigen Fällen gibt es noch den Level NOTICE, der zwischen INFO und DEBUG angesiedelt wird und im folgenden Einfachheit halber als Nuance des INFO Levels gewertet wird.

Fatality

Beim Loglevel FATAL sind sich fast alle Autoren einig: Demnach sollte der Level FATAL nur bei Fehlern eingesetzt werden, welche die Anwendung (oder zumindest Teile) komplett lahm legen, also einen GAU darstellen.

Cowan schreibt hierzu:

The app (or at the very least a thread) is about to die horribly. This is where the info explaining why that’s happening goes.

Masterzen:

Too bad it’s doomsday. Use this very scarcely, this shouldn’t happen a lot in a real program. Usually logging at this level signifies the end of the program. For instance, if a network daemon can’t bind a network socket, log at this level and exit is the only sensible thing to do.

Twist:

Fatal is reserved for special exceptions/conditions where it is imperative that you can quickly pick out these events. I normally wouldn’t expect Fatal to be used early in an application’s development. It’s usually only with experience I can identify situations worthy of the FATAL moniker experience do specific events become worth of promotion to Fatal. After all, an error’s an error.

Fehler sind menschlich

Den ERROR-Level ordnet Cowan kritischen Fehlern zu, die nicht passieren sollten, wie Netzwerkfehler, aber keine von der Anwendung bereits erwarteten oder behandelten Fehler sind (wie fehlerhafte Eingaben):

Something that the app’s doing that it shouldn’t. This isn’t a user error (‚invalid search query‘); it’s an assertion failure, network problem, etc etc., probably one that is going to abort the current operation

Für den ERROR-Level definiert Masterzen zusätzlich eine Gruppe von Fehlern, die aus extern Schnittstellen kommen können:

Log every error conditions at this level. That can be API calls that return errors or internal error conditions.

Twist schlägt den ERROR Level als eine Art Standardausgabe für jegliche unbehandelten Ausnahmen vor:

Error is used to log all unhandled exceptions. This is typically logged inside a catch block at the boundary of your application.

Meiner Meinung nach lassen sich hieraus folgende Kriterien für den ERROR Level ableiten:

  • Unbehandelte Fehler (sollten behoben werden)
  • Fehler zur Verfügbarkeit relevanten Ressourcen (Netzwerk, Datenbank)
  • Fehler externer Schnittstellen
  • Dinge, welche die Anwendung nicht machen sollte
  • Fehler, welche den Betrieb der Anwendung gefährden oder stoppen

Alerta

Cowan sieht im WARN Level Ereignisse, die sich zu Fehlern entwickeln könnten, insbesondere knapp werdende Ressourcen.

something that’s concerning but not causing the operation to abort; # of connections in the DB pool getting low, an unusual-but-expected timeout in an operation, etc. I often think of ‚WARN‘ as something that’s useful in aggregate; e.g. grep, group, and count them to get a picture of what’s affecting the system health

Masterzen verweist zusätzlich auf die Funktion des WARN Levels als Vorbote von Fehlern des ERROR Levels:

Log at this level all event that could potentially become an error. For instance if one database call took more than a predefined time, or if a in memory cache is near capacity. This will allow proper automated alerting, and during troubleshooting will allow to better understand how the system was behaving before the failure.

Twist ergänzt die Nutzen mit dem einmaligen Gebrauch während des Applikationsstarts bei fehlenden Konfigurationen, welche durch Standardeinstellungen belegt werden.

Warning is often used for handled ‚exceptions‘ or other important log events. For example, if your application requires a configuration setting but has a default in case the setting is missing, then the Warning level should be used to log the missing configuration setting.

Hieraus leitet sich folgende Zusammenfassung für den WARN Level ab:

  • Fehler, welche den Betrieb der Anwendung gefährden
  • Resourcen werden knapp
  • Alles, was sich zu einem relevanten Fehler entwickeln könnte
  • Hilfsmittel bei der Analyse von schwerwiegenderen Fehlern
  • Nicht gemachte Konfigurationen (bei denen nun Defaultwerte greifen)

Info

Cowan fasst den Info Level sehr schön und kompakt zusammen:

Normal logging that’s part of the normal operation of the app; diagnostic stuff so you can go back and say ‚how often did this broad-level operation happen?‘, or ‚how did the user’s data get into this state?‘

Masterzen weist zusätzlich darauf hin, dass üblicherweise Anwendungen mit dem Default-Loglevel INFO gestartet werden. Ein wichtiger Hinweis, denn entsprechend macht es natürlich Sinn, die Ausgaben so anzupassen, dass Details, wie Methodenaufrufe, nicht in den Standardlogausgaben landen.

log at this level all actions that are user-driven, or system specific (ie regularly scheduled operations…)

NOTICE level: this will certainly be the level at which the program will run when in production. Log at this level all the notable event that are not considered an error.

Aus Twists Ausführungen lässt sich für die Level TRACE, DEBUG und INFO auch eine Abstraktionshierarchie ableiten, bei welcher der Ein- und Austritt in funktionale Blöcke erfasst wird. Im Falle INFO wäre das eine hohe Abstraktionsebene, wie Module, Komponenten oder Systemteile.

The Information level is typically used to output information that is useful to the running and management of your system. Information would also be the level used to log Entry and Exit points in key areas of your application. However, you may choose to add more entry and exit points at Debug level for more granularity during development and testing.

Daraus ergibt sich folgende Zusammenfassung für den INFO Level:

  • Statusmeldungen bei langen Operationen oder Batch-Prozessen
  • Ein- / Austritt aus Modulen (Hierarchisches Loggen)

Entmotten

Der DEBUG-Level, auch hier sind sich alle Autoren einig, ist nur für den Gebrauch auf den Entwicklungssystemen gedacht und soll beim Finden von Fehlern helfen.
Er ist standardmäßig nicht aktiv und sollte laut Masterzen und Twist sogar aus dem Code entfernt werden, bevor dieser auf ein produktives System ausgerollt wird.

Cowan:

Off by default, able to be turned on for debugging specific unexpected problems. This is where you might log detailed information about key method parameters or other information that is useful for finding likely problems in specific ‚problematic‘ areas of the code.

Masterzen

log at this level about anything that happens in the program. This is mostly used during debugging, and I’d advocate trimming down the number of debug statement before entering the production stage, so that only the most meaningful entries are left, and can be activated during troubleshooting.

Twist

This is the most verbose logging level (maximum volume setting). I usually consider Debug to be out-of-bounds for a production system and used it only for development and testing. I prefer to aim to get my logging levels just right so I have just enough information and endeavour to log this at the Information level or above.

Für den DEBUG-Level gilt dann folgende Zusammenfassung:

  • Ein-/Austritt aus fein granularen Modulen oder Methoden (Hierarchisches Loggen)
  • Nutzung beim Debuggen zum Eingrenzen von Fehlern auf einzelne Zeilen oder Methoden
  • Einzelne Ressourcenzugriffe (Datei, SQL)

Spuren

Der TRACE-Level wird analog zum DEBUG-Level eingesetzt, ist jedoch noch fein granularer. An dieser Stelle wird wirklich jede generierte Kommunikation, Variable und weitere Zustände genauestens protokolliert.
Obwohl Masterzen meint, dass TRACE-Loganweisungen nie in ein Versionssystem eingecheckt werden sollten, ist dieser Level durchaus auch relevant in GA-Versionen.
Diverse male habe ich persönlich Gebrauch von den TRACE-Leveln in den Apache HTTP Components gemacht, und war froh, mir die Request- und Responsedaten en Detail anschauen zu können.
Auch die Hibernate-API erlaubt es über den TRACE-Level die Zuweisung von einzelnen Werten an Prepared- und Named-Queries auszugeben.

Cowan:

„Seriously, WTF is going on here?!?! I need to log every single statement I execute to find this @#$@ing memory corruption bug before I go insane“

Masterzen:

this is a code smell if used in production. This should be used during development to track bugs, but never committed to your VCS.

Twist führt diesen Level nicht mehr auf, da er auch als eine Nuance des DEBUG-Levels aufgefasst werden kann.

Zusammengefasst ergibt sich für den TRACE-Level:

  • Ein- / Austritt aus Methoden und einzelne Codezeilen (Hierarchisches Loggen)
  • Nutzung beim Debuggen zum Eingrenzen von Fehlern auf einzelne Zeilen oder Methoden
  • Detaillierte Inhalte bei Ressourcenzugriffen (Datei- / Streaminhalte, SQL Eingangs- und Rückgabeparameter)

Die 10 Gebote des Loggens

Darüber hinaus hat Masterzen in seinem Artikel weitere brauchbare Tipps rund um das Loggen. Besonders interessant: Die Gebote 6 und 7.

Gebot 6 beschreibt die oft mangelnde Kontextinformation bei Logmeldungen. So sollte bei Loginformationen rund um Transaktionen, Benutzer oder andere Geschäftsobjekte immer der Kontext (welcher Benutzer, welches Objekt, in welchem Zusammenhang) mitgeloggt werden. Dies gilt auch für Exceptions. (In diesem Zusammenhang lohnt es sich auch die Artikel „An Exception Handling Framework for J2EE Applications“ von ShriKant Vashishtha und „Exception management and error tracking in J2EE“ von Kåre Kjelstrøm and Jens Schjærff Byager über das Behandeln von Exceptions innerhalb einer Anwendung durch zu lesen.)

Gebot 7 regt an, seine Logmeldungen derart zu formulieren, dass sie maschinell lesbar sind und später einfacher maschinell verarbeitet (daher geparst) werden können.

Schreibe einen Kommentar

Deine E-Mail-Adresse wird nicht veröffentlicht. Erforderliche Felder sind mit * markiert.