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.

Kontext

Kontext ins Log schreiben

Wie log4j die Informationen in das Log schreibt, ist in der der Konfiguration hinterlegt. Kommt das PatternLayout von log4j2 zum Einsatz, ist %X hinzuzufügen, damit das Tool den Inhalt des MDC bei jedem Eintrag mit ausgibt. Mit JSONLayout gibt es das MDC hingegen automatisch aus.

<PatternLayout pattern="%d{HH:mm:ss.SSS} %X %-5level ..."/>

Der neue Log-Eintrag, den der um den MDC erweiterte Code und die angepasste Log-Konfiguration erzeugen, sieht nun wie folgt aus:

08:39:42.969 {invoiceId=1} ... - can't load item ID 4711

Der Log-Eintrag enthält damit immer die dazugehörige Rechnungsnummer.

Automatisch mehr Kontextinformationen sammeln

Im vorangegangenen Beispiel wurde das Logging im fachlichen Code erweitert, Logging (wie Tracing) ist aber auch eine Querschnittsfunktion. In vielen Anwendungen gibt es für jede Verarbeitung einen Nutzer, eine Quell-IP-Adresse und gegebenenfalls eine URL, die der Nutzer aufgerufen hat.

In einer Java-EE-Umgebung lässt sich das als Servlet-Filter umsetzen. Beim Gebrauch der JAX-RS können Entwickler dafür Filter für eingehende und ausgehende Requests nutzen. Abhängig von den Informationen, die jede Log-Nachricht enthalten soll, könnte ein solcher Filter folgendermaßen aussehen (Pfeile zeigen lediglich aus Platzgründen umbrochene Zeilen an):

@Provider
public class RequestFilter implements ContainerRequestFilter {

    @Override
    public void filter(ContainerRequestContext containerRequestContext) {
        MDC.put("http.url", ↲
    containerRequestContext.getUriInfo().getAbsolutePath().toString());
        MDC.put("http.method", containerRequestContext.getMethod());
        Principal principal = ↲
    containerRequestContext.getSecurityContext().getUserPrincipal();
        if(principal != null) {
            MDC.put("user", principal.getName());
        } else {
            MDC.put("user", "anonymous");
        }
    }
}
@Provider
public class ResponseFilter implements ContainerResponseFilter {

    @Override
    public void filter(ContainerRequestContext containerRequestContext,
                       ContainerResponseContext ↲
                       containerResponseContext) {
        MDC.remove("http.url");
        MDC.remove("http.method");
        MDC.remove("user");
    }
}

Mit dem nachstehenden Filter lassen sich automatisch alle Log-Einträge erweitern, ohne dass eine Zeile des fachlichen Codes anzupassen ist:

08:52:54.276 {http.method=GET, ↲
http.url=http://localhost:8080/api/startBillingRun, ↲
invoiceId=1, user=Theo Tester} ↲
ERROR d.a.t.d.Invoice - can't load item ID 4711
 

Die zusätzlichen Informationen zeigen, dass die Fehlermeldung im Log wirklich zu dem Nutzer gehört, der das Ticket eröffnet hat.

Mit den bisher gesammelten Informationen lassen sich Log-Einträge einem Anwender zuordnen. Anhand des Zeitstempels können Auswerter mehrfache Versuche eines Nutzers identifizieren. Es bleibt jedoch unklar, welche Einträge zu einem Versuch gehören, wenn Letztere schnell aufeinander folgen. Außerdem fehlen Informationen, um Log-Einträge zu identifizieren, die zwar ein einzelner Request ausgelöst hat, den aber unterschiedliche, nachgelagerte Services beantwortet haben.

Das Dapper-Konzept – implementiert von Zipkin und Sleuth

Googles Dapper-Konzept beschreibt, wie Systeme Aufrufe innerhalb und zwischen Services nachverfolgen können: Trifft ein Aufruf beim ersten Service ein, bekommt er eine zufällig erzeugte Trace-ID. Ruft der einen anderen Service auf, erhält er zusätzlich eine neue Span-ID. Ein weiterer Aufruf eines anderen Services bekommt die gleiche Trace-ID aber eine andere, neu erzeugte Span-ID. Zusätzlich werden Start- und Endzeiten auf Client- und Serverseite mitprotokolliert – mehr dazu später.

