Über unsMediaKontaktImpressum
Dirk Tröndle 15. September 2020

Elastic Stack: Mit strukturierten Logs schneller Fehler finden

Fehler früh zu finden und, wenn irgend möglich, ehe es die Anwender tun – das ist das Wichtigste, während man den Betrieb einer Software überwacht. Logging ist dabei eines von vielen Hilfsmitteln, mit denen man Fehler erkennen und analysieren kann. In Zeiten von Microservices und verteilten Systemen gewinnen dazu Tools wie der Elastic Stack immer mehr an Bedeutung.

Leider ist der bloße Tooleinsatz kein Selbstläufer. Manchmal bleiben Tools hinter dem zurück, was sie tatsächlich leisten könnten. Um das zu vermeiden, ist es elementar, bereits zur Entwicklungszeit die eigenen Logausgaben mit sinnvollen Daten in einem geeigneten Format zu befüllen.

Der Artikel beschreibt, wie sich Logausgaben mit wenigen Handgriffen verbessern lassen. Das Ziel dabei ist es, mit dem Elastic Stack bessere Dashboards bauen zu können und Fehlerursachen schneller zu identifizieren.

Elastic Stack

Der Elastic Stack ist eine Sammlung an Open-Source-Produkten der Firma Elastic. Früher war er auch unter dem Namen ELK Stack bekannt, benannt als Akronym der drei Produkte ElasticSearch, Logstash und Kibana. Als das vierte Produkt Beats in den Stack kam, wurde es schwierig, das Akronym beizubehalten, weshalb die Sammlung in Elastic Stack umbenannt wurde.

Die Produkte sind im Wesentlichen Tools, die einem Nutzer dabei helfen, Daten aus beliebigen Quellsystemen mithilfe der ElasticSearch, einer RESTful-Suchmaschine auf JSON-Basis, zu analysieren. Außerdem können die Daten mittels Kibana in verschiedenen Ausprägungen, z. B. Tabellen oder Diagrammen visualisiert werden. Logstash ist dabei eine Datenverarbeitungspipeline, die Daten aus verschiedenen Quellen konsumiert, umwandelt und dann in ein Zielsystem, i. d. R. ElasticSearch schickt [1].

Der Elastic Stack hat als wichtigen Anwendungsbereich die Verarbeitung und Visualisierung von Logdateien aus verteilten Systemen. Man kann ihn aber natürlich auch für die Analyse von anderen Daten verwenden. Der Elastic Stack kann auf eigenen Servern, also OnPremise gehostet werden. Alternativ gibt es ihn auch als Software-as-a-Service-Produkt und er ist in allen gängigen Cloud-Plattformen als Service verfügbar.

Was sind gut analysierbare Logausgaben?

Der Einsatz vom Elastic Stack verbessert leider nicht die Qualität der Logausgaben. Deshalb sollte man bereits im Anwendungscode darauf achten, dass die Logausgaben möglichst leicht analysierbar sind.

Grundsätzlich sollte man in seinen Logausgaben auch weiterführende Informationen zur Analyse inkludieren, falls die Message alleine nicht aussagekräftig genug ist. Eine Logausgabe mit dem Inhalt "something went wrong" sagt beispielsweise zwar aus, dass etwas schief lief, liefert aber außer dem Zeitpunkt keine weiteren Informationen um den konkreten Fehler zu finden. Auch Stacktraces sind unter Umständen alleine nicht aussagekräftig genug und bedürfen oftmals weiterer Informationen.

Wenn man weiterführende Informationen in seine Logausgaben aufnimmt, sollte man natürlich auf den Datenschutz achten. In den meisten Fällen genügen pseudonymisierte oder unsensible Informationen für eine Fehleranalyse.

Die Vermischung vom wesentlichen Inhalt und weiterführenden Informationen sollte man auch vermeiden. Der wesentliche Inhalt der Logausgabe bezeichnet hier den Grund, warum man diese Ausgabe gerade loggt. Weiterführende Informationen können beispielsweise eine Id einer Ressource sein. Gibt es für eine Logausgabe keinen (möglichst konstanten) Grund, warum sie existiert, sollte man hinterfragen, ob es sinnvoll ist, die Ausgabe überhaupt zu loggen.

