Loggen mit Struktur

Log-Server bieten weit mehr als eine Volltextsuche über textuelle Log-Meldungen an. Sie sind komplette Datenbanksysteme mit komplexen Auswertemöglichkeiten. Wenn Log-Meldungen passend zu den Datenbankfähigkeiten erstellt werden, ergeben sich neue Möglichkeiten im Umgang mit Log-Daten.

Java-Log-Bibliotheken zum effizienten Schreiben von Log-Meldungen gibt es seit über 20 Jahren. Ursprünglich dienten sie als Hilfe beim Debuggen während der Entwicklung und zur Diagnose von Produktionsproblemen. Im produktiven Unternehmenseinsatz hatten Entwickler meistens keinen Zugriff auf die produktiven Log-Dateien. Die Dateien mussten erst von einem Administrator angefordert werden, der einem dann die hoffentlich richtigen Log-Dateien bereitstellte. Unter solchen Umständen dauerte es oft Stunden, bis ein Problem diagnostiziert werden konnte. Mit dem Aufkommen von Microservice-Architekturen und verteilten Anwendungen in der Cloud steigt die Anzahl der relevanten Log-Dateien rasant an. In der Vergangenheit gab es Projekte mit einer Microservice-Architektur, bei denen allein von den Java-Anwendungen über 40 Log-Dateien auf vier verschiedenen Maschinen gleichzeitig geschrieben wurden. Die Problemdiagnose nur mit Texteditoren und UNIX-Kommandozeilen-Tools ist bei einer solchen Anzahl von Dateien keine erfreuliche Aufgabe. Ein Log-Server, der über eine grafische Oberfläche eine Volltextsuche über alle Log-Dateien ermöglicht, ist unter diesen Umständen eine große Arbeitserleichterung. Da der Zugriff auf den Log-Server nicht den direkten Zugriff auf das Produktionssystem erfordert, ist es – abgesehen vom Datenschutz – auch unkritisch, dem Entwickler Zugriff auf die Produktions-Logs zu geben. Es dauert dann nicht mehr Stunden, bis ein Entwickler die richtigen Log-Meldungen sehen kann, sondern er kann ohne fremde Hilfe tätig werden und hat praktisch Live-Zugriff.

Volltextsuche ist nicht genug

Die Datenbank eines Log-Servers speichert eine Log-Meldung nicht als Textzeile, sondern als Objekt mit mehreren Attributen. Die Textmeldung ist nur eines dieser Attribute. Andere Attribute sind zum Beispiel der Zeitstempel oder der Log-Level. Die Volltextsuchen der Log-Server sind zwar sehr schnell, Suchen auf Attributbasis sind jedoch nochmal eine Größenordnung schneller. Bei großen Log-Datenbeständen macht das einen spürbaren Unterschied. Außerdem sind Suchanfragen treffsicherer, wenn sie direkt auf ein Attribut abzielen. Wird zum Beispiel nach kurzen Zahlen über den vollen Text gesucht, gibt es regelmäßig Treffer in den Zeitstempeln. Bei der Suche nach einem Attribut sind solche False-Positives ausgeschlossen. In den GUIs der Log-Server gibt es außerdem statistische Auswertemöglichkeiten für Attributwerte. (Abb. 1) zeigt als Beispiel dafür, wie sich Meldungen mit einem gesuchten Fehlercode auf verschiedene Versionen der Software verteilen. Die gängigen Java-Log-Bibliotheken loggen nicht nur Textmeldungen, sie können auch Log-Meldungen direkt als Objekte im JSON-Format loggen. Die Attribute können dann direkt in die Datenbank übernommen werden und stehen dort als Parameter für Abfragen bereit.

Eine Auswertung in Kibana: Der Fehlercode 23505 taucht in drei verschiedenen Softwareversionen (appVersion) auf. (Abb. 1)

Die Infrastruktur: Log-Server und Java-Log-Bibliotheken