Dapper ist ein von Google entwickeltes Werkzeug, dessen Konzept und Header zum Austausch von Trace- und Span-IDs mit anderen Diensten in einem wissenschaftlichen Artikel beschrieben sind. Zipkin implementiert einen zentralen Server, der die entsprechenden Informationen speichert, durchsucht und anzeigt. Außerdem enthält es Client-Bibliotheken, die die Daten von den Services zum zentralen Server transportieren. Zipkins historische Wurzeln sind bei Twitter, der komplette Quellcode ist als Open-Source-Projekt zusammen mit weiteren Bibliotheken heute Teil des OpenZipkin-Projekts.

Unterschiedliche Bibliotheken helfen, die Informationen innerhalb der Services zu sammeln. Die brave Libraries sind Teil des OpenZipkin-Projekts: Sie kapseln client- und serverseitige Java-Bibliotheken und kümmern sich um die anfallenden Trace-Informationen. Zusätzlich gibt es Bibliotheken für Go, JavaScript und andere Programmiersprachen. Wer Spring Boot benutzt, kann Spring Sleuth einbinden: Es instrumentiert viele Standardbibliotheken und sammelt die entsprechenden Trace-Informationen.

Die folgenden Beispiele nutzen Spring Boot. Spring Sleuth sammelt Trace-Informationen und Zipkin speichert, durchsucht und zeigt sie an.

Trace-Informationen weitergeben

Standardisierte HTTP-Header geben die Trace-Informationen an nachgelagerte Services weiter:

GET /api/callback HTTP/1.1
Host: localhost:8080
...
X-B3-SpanId: 34e628fc44c0cff1
X-B3-TraceId: a72f03509a36daae
...
 

Sleuth fügt sie ausgehenden Anfragen hinzu und liest sie bei eingehenden Anfragen aus. Es ergänzt sie zudem direkt im Mapped Diagnostic Context. Damit sieht der Log-Eintrag wie folgt aus:

09:20:05.840 {X-B3-SpanId=34e628fc44c0cff1,↲
 X-B3-TraceId=a72f03509a36daae, ...} ↲
ERROR d.a.t.d.Invoice - can't load item ID 4711
 

Die Einträge sind durch die Änderung besser durchsuchbar: Alle Einträge mit der gleichen Trace-ID gehören zur gleichen Nutzeranfrage – egal in welchem Service der Logger sie protokolliert hat.

Wenn es bei der Verarbeitung zu einem Fehler kommt, sollte die Trace-ID dem Nutzer in der Fehlermeldung ersichtlich sein. So ist sie für die Suche in den Logs bei der Analyse direkt verfügbar.

Zipkin Server und Tools

Funktionen des Zipkin-Servers

Aber der Zipkin-Server kann noch mehr: Er speichert die Trace- und Span-Informationen inklusive Timing-Daten zentral und erstellt gleichzeitig eine Übersicht über die Servicelandschaft. So lassen sich beispielsweise Einträge suchen, die Fehler produzierten oder besonders lange brauchten. Das System sammelt die Informationen separat von den eigentlichen Logs der Anwendungen. In Produktion wird in der Regel nur ein kleiner Prozentsatz dieser Daten erfasst, um unnötig große Sammlungen zu vermeiden.

Der Zipkin-Server besteht aus einem Web-Frontend, einer Serveranwendung und einem Backend, um die Daten zu speichern (entweder Cassandra, MySQL oder Elasticsearch). Das Web-Frontend stellt die Beziehung der Services untereinander dar und zeigt pro Request eine detaillierte serviceübergreifende Zeitleiste an

Traces enthalten automatisch querschnittliche Informationen wie den Servicename und die aufgerufene URL. Dafür ist kein fachlicher Code anzupassen. Sind mehr Informationen in den Traces gewünscht, können Entwickler den Traces im fachlichen Code Tags und Events hinzufügen. Die Daten sind dann für die Suche und die Anzeige in Zipkin verfügbar.

@Component
public class BillingResource {

    @Autowired
    private Tracer tracer;

    public String startBillingRun() {
        /* ... */
        Span span = tracer.getCurrentSpan();
        span.logEvent("log a line");
        tracer.addTag("invoiceId", String.valueOf(i.getId()));
        /* ... */
    }
}

Zipkin-Werkzeuge nicht nur für Entwickler