Gibt es dagegen einen sinnvollen Grund für eine Logausgabe, dann kann man diesen auch einfach als Message in die Logausgabe schreiben. Dabei ist es hilfreich, wenn weiterführende Informationen nicht innerhalb dieses Grundes stehen, sondern davor oder danach in einem weiteren Satz vorkommen. Denn es ist viel einfacher, nach einem konstanten Text zu suchen, anstatt nach mehreren Textteilen. Vermeiden sollte man also etwas wie "Buchung mit Id [12345] wurde storniert" zu loggen, stattdessen wäre es besser "Buchung wurde storniert. Id [12345]" zu loggen, damit man nach dem konstanten Text "Buchung wurde storniert" suchen und gleichartige Logausgaben finden kann, ohne im Suchergebnis falsche Treffer zu haben.

Für das Logging sollte man falls möglich immer ein Logging Framework benutzen. Diese gibt es eigentlich für alle Programmiersprachen und sie ergänzen automatisch weitere wichtige Informationen, wie das Level oder den Timestamp.

Wird so ein Framework genutzt, sollte man in einem der Logausgabe angemessenen Level loggen. Positive Logausgaben sollten eher im Level INFO bzw. DEBUG und Fehler eher im Level WARN, ERROR bzw. FATAL sein.

Zudem sollte man darauf achten, dass beim Zusammenbauen der Log-Message keine Exceptions entstehen können. In Java sollte auch vermieden werden Objekte ohne sinnvolle toString()-Methode direkt zu loggen, da ein Objekt-Hash wie MyObjectName@27af8038 nicht wirklich bei einer Analyse weiterhilft.

Mit dem Elastic Stack kommen noch weitere Aspekte dazu, die man für gut analysierbare Logausgaben beachten sollte. Grundsätzlich unterstützt ElasticSearch die Datentypen die es im JSON-Format gibt. Beim Weg einer Logausgabe von der Anwendung hin zur ElasticSearch über Logstash wird eine Logausgabe automatisch in ein Log-Event im JSON-Format konvertiert. Dabei wird die eigentliche Logausgabe, wenn sie bereits im JSON-Format ist und man Logstash entsprechend konfiguriert, direkt übernommen und ggf. durch weitere Metainformationen ergänzt. Wenn sie allerdings nicht im JSON-Format ist, landet die gesamte Logausgabe als String Value für den Key message im Log-Event.

Visualisierungen in Kibana und damit auch mögliche Auswertungen von Log-Files sind durch den Datentypen eines Values innerhalb des Log-Events unter Umständen stark limitiert. Für Strings kann man in Visualisierungen im Wesentlichen nach einem Substring suchen und passende Log-Events zählen.

Für Zahlendatentypen sind auch Analysen wie Durchschnitts-/Minimal-/Maximalwerte oder Perzentile möglich. Dies kann insbesondere bei automatischen Warnungen sehr hilfreich sein, wenn man eine Mail nur bei Überschreiten eines fachlichen Schwellenwertes verschicken möchte.

Selbst bei Strings, die auch ein spezielleres Format haben, bietet es sich an, diese direkt im entsprechenden Format zu loggen. Dann kann man z. B. für Ländercodes die im ISO 3166-1 alpha-2-Format sind, also zwei Buchstaben haben, weitere Logdaten des gleichen Log-Events farblich auf einer Landkarte darstellen.

Allgemein sollte man weiterführende Informationen also immer in einem möglichst passenden Datentyp loggen. Dadurch kann man in Kibana das volle Potential an Analysemöglichkeiten ausschöpfen.

Wenn eine Anwendung nicht im JSON-Format loggt, kann es bei der Verarbeitung der Logausgaben in Logstash dazu kommen, dass im resultierenden Log-Event mehrere Timestamps sind. Zum einen enthält in der Regel jede Logausgabe einen Timestamp. Dieser landet als Teil der Logausgabe standardmäßig im Key message. Zum anderen fügt Logstash normalerweise einen Timestamp als Metainformation zum Log-Event hinzu. Dies ist dann der Timestamp zu dem die Logausgabe innerhalb von Logstash verarbeitet wurde. Diese zwei in der Regel unterschiedlichen Timestamps können bei einer Log-Analyse zu Verwirrungen führen.