Log-Aggregierungs-Server sammeln die anfallenden Log-Daten ein, parsen die Log-Meldungen und speichern sie in einer Volltextdatenbank. Durch das Parsen werden die in unterschiedlichen Formaten anfallenden Log-Meldungen in ein einheitliches JSON-Format umgewandelt. Über grafische Oberflächen lassen sich die Log-Meldungen durchsuchen und anzeigen. Es gibt derzeit drei verbreitete Systeme: Der freie ELK-Stack besteht aus den Komponenten Elasticsearch als Volltextdatenbank, Logstash als Komponente zum Einsammeln sowie Parsen von Log-Daten und Kibana als grafische Benutzeroberfläche. Splunk ist ein verbreitetes kommerzielles Komplettsystem zur Log-Verarbeitung im Enterprise-Umfeld. Graylog gilt als kostengünstigere Alternative zu Splunk. Es gibt Graylog sowohl in einer Open-Source-Variante, als auch in einer kommerziellen Enterprise-Version. Es gibt Anbieter, die Cloud-basierte ELK-Stacks bereitstellen, die für einen Testzeitraum auch kostenlos ausprobiert werden dürfen.

Für das Erzeugen von Log-Meldungen gibt es aktuell zwei relevante und verbreitete Java-Log-Bibliotheken: Log4j2 und Logback. Beide stammen vom mittlerweile veralteten Log4j ab. Bezüglich Features und Performance liefern sich Logback und Log4j2 ein Kopf an Kopf Rennen. Das sehr verbreitete sl4j ist keine eigenständige Log-Bibliothek, sondern eine Fassade, die eine einheitliche API sowohl für Logback als auch für Log4j2 und andere weniger verbreitete Bibliotheken bietet. Durch sl4j werden direkte Abhängigkeiten im Code zur konkreten Log-Bibliothek vermieden. Für Code in Bibliotheken oder Frameworks ist nicht sicher, wie und von wem er später verwendet wird. Hier sollte immer sl4j genutzt werden, um die Entscheidung für eine konkrete Log-Bibliothek dem späteren Verwender des Codes zu überlassen.

Log-Meldungen richtig formatieren

Sowohl bei Log4j2 als auch bei Logback sind das Erzeugen von Log-Meldungen im Code und das Ausgeben einer Log-Meldung voneinander entkoppelt. In einer Konfigurationsdatei wird jeweils angegeben, wie Log-Meldungen ausgegeben werden sollen. Bei Log4j2 wird dazu ein Appender und eventuell ein Layout konfiguriert. Bei Logback hingegen ein Encoder. Log-Meldungen können direkt über das Netzwerk an einen Log-Server geschickt werden. Dies vereinfacht die Konfiguration des Gesamtsystems, da der Transport und das Parsen von Log-Dateien nicht selbst organisiert werden muss. Allerdings ist dann die Verfügbarkeit der Applikation an eine hinreichend schnelle und stabile Netzwerkverbindung zum Log-Server gekoppelt. Wird erst in eine Datei geloggt und dann diese Datei zum Log-Server transportiert, führt das zu einer höheren Resilienz.

Beim Schreiben in eine Log-Datei muss das textuelle Format der Log-Meldungen festgelegt werden. Da Log-Server die Daten im JSON-Format erwarten, ist es am einfachsten, gleich JSON zu loggen. Die Konfiguration der Log-Parser vereinfacht sich und zur Laufzeit wird die Rechenleistung für das Parsen reduziert. Sowohl für Log4j2 als auch für Logback gibt es passende Layouts, beziehungsweise Encoder für JSON. (Listing 1) zeigt ein Beispiel für Logback.

Log-Dateien im JSON-Format sind für Menschen schwerer zu lesen als normale Text-Log-Meldungen. Das UNIX-Kommandozeilen-Tool jq hilft, JSON-Meldungen lesbarer auszugeben. Zusätzlich zu einer Log-Datei im JSON-Format lassen sich in der Entwicklungsumgebung Log-Meldungen auch im Textformat auf der Konsole oder einer zusätzlichen Datei ausgeben.

Techniken fürs Loggen