Ein Service erstellt immer dann eine neue Trace-ID, wenn der empfangene Request keine enthält. Den Umstand nutzt Chromes Zipkin Plugin: Es erzeugt die Trace-ID im Browser und schickt sie mit dem Request zum Server. So ist die ID im Vorhinein bekannt und das Plug-in kann für die Analyse direkt aus den Chrome-Entwicklerwerkzeugen in den passenden Trace im Zipkin-Web-Frontend verlinken. Eine aufwendige Suche entfällt. Außerdem setzt es den X-B3-Sampled-Header: Er stellt sicher, dass der Trace protokolliert wird und zum Zipkin-Server gelangt – unabhängig von der Anwendungskonfiguration. Sleuth leitet diesen Header auch an alle nachgelagerten Services weiter, sodass alle Abschnitte des Aufrufbaums protokolliert werden.

Dieses Vorgehen lässt sich nicht nur in den Entwicklungsumgebungen, sondern auch in Produktion nutzen, um einzelne Traces zu sammeln – insbesondere, wenn in Produktion aus Performancegründen normalerweise nur ein kleiner Prozentsatz gespeichert wird.

Ist das Plug-in aktiviert, sendet es die zusätzlichen HTTP-Header für alle Requests mit. Daher sollten es Entwickler ausschalten, wenn sie die Funktion nicht benötigen. Darüber hinaus ist es naheliegend, alle X-B3-*-HTTP-Header an der äußeren Firewall zu entfernen, um zu verhindern, dass jemand von außerhalb des Unternehmens die Header mitschickt und so unnötig oder mutwillig Logs- und Trace-Informationen generiert.

Per-Request-Debugging mit log4j2 and Zipkin

Mit den zusätzlichen HTTP-Headern lassen sich Trace-Informationen in Produktion sammeln, während Logs meist nur Warnungen und Fehler protokollieren. Log4j 2.x enthält eine Lösung dafür: Zipkin und Sleuth verarbeiten zusätzlich den Header X-B3-Flags, wobei der Wert 1 für "Debugging angestellt" steht. An diese Information kommen Anwender mit einem Filter analog zu dem für die Nutzerdaten aus dem anfänglichen Beispiel, dass sie im MDC mit dem Schlüssel X-B3-Flags-debug ablegt. Die folgende Konfiguration von DynamicThresholdFilter in log4j2.xml erwirkt das Anlegen von Log-Einträgen im Trace-Level für jeden Request, der mit dem X-B3-Flags-Header und dem Wert 1 an die Anwendung geschickt wurde.

<DynamicThresholdFilter key="X-B3-Flags-debug" onMatch="ACCEPT" 
defaultThreshold="warn" onMismatch="NEUTRAL">
    <KeyValuePair key="true" value="trace"/>
</DynamicThresholdFilter>

Das klappt jedoch erst ab log4j Version 2.7 zuverlässig: Frühere Varianten enthalten einen Fehler, der verhinderte, dass der Vorgang für Log-Meldungen mit Parametern funktionierte (vgl. Ticket LOG4J2-1511).

Fazit

Um Log-Einträge mit zusätzlichen Informationen anzureichern, beginnen Entwickler normalerweise mit einem Filter, der Informationen wie den Nutzernamen oder die aufgerufene URL in den MDC schreibt: Als querschnittliche Implementierung erweitert er alle Log-Einträge und benötigt keine zusätzlichen Bibliotheken im Projekt. Das funktioniert sowohl mit log4j in den Versionen 1 und 2 als auch gegebenenfalls mit anderen Logging-Implementierungen wie Logback.

In einer Architektur, in der ein Service einen anderen aufruft, ist das Umsetzen des Dapper-Konzepts naheliegend. Hierfür sind jedoch zusätzliche Bibliotheken notwendig. So werden die Log-Einträge um Trace-Informationen ergänzt, auch wenn zunächst kein Zipkin-Server zum Einsatz kommt, um sie zusammenzuführen. Ist Dapper implementiert, lassen sich Fehlermeldungen für Nutzer um Trace-IDs ergänzen. Das erleichtert die Fehlersuche in den Logs. Anschließend (und wenn ein Update auf log4j 2.7 oder neuer möglich ist) lässt sich das Per-Request-Debugging angehen.

Alle beschriebenen Maßnahmen helfen, mit den vorhandenen Logs schneller zu den Problemen vorstoßen zu können. Denn das nächste Ticket ist nicht weit.

Alexander Schwartz
arbeitet als Principal IT Consultant bei msg systems ag. Im Laufe der Zeit arbeitete er mit verschiedensten Server- und Web-Techniken. Er schätzt produktive Arbeitsumgebungen, agile Projekte und automatisierte Tests. Auf Konferenzen und bei User Groups spricht er über seine Erfahrungen. (jul)