Um das zu vermeiden und um weiterführende Informationen in einem möglichst passenden Datenformat analysieren zu können, gibt es im Wesentlichen zwei Möglichkeiten: Zum einen kann man bereits in der Anwendung im JSON Format loggen und dies in der Logstash Konfiguration entsprechend einstellen. Zum anderen kann man in der Anwendung weiterhin zeilenbasiert loggen und in der Logstash Konfiguration Filter Plugins definieren. Diese Plugins können den einen Value zum Key "message" im String Datentyp, der die gesamte Logausgabe enthält in mehrere Key-Value Paare mit konkreteren Datentypen zerlegen. Normalerweise bleibt dabei die ursprüngliche Logausgabe weiterhin vollständig in einem eigenen Key erhalten.

Anwendungsseitige Anpassung der Logausgaben

Es ist in der Regel am einfachsten, Daten direkt an deren Quelle zu bereinigen. Deshalb bietet es sich auch an, für einfachere Log-Analysen direkt den Anwendungscode anzupassen, der die Logausgaben produziert. Wenn man in seiner Anwendung ein Logging Framework benutzt, was immer empfehlenswert ist, ist die Umstellung auf Logging im JSON-Format recht einfach. In einer Java-Anwendung mit Springboot, die SLF4J mit Logback als Logging Framework benutzt, muss man beispielsweise lediglich eine Konfigurationsdatei in den Classpath legen, in der man einen entsprechenden Appender definiert. Mit einem Appender kann man steuern, in welchem Format die Logausgabe stattfindet und welche Daten automatisch inkludiert werden.

Listing 1: Appender-Konfiguration für die Logausgabe im JSON-Format

...
<appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
        <providers>
            <timestamp/>
             <mdc/>
             <context/>
             <version/>
             <logLevel/>
             <message/>
             <threadName/>
             <logstashMarkers/>
             <arguments/>
             <stackTrace/>
             <callerData/>
        </providers>
    </encoder>
</appender>
...

Die Konfiguration aus Listing 1 bedeutet, dass der Appender den LoggingEventCompositeJsonEncoder von Logback benutzt, der sich um die Ausgabe im JSON-Format kümmert. Im <providers>-Tag kann man dann definieren, welche weiteren Informationen man als eigenes Key-Value-Paar im JSON haben möchte. So sorgt z. B. das <stackTrace />-Tag dafür, dass man im Falle von Fehlerlogging für den Stacktrace ein eigenes Key-Value-Paar erhält.

Produziert man bereits in der Anwendung Logausgaben im JSON-Format, dann kann man auch eigene Key-Value-Paare für jede weiterführende Information einführen.

Listing 2: Ein Log-Statement mit weiterführenden Informationen

logger.warn("Critical Values detected! SensorId={}, AggregationType={}, Value={}", sensor.getId(), data.getAggregationType(), data.getValue());

In Java mit Logback gibt es dafür die StructuredArguments-Klasse. Die weiterführenden Informationen werden dabei in ein StructuredArguments.keyValue verpackt. Dadurch landen sie zusätzlich zur Ersetzung der "{}"-Platzhalter in der Log-Message auch in eigenen Key-Value-Paaren.

Listing 3: Das Log-Statement aus Listing 2 nach dem Umbau mit StructuredArguments von Logback. Die Logausgabe bleibt dabei identisch.

import net.logstash.logback.argument.StructuredArguments;
...
logger.warn("Critical Values detected! {}, {}, {}", 
	StructuredArguments.keyValue("sensorId", sensor.getId()),
	StructuredArguments.keyValue("AggregationType", data.getAggregationType()),
	StructuredArguments.keyValue("value", data.getValue()));

Man kann in dem Fall auch die Platzhalter in der Log-Message weglassen, wodurch die eigentliche Log-Message zu einem konstanten String wird. Dabei verliert man durch die eigenen Key-Value-Paare keine Daten und erhält eine sehr viel leichter analysierbare Logausgabe, da sie eine konstante Message enthält. Für andere Programmiersprachen oder Logging Frameworks als Java mit SLF4j und Logback gibt es meistens ähnliche Konstrukte.