Es bleibt die Frage, wie die Attribute im Java-Code für die Log-Meldungen eingesammelt und ausgeloggt werden. In einem realen Projekt können die Log-Meldungen weit mehr als 20 Attribute besitzen. Niemand schreibt gern Log-Meldungen, bei denen er bei jedem Aufruf einer Log-Methode über 20 Parameter angeben muss. Fast alle Attribute müssen automatisch zu einer Log-Meldung hinzugefügt werden, sonst scheuen sich Entwickler, viele Log-Meldungen zu schreiben. Die Attribute einer Log-Meldung lassen sich in drei Kategorien aufteilen, die jeweils mit unterschiedlichen Techniken angegangen werden. Einige Attribute sind innerhalb der Laufzeit einer Applikation konstant. Andere Attribute sollen für alle Log-Meldungen innerhalb eines bestimmten Bereichs gelten. Ein Beispiel für einen Bereich beziehungsweise Scope ist ein Web-Request. Schließlich gibt es Attribute, die nur für eine individuelle Log-Meldung gelten. Beispiele für konstante Attribute, die sich nach dem Start der Applikation nicht mehr ändern, sind

• der Name der zuständigen Organisationseinheit (Projektname, Abteilungsname etc.), falls der Log-Server von mehreren Projekten gemeinsam genutzt wird,
• der Name der Applikation,
• der Name des Microservice, falls eine Applikation aus mehreren Microservices besteht,
• die Software-Version,
• der Typ der Laufzeitumgebung (Entwicklung, Integration, Test, Produktion etc.) und
• die Bezeichnung der Laufzeitumgebung, auf der die Applikation läuft. Das kann der Hostname, der Name eines Clusters, Pods, Stacks oder ähnliches sein. Es kann auch zwischen den Namen der virtuellen und physischen Laufzeitumgebungen unterschieden werden.

Diese Attribute werden einmalig in der Log-Konfigurationsdatei gesetzt. Wie dies genau funktioniert hängt von der verwendeten Log-Bibliothek und vom verwendeten Formatter beziehungsweise Encoder ab. Ein einheitlicher Standard existiert leider nicht. Prinzipiell gibt es zwei Möglichkeiten die Werte in der Log-Konfiguration zu setzen. Beim Deployment kann die Konfigurationsdatei durch den Deployment-Mechanismus mit den richtigen Werten erzeugt werden. In einem Template der Log-Konfiguration werden durch Textersetzungen die gewünschten Werte gesetzt.

Die zweite Möglichkeit ist, Werte von Environment-Variablen in der Konfigurationsdatei beim Start der Anwendung auszuwerten. Dies funktioniert aber leider nicht mit allen Formattern beziehungsweise Encodern. In (Listing 1) ist ein Logback-Beispiel dargestellt.

(Listing 1)

Logback Konfiguration mit JSON-Ausgabe und festen Attributen im Tag customFields. VERSION wird aus dem Environment gelesen.

Wenn die Attribute für alle Log-Meldungen innerhalb eines Scopes, wie zum Beispiel einem Web-Request oder einem Methodenaufrufs gelten sollen, ist der Mapped-Diagnostic-Context (MDC) das Mittel der Wahl. Er wird von sl4j, Logback und Log4j2 unterstützt. Der Mapped-Diagnostic-Context speichert eine Map mit Log-Attributen im aktuellen Thread. Die Log-Attribute werden dabei in allen Log-Meldungen ausgegeben, die innerhalb des aktuellen Threads erzeugt werden. Dies betrifft insbesondere auch Log-Meldungen, die in Frameworks beziehungsweise Libraries erzeugt werden. Wenn zum Beispiel in einem Framework eine SQLException geloggt wird, ist diese Log-Meldung mit allen im MDC vorhandenen Attributen versehen und kann so mit anderen Log-Meldungen korreliert werden. Gute Code-Stellen, um den MDC zu füllen, sind zum Beispiel ServletFilter, in denen sich Informationen aus einem Web-Request abgreifen lassen:

