Logging und Tracing mit Kontextinformation für Java-Entwickler

Inhaltsverzeichnis

Software durchläuft vor der Produktionsaufnahme viele Reviews und Teststufen. Trotzdem geschieht es, dass im Betrieb Fehler oder Auffälligkeiten auftreten, die das Entwicklungsteam untersuchen muss. Der erste Schritt ist immer, zu verstehen, was gerade unter welchen Rahmenbedingungen passiert ist.

Ausgangspunkt für diesen Artikel dient ein Fehlerticket: Der Nutzer – in diesem Fall Theo – beschreibt, dass er keine Rechnungen drucken konnte. Die Suche beginnt im Log des Servers. Der erste Eintrag lautet:

07:26:00.595 d.a.t.d.Invoice ERROR - can't load item ID 4711

Als erster Hinweis dient die Kennung der Rechnungsposition 4711. Allerdings hilft das nur wenig, wenn eine Rechnung immer mehrere Positionen hat und 4711 häufig vorkommt. Wie ließe sich der folgende Code verbessern, sodass er mehr Hinweise für die Analyse des Logs liefert?

for (Invoice i : invoiceRepository.findAll()) {
    i.calculateTotal();
}

Zumindest die Rechnungsnummer und ein paar Informationen zum Nutzer wären hilfreich. Die folgenden Beispiele zeigen, wie das funktioniert. Der zugehörige Code steht auf GitHub zur Verfügung.

Logging mit log4j

Version 1.2 des log4j-Logging-Frameworks erschien 2002 und wurde erst 2015 offiziell abgekündigt – eine sehr lange Zeit in der Softwareentwicklung. Version 2.0 wurde im Juli 2014 veröffentlicht und Version 2.7 ist seit Oktober 2016 verfügbar. Die Chance, dass ein Java-Entwickler bereits mit log4j gearbeitet hat, ist daher groß. Einige der Funktionen, die der Artikel beschreibt, sind mit Version 1.2 nutzbar, für alle anderen gibt es einen entsprechenden Hinweis.

Es gibt zwei Möglichkeiten, log4j Kontextinformationen mitzugeben: den Mapped Diagnostic Context (MDC) und den Nested Diagnostic Context (NDC). Sie verhalten sich wie eine Map, die Werte anhand von Schlüsseln, und ein Stack, der Werte in einer bestimmten Reihenfolge ablegt. Beide speichern diese Informationen für den aktuellen Thread und fügen sie jedem Log-Statement, das in der Folge geschrieben wird, hinzu. Je nach verwendetem Framework werden die Kontextinformationen gegebenenfalls auch an asynchron gestartete Aufgaben weitergegeben. In den folgenden Beispielen werden Informationen mit Schlüsseln unabhängig von einer Reihenfolge gesetzt, daher wird MDC benutzt. Wenn die Werte eine Hierarchie darstellen würden, wäre NDC das Richtige.

Beim Rechnungsproblem eben wäre die Rechnungsnummer hilfreich gewesen. Die folgende Funktion fügt sie daher dem MDC hinzu.

for (Invoice i : repository.findAll()) {
    MDC.put("invoiceId", Long.toString(i.getId()));
    try {
        i.calculateTotal();
    } finally {
        MDC.remove("invoiceId");
    }
}

MDC und NDC nehmen beliebige Werte als Strings entgegen. Nach dem Verarbeiten muss das Programm den Wert wieder entfernen, da er sonst im Kontext des Threads verbleiben würde – egal was dieser als nächstes verarbeitet.

Die Syntax von log4j 2.x für MDC ermöglicht ein try-with-resources-Konstrukt. Der folgende Code führt in der 2.x-Serie zum gleichen Ergebnis wie oben:

for (Invoice i : repository.findAll())
    try (final CloseableThreadContext.Instance c
            = CloseableThreadContext
              .put("invoiceId", String.valueOf(i.getId()))) {
        i.calculateTotal();
    }
}

Wer Version 2 verwendet, aber trotzdem die alte Syntax für MDC verwenden möchte, kann slf4j als Logging-Fassade nutzen.