Alternativ ist der sogenannte Mapped Diagnostic Context (MDC) ein sehr verbreitetes Konzept. Dieses Konzept existiert in vielen der verbreiteteren Programmiersprachen. Der MDC ist im Wesentlichen eine Map, die für den aktuellen Thread nutzbar ist und in die man Werte setzen kann, die dann als Key-Value-Paar in jeder Logausgabe auftauchen. Man muss dabei aber aufpassen, dass man den MDC zu einem geeigneten Zeitpunkt wieder leert. Denn da der MDC für den ganzen Thread gilt und je nach Programmiersprache Threads durchaus für andere Requests wiederverwendet werden könnten, kann es passieren, dass man Daten im MDC hat, die nichts mit der aktuellen Request zu tun haben. Dies kann eine Log-Analyse wesentlich erschweren.

Um dieses Problem anzugehen kann man in Java z. B. OncePerRequestFilter oder Aspekte benutzen, die den MDC zum Ende einer Request bereinigen. Alternativ kann man sich auch einen Wrapper für den Logger schreiben, der weitere Parameter nur für die Dauer einer einzelnen Logausgabe in den MDC setzt und danach direkt wieder entfernt.

Logstashseitige Anpassung der Logausgaben

Was soll man aber tun, wenn man keine Zeit oder Berechtigung hat, den Code der Anwendung zu ändern?

Grundsätzlich ist es natürlich besser, die Logausgaben so nah wie möglich an der Quelle, also im Anwendungscode, in ein sinnvolles Format zu bringen. Allerdings bietet der Elastic Stack mit Logstash Filter Plugins auch eine Möglichkeit, Logausgaben bei der Konvertierung in Log-Events strukturell zu verändern. Dabei kann man auch mehrere Filter Plugins hintereinander schalten, um nach und nach sinnvolle Key-Value-Paare aus der Logausgabe zu extrahieren. Der Vorteil daran ist, dass man die Anwendung nicht ändern muss. Man sollte allerdings nach Möglichkeit trotzdem die oben genannten Punkte zu sinnvoll formatierten Logausgaben beachten, da diese auch die Konfiguration der Plugins wesentlich einfacher machen können.

Der Nachteil an den Logstash Plugins ist, dass man sie in manchen Cloud-Infrastrukturen nicht selbst konfigurieren darf und mit der vorgegebenen Konfiguration arbeiten muss. In diesem Fall muss man die Anwendung den Vorgaben der Infrastruktur entsprechend anpassen.

Außerdem greifen die Plugins, wenn man keine sinnvollen Bedingungen für sie definiert, für die Logausgaben von jeder Anwendung die die Logstash-Instanz durchlaufen. Folglich muss man bei der Konfiguration Vorsicht walten lassen, da im schlimmsten Falle bei Syntaxfehlern Logausgaben verloren gehen könnten. Aus diesem Grund bietet es sich an, die Konfiguration vor dem Einsatz in einem produktiven System ausgiebig zu testen. Dabei sollte man zum einen verifizieren, dass alle Log-Events wie erwartet im Elastic Stack landen und zum anderen, dass sie das gewünschte Format haben. Man kann dazu relativ einfach die Docker-Container von Elastic benutzen, mit denen man als Entwickler auch auf dem eigenen Rechner in wenigen Minuten einen lauffähigen Elastic Stack haben kann [2].

Es gibt eine lange Liste an Logstash Filter Plugins, von denen sich drei vor allem um die Strukturierung von Log-Events kümmern, nämlich dissect, grok und kv [3]. Für andere Anwendungsfälle lohnt sich ein Blick in die Dokumentation von Logstash [4].

Vermutlich ist das kv-Plugin das am einfachsten zu konfigurierende von den genannten Plugins. Es kann im Wesentlichen Logausgaben verarbeiten, die key=value enthalten und erstellt für solche Werte jeweils ein neues Key-Value-Paar im JSON des resultierenden Log-Events. Dabei können auch automatisch Klammern oder andere definierbare Zeichen entfernt werden. Außerdem kann man ein anderes Zeichen als das Gleichheitszeichen zur Erkennung der Paare benutzen.

Listing 4: Die Logausgabe von Listing 2 nach Anwendung des kv-Plugins ohne spezielle Konfiguration.