• Der Name des angemeldeten Benutzers
• Die aufgerufene URL
• Die IP-Adresse des Aufrufers
• Ein Hash der Session-ID
• Daten aus der Session
• Daten aus Cookies
• Andere Attribute aus dem Http-Header

Andere gute Stellen zum Füllen des MDC sind Implementierungen von fachlichen Services. Hier können fachliche Daten aus den Aufrufparametern in den MDC geschrieben werden, bevor die eigentliche Geschäftslogik ausgeführt wird. Auf jeden Fall sollten fachliche IDs im MDC abgelegt werden. Fachliche IDs sind zum Beispiel Kundennummern, Bestellnummern oder Vorgangsnummern. Kundensichtbare IDs sind besonders wertvoll, denn wenn es zu einer Störung kommt, werden Anwender diese IDs nennen. Wird das Loggen von fachlichen IDs konsequent umgesetzt, wird bei einer Suche nach einer fachlichen ID der Gesamtzusammenhang eines Vorgangs sichtbar. Es ist nicht nur die Benutzeraktion mit dem Fehler zu sehen, sondern auch alle anderen zum Vorgang gehörenden Aktionen, wie zum Beispiel Änderungen durch andere Benutzer oder durch Batch-Prozesse. Dieses mehr an Kontext hilft ungemein bei einer Fehleranalyse.

Attribute müssen wieder gelöscht werden, sobald sie nicht mehr im Scope sind. Andernfalls kann zum Beispiel ein Web-Request noch alte Attribute vom Vorgänger loggen. Um dies zu lösen, ist der MDC als Stack aufgebaut und implementiert das Closeable Interface, so dass try–with Klauseln zum Füllen des MDCs verwendet werden können. In (Listing 2) ist ein Beispiel aus einem ServletFilter zu sehen, der Attribute per sl4j-API in den MDC schreibt. Eine zugehörige Log-Meldung ist in (Abb. 2) zu sehen. Die Meldung wurde von Hibernate erzeugt und stammt nicht aus dem eigenen Applikations-Code.

(Listing 2)

Innerhalb eines ServletFilters wird der Mapped-Diagnostic-Context mit Attributen gefüllt.

Kibana zeigt eine Logmeldung an. (Abb. 2)

Bei jeder individuellen Log-Meldung werden bereits von der Log-Bibliothek Attribute automatisch gesetzt. Dazu gehören der Zeitstempel, der Log-Level, der Meldungstext, der Name des Loggers und der Name des Threads. Von diesen Attributen können wir den Namen des Loggers, den Meldungstext und den Log-Level beeinflussen. Welcher Log-Level ist jetzt der jeweils richtige für eine Log-Meldung? Auf alle Fälle muss das einheitlich festgelegt werden. Hier ein Anwendungseispiel:

• ERROR ist für Fehler und Java-Exceptions. Hier besteht die Erwartung, dass die Ursache jeder Log-Meldung auf dem Level ERROR nachgegangen wird. Zusätzlich kann beim Level ERROR eine automatische Benachrichtigung an die Administratoren erfolgen.
• WARN ist eine als harmlos erkannte Fehlermeldung. Normalerweise können diese Meldungen ignoriert werden, es sei denn sie treten in großer Zahl auf. Ein Beispiel hierfür ist ein fehlgeschlagener Login-Versuch. Dies tritt regelmäßig auf und ist kein Grund zur Sorge. Wenn sich die Anzahl von fehlgeschlagenen Login-Versuchen stark häuft, kann das ein Anzeichen für eine technische Störung im Authentisierungssystem sein, oder es handelt sich um einen Angriff. In beiden Fällen muss gehandelt werden. Über die Histogrammfunktionen der Log-Server-GUIs lassen sich Zunahmen von Log-Meldungen im Level WARN leicht erkennen.
• INFO ist eine allgemeine Meldung zum Nachvollziehen der Vorgänge in einer Anwendung. Dieser Level ist im Produktionssystem eingestellt. Die Erwartung ist, dass auf diesem Level alle Informationen geloggt werden die notwendig sind, um eine Fehlersituation im Produktionssystem in einem Testsystem nachzustellen. Außerdem werden auf diesem Level Audit-Meldungen und alle Daten für statistische und fachlichen Auswertungen sowie das Monitoring geloggt.
• DEBUG ist auf dem Test- und Entwicklungssystem eingeschaltet. Der Level dient dazu, den Entwicklern Informationen zur Fehleranalyse bereitzustellen. Da dieser Level nicht in produktiven Systemen genutzt wird, können hier auch personenbezogene Daten und andere sensible Daten geloggt werden.
• TRACE wird von einigen Libraries und Frameworks genutzt. Der eigene Code benutzt diesen Level nicht.