{
    "message": "2020-08-14 08:53:55.316  WARN 1 --- [nio-8080-exec-2] d.a.dtroendle.controlUnit.Controller     : Critical Values detected! SensorId=7c39af02-d766-4e6c-b195-f300dbf9bbda, AggregationType=MIN, Value=-4.088636112904403",
    "SensorId": "7c39af02-d766-4e6c-b195-f300dbf9bbda",
    "AggregationType": "MIN",
    "Value": "-4.088636112904403"
}

Das dissect-Plugin bietet sich an, wenn man viele Logausgaben mit gleicher Struktur hat. Man kann mit dem Plugin nämlich ein Pattern angeben, nach dem die einzelnen Elemente einer Logausgabe in neue Key-Value-Paare aufgetrennt werden. Das Ganze ist sehr performant und funktioniert ähnlich wie eine Split-Operation mit mehreren Trennzeichen. Wenn man eine Springboot-Applikation hat, die nicht im JSON-Format loggt, dann haben meistens alle Logausgaben dieses Format:

Date Time Level PID --- [Threadname] Loggername : Logmessage

Daraus lässt sich wie in Listing 5 beschrieben leicht ein dissect-Pattern erstellen.

Listing 5: Beispielhafte dissect-Plugin-Konfiguration für Logausgaben einer Springboot-Anwendung

dissect {
	mapping => {
		"message" => "%{+timestamp} %{+timestamp} %{level} %{pid} --- [%{thread}] %{loggername} : %{msg}"
	}
}

Durch die Konfiguration in Listing 5 werden für jedes passende Element des konfigurierten Patterns eigene Key-Value-Paare im Log-Event erstellt. Listing 6 zeigt, wie das Log-Event einer Springboot-Anwendung dann nach Anwendung des Plugins aussehen würde.

Listing 6: Die Logausgabe von Listing 2 nach der Anwendung des dissect-Plugins.

{
    "message": "2020-08-14 08:53:55.316  WARN 1 --- [nio-8080-exec-2] d.a.dtroendle.controlUnit.Controller     : Critical Values detected! SensorId=7c39af02-d766-4e6c-b195-f300dbf9bbda, AggregationType=MIN, Value=-4.088636112904403",
    "timestamp": "2020-08-14 08:53:55.316",
    "level": "WARN",
    "pid": 1,
    "thread": "nio-8080-exec-2",
    "loggername": "d.a.dtroendle.controlUnit.Controller",
    "msg": "Critical Values detected! SensorId=7c39af02-d766-4e6c-b195-f300dbf9bbda, AggregationType=MIN, Value=-4.088636112904403"
}

Allerdings kann es dabei zu Fehlern kommen, wenn eine Logausgabe das Plugin durchläuft, die nicht diese Struktur hat. Deshalb sollte man die Anwendung des Plugins auf passende Logausgaben einschränken.

Haben die Logausgaben der Anwendung keine allgemeingültige Struktur, sollte man eher das grok-Plugin benutzen. Damit kann man Logausgaben mithilfe von regulären Ausdrücken in eigene Key-Value-Paare auftrennen. Es gibt viele vorgefertigte Patterns, die direkt mitgeliefert werden, z. B. Patterns für IP-Adressen oder Datumsformate. Man kann aber natürlich auch eigene Patterns definieren. Das Plugin ist etwas mächtiger, aber auch langsamer als das dissect-Plugin, weshalb man bei gleichbleibender Struktur eher das dissect-Plugin verwenden sollte. Es können aber natürlich auch die beiden bzw. die drei Plugins kombiniert werden. Beispielsweise kann zunächst die allgemeine Struktur mittels dissect in Key-Value-Paare aufgeteilt werden. Danach kann man, auf die resultierenden neuen Key-Value-Paaren nachgelagert, das grok- oder kv-Plugin anwenden, um für diese eine einfachere Konfiguration schreiben zu können.

Die bisher beschriebenen Schritte teilen eine Logausgabe lediglich in eigene Key-Value-Paare im Log-Event auf. Der Value-Datentyp bleibt dabei aber zunächst String. Mit den dissect- und grok-Plugins kann man darüber hinaus auch noch den Value-Datentyp ändern und beispielsweise Key-Value-Paare, die eine Zahl enthalten, auch als Number-Typ konvertieren, um in Kibana bessere Analysen machen zu können.

Möglichkeiten in Kibana durch strukturierte Log-Events

Mit den oben beschriebenen Schritten kann man seine Log-Events im Elastic Stack besser strukturieren. Man erhält eigene Key-Value-Paare für unterschiedliche Daten, die darüber hinaus bestenfalls auch noch einen passenden Datentyp haben.

Da die weiterführenden Informationen in eigenen Key-Value-Paaren sind, lässt sich eine Visualisierung konfigurieren, die diese sinnvoll z. B. in Form von Perzentilen oder Durchschnittswerten darstellen.

In Kibana kann man außerdem mit einem einfachen Klick auf das Plus beim entsprechenden Key im Log-Event nach gleichartigen Log-Events filtern. Dadurch sieht man sehr schnell, ob ein konkreter Fehler häufiger vorkommt.

Zusammenhang zwischen verschiedenen Log-Events herstellen

Bisher haben wir erreicht, dass wir einzelne Log-Events sinnvoller analysieren und in entsprechenden Visualisierungen verwenden können. Man kann, falls man den Anwendungscode anpassen möchte, aber auch noch einen Schritt weiter gehen und den Zusammenhang zwischen mehreren Log-Events der gleichen Request an die Anwendung herstellen. Dies kann sehr hilfreich sein um die Ursache von Fehlern anhand von weiteren Log-Events zu identifizieren, die zur gleichen Request gehören.

Dafür genügt es im Wesentlichen, einen eindeutigen Identifizierer, z. B. eine UUID oder Transaktionsnummer als zusätzliches Key-Value-Paar in jede Logausgabe einer Request hinzuzufügen. Dabei wird man vom bereits erwähnten MDC unterstützt.

Wenn man an einem frühen Zeitpunkt einer Request eine UUID als LoggingId zur Identifikation zusammengehöriger Logausgaben in den MDC setzt, kann man über diese LoggingIds zusammengehörige Log-Events im Kibana sehr einfach erkennen und über den Plus-Filter danach suchen. Hier muss man aber wie bereits erwähnt auch aufpassen, dass man den MDC nach der aktuellen Request wieder bereinigt.

Den gleichen Mechanismus kann man natürlich auch verwenden, um allgemeingültige weiterführende Informationen für die aktuelle Request in jeder Logausgabe einer Request oder in jeder Logausgabe eines Methodenaufrufs zu ergänzen. Dadurch kann man unter Umständen einiges an Code einsparen.

Bei einer Microservice-Architektur kann es auch sinnvoll sein, solche LoggingIds über Servicegrenzen hinweg weiterzureichen, damit man Fehler, die sich über mehrere Services erstrecken leichter analysieren kann.

Im Spring-Umfeld gibt es für diesen Zweck mit Spring Sleuth ein Framework, das dies automatisch macht. Es ergänzt also TraceIds in jeder Logausgabe und sendet diese via Request Header auch an andere Anwendungen, die diese dann weiterverwenden können. Falls man diese Bibliothek in alle Microservices einbauen kann oder darf, kann sich der Einsatz von Sleuth lohnen [5].

Fazit

Die Möglichkeiten des Elastic Stacks sind limitiert durch den Inhalt der Logausgaben der Anwendungen. Wenn keine guten Informationen in den Logausgaben stehen, wird man auch mit dem Elastic Stack keine sinnvollen Fehleranalysen vornehmen und Dashboards konfigurieren können. Strukturell sollte man nach Möglichkeit bereits in der Anwendung Logausgaben im JSON-Format produzieren. Falls das nicht möglich ist, kann man die Logausgaben mithilfe von Logstash Filter Plugins nachträglich in ein JSON-Format konvertieren. Wenn diese Punkte beachtet werden, steht einem effizienten Tooleinsatz des Elastic Stacks nichts mehr im Wege.

Autor

Dirk Tröndle

Dirk Tröndle ist Full-Stack-Entwickler mit Erfahrung in Java und Javascript, sein Fokus liegt aber auf der Backendentwicklung mit Java und Spring.
>> Weiterlesen
Kommentare (0)

Neuen Kommentar schreiben