Als erster Parameter einer Log-Meldung kann optional ein Marker übergeben werden. Der Umgang mit einem Marker kann schon in die Log-Konfigurationsdatei eingestellt werden. Log-Meldungen mit einem Marker können in eine andere Log-Datei als der Rest geschrieben werden. So können z.B. Audit-Meldungen in eine eigene Audit-Log-Datei getrennt von den restlichen Log-Meldung ausgeleitet werden. In (Listing 3) wird eine Audit-Meldung mit einem Marker geschrieben. (Listing 4) zeigt am Beispiel von Logback, wie diese Audit-Meldungen in eine eigene Log-Datei umgeleitet werden.

(Listing 3)

(Listing 4)

Logback-Konfiguration für das Ausleiten von Audit-Meldungen in die Log-Datei audit.log.

Key-Value-Paare können als Attribute direkt an eine Log-Meldung gehängt werden. Bei wichtigen Aktionen innerhalb der Anwendung sollte eine Event-ID als Attribut angegeben werden. Die ID sollte lesbar und eindeutig sein. Beispielsweise kann bei einem Zustandsübergang für den Schlüssel eventId der Name des Events als Wert gespeichert werden. Immer wenn das System eine fachliche Entscheidung trifft, kann ein Name für diese Entscheidung als Wert für eventId geloggt werden. Zahlenwerte (Mengen, Preise, Aufrufdauer etc.) lassen sich auch als Wert in einem Key-Value-Paar loggen. Die Verteilung der Zahlenwerte lässt sich mit dem Log-Server-GUIs statistisch auswerten.

Fehler-Codes sollten unter einem Schlüssel mit dem Wert des Codes als Attribut geloggt werden. Mit einem Fehler-Code können gleichartige Fehler gezielt gesucht und mit anderen Attributen gruppiert werden, um zum Beispiel die folgenden Fragen zu beantworten:

• Tritt der Fehler nur in Testsystemen auf oder auch im Produktionssystem?
• Mit welcher Softwareversion trat der Fehler erstmals auf (Abb. 1) ? Wurde der Fehler wirklich durch eine neue Version behoben?
• Welche Benutzer sind von dem Fehler betroffen und müssen eventuell kontaktiert werden?

Wird Logback mit dem Logstash-Encoder verwendet, können mit Hilfe der kv Methode sehr einfach Key-Value-Paare als Parameter geloggt werden. So führt die Code-Zeile

zu folgender Log-Meldung:

(Listing 5)

Bei Log4j2 funktioniert dieser Key-Value-Mechanismus leider nicht. Stattdessen bietet Log4j2 das Message Interface an. Um Key-Value-Paare über Message Objekte zu loggen, ist allerdings eine eigene Implementierung des Message Interfaces und eine eigene Implementierung eines Appenders notwendig.

Noch mehr IDs zum Zusammenhalten von Log-Meldungen

In einer Microservice-Architektur wird eine Benutzerinteraktion nicht nur von einem Service allein abgearbeitet. Um die Log-Meldungen einer einzelnen Aktion auf mehreren Services verfolgen zu können, werden sogenannte Correlation-IDs benötigt, die sich automatisch bei REST, JMS oder anderen Service-Aufrufen weiter übertragen. Dies funktioniert wie folgt:

• Trifft ein Request ohne Correlation-ID ein, wird eine ID erzeugt und in den MDC geschrieben.
• Beim Aufruf eines anderen Microservice wird die Correlation-ID in die Metadaten des Aufrufs geschrieben. Bei REST-Aufrufen wird die ID in den HTTP-Header geschrieben.
• Eine in den Meta-Daten eines eingehenden Request gefundene Correlation-ID wird in den MDC geschrieben.

Im Spring-Umfeld erledigt das die Bibliothek Sleuth automatisch. In (Abb. 2) hat Sleuth die Log-Meldung um eine Correlation-ID im Attribut traceId angereichert.

Es darf nicht alles geloggt werden

Sicherheitsrelevante Daten dürfen auf keinen Fall in Logs geschrieben werden. Dazu gehören unter anderem Passwörter und Kreditkarteninformationen. In vielen Logs ist häufig die Session-ID der HTTP-Session zu sehen. Bei der Verwendung eines Log-Servers darf diese ID nicht geloggt werden, da mit Kenntnis der Session-ID innerhalb des Gültigkeitszeitraums die Session eines Benutzers übernommen werden kann. Ein Log-Server macht die Session-ID viel zu schnell sichtbar. Da der konkrete Wert der Session-ID für die Log-Analyse nicht relevant ist, kann stattdessen ein Hash-Wert der Session-ID geloggt werden. Personenbezogene Daten werden am besten über eigene Log-Kommandos in abgetrennten Log-Dateien geloggt. Marker sind dazu gut geeignet. Log-Daten können im Log-Server in unterschiedlich abgesicherte Indizes gespeichert werden. Der Personenkreis, der Zugriff auf personenbezogene Daten haben soll, kann so stark eingeschränkt werden, während der Zugriff auf den Rest der Log-Daten ausgeweitet werden kann. Durch mehrere Indizes können auch unterschiedliche Löschfristen für die Log-Daten realisiert werden. Bei personenbezogenen Daten sind eher kurze maximale Aufbewahrungsfristen gefordert, während bei Auditdaten eher lange Mindestaufbewahrungsfristen wünschenswert sind. Die Aufteilung der Log-Daten auf verschiedene Indizes mit unterschiedlichen Löschfristen löst dieses Problem elegant.

Lebt die Applikation noch?

Ein gut strukturiertes Logging erlaubt das Monitoring einer Anwendung. Klassischerweise werden Fehlermeldungen im Log überwacht. Auf diese Weise lässt sich feststellen, dass irgendetwas nicht funktioniert. Viel wichtiger ist es aber festzustellen, dass eine Anwendung erfolgreich arbeitet. In komplexeren Systemen kommt es hin und wieder zu Fehlersituationen, die nicht zu Fehlermeldungen führen. Beispiele dafür sind:

• Benutzer führen einen Prozessschritt in einem Fremdsystem durch und werden dort durch Fehler blockiert, die nicht im eigenen Log auftauchen. Im eigenen System ist nur zu sehen, dass nichts passiert, weil die Benutzer nicht zurückkehren. Wird ein Abgangs- und ein Rückkehr-Event geloggt, zeigt eine stark abfallende Rate der Rückkehr-Events das Problem an.
• Netzwerkprobleme mit Teilausfällen vor der eigentlichen Anwendung führen zu keinen Fehlern in den Anwendungs-Logs. Allerdings bricht die Rate der Events im Log sichtbar ein.

Tests auch für das Logging

Auch Log-Meldungen einer Applikation sollten Tests unterzogen werden. Damit ist nicht gemeint, dass in Unit-Tests das Loggen jeder einzelnen Meldung überprüft wird, sondern dass Log-Meldungen auf Vollständigkeit und Verständlichkeit geprüft werden. Dazu werden die Use-Cases der Anwendung durchgeführt und anschließend wird geprüft, ob sich die durchgeführten Aktionen nachvollziehen lassen. Tritt bei einem Test ein Fehler in der Anwendung auf, sollte immer auch überprüft werden, ob der Fehler in den Log-Meldungen nachvollziehbar ist und ob zur Diagnose des Fehlers Daten fehlen. Wenn erst im produktiven Betrieb festgestellt wird, dass im Log Daten fehlen, ist es zu spät.