Einfachere Observability durch strukturiertes Logging

Während CI/CD-Tools und Container-Technologien oft die Brücke zwischen Dev und Ops in der einen Richtung bilden, schließen Observability-Lösungen den Kreis in die andere Richtung, d. h. von Ops nach Dev [2]. Observability ist damit die Grundlage für eine daten-getriebene Softwareentwicklung (s. Abb. 1).

Im Verlaufe der Entwicklungen rund um das cloud(-native) Computing begannen immer mehr Ingenieure, "in ihren Dashboards zu leben". Sie lernten, dass es nicht ausreicht, einfach nur Datenpunkte zu erfassen und zu überwachen, sondern dass es notwendig ist, sich diesem Problem systematischer zu widmen. Heutzutage wird Observability daher oft als Dreiklang verstanden. Die Beobachtbarkeit von Systemen wird durch die Erfassung und Aufbereitung von Metriken, von sogenannten Distributed-Tracing-Daten und Logging erzielt. Folgerichtig sind auch drei Stacks von (oft Open-Source-)Observability-Lösungen entstanden, die heutzutage in cloud-nativen Anwendungen Verwendung finden, aber auch durchaus als Managed Cloud Services bezogen werden können.

• Metriken: Hier werden häufig quantitative Daten in Form von Zeitreihen erhoben, z. B. wieviele Requests verarbeitet ein System gerade. Der Metrik-Technologie-Stack ist oft durch Tools wie Prometheus und Grafana gekennzeichnet.
• Tracing: Beim Distributed Tracing verfolgt man den Weg von Transaktionen entlang der Komponenten eines verteilten Systems. Der Tracing-Technologie-Stack ist durch Tools wie Zipkin oder Jaeger gekennzeichnet und man nutzt die Technologien insbesondere dazu, besonders langsame oder fehleranfällige Teilschritte einer verteilten Transaktionsverarbeitung zu identifizieren und zu optimieren.
• Logging: Logging ist vermutlich so alt wie die Softwareentwicklung selber und wird von vielen Entwicklern erst einmal gar nicht bewusst als Teil einer ganzheitlichen Observability empfunden. Logs werden meist in sogenannten Log-Dateien gespeichert. Dabei werden meist qualitative Ereignisse geloggt (z. B. User XYZ loggt sich ein/aus). Ein Ereignis wird dabei meist in einer Textzeile an eine Log-Datei angehängt. Oft herrscht dabei die implizite und historisch begründbare Annahme bei Entwicklern vor, dass diese Log-Dateien vor allem von Administratoren (also Menschen) gelesen und ausgewertet werden. Zunehmend mehr setzt sich durch, die Inhalte dieser Log-Dateien mittels "Log-Forwardern" an eine zentrale Datenbank weiterzuleiten, um sie dort zentral auswerten und analysieren zu können. Der Technologiestack ist dabei oft durch Tools wie Fluentd, FileBeat, LogStash zum Log-Forwarding, Datenbanken wie ElasticSearch, Cassandra oder einfach S3 und User Interfaces wie bspw. Kibana gekennzeichnet.

Allen drei Beobachtbarkeitssäulen ist im Übrigen gemein, dass zu entwickelnde Software geeignet instrumentiert werden muss. Insbesondere die Distributed-Tracing-Instrumentierung wird dabei von Entwicklern häufig als aufwändig eingeschätzt. Auch wann welche Metriktypen (Counter, Gauge, Histogramm, History) bei Lösungen wie z. B. Prometheus zu nutzen sind, ist oft von Erfahrung abhängig und den Entwicklern nicht immer sofort einsichtig. Gewisse Observability-Hoffnungen scheitern schlicht an falsch gewählten Metriktypen. Einzig und allein System-Metriken wie CPU-, Memory-, Storage-Auslastung sind blackbox-artig (d. h. ohne Instrumentierung im Code) durch Metriksysteme weitgehend problemlos erfassbar. Diese Daten sind aber häufig für die fachliche Beurteilung von Systemen nur begrenzt hilfreich. Die CPU-Auslastung gibt bspw. wenig Aufschluss darüber, ob sich Konversionsraten in einem Online-Shop in die gewünschte Richtung entwickeln.

Bei aktuellen Observability-Lösungen wird oft von diesen drei Säulen ausgehend gedacht und nicht von der Applikation kommend. Im Resultat ergibt sich eine Applikation, die von einem komplexen Observability-System umgeben ist (s. Abb. 2).

Abb. 2 setzt dabei die Applikation (also das zu überwachende Objekt) in den Mittelpunkt. Beim bloßen betrachten der Abbildung stellt sich sofort die Frage, ob es eigentlich gerechtfertigt ist, drei komplexe Teilsysteme und auch drei Arten der Instrumentierung einsetzen zu müssen, die ja auch immer dreifachen Aufwand bedeuten.

Vereinheitlichungspotenzial

Die oft genutzte Tool-Kombination aus ElasticSearch, LogStash und Kibana wird oft für das Logging eingesetzt und hat sogar ein einprägsames Kürzel erhalten: ELK-Stack [3].

An exakt dieser Kombination kann man übrigens diverse Überschneidungen zwischen den genannten drei Säulen sehen. Der ELK-Stack kann durchaus auch zur Erfassung von Metriken und auch für das Distributed Tracing eingesetzt werden. Die drei Säulen sind also nicht wirklich trennscharf oder gar disjunkt. Die Trennschärfe wird eher historisch "suggeriert", als dass diese technologisch tatsächlich gegeben wäre. Dennoch ist diese Dreiteilung in Metriken, Tracing und Logging sehr prägend für die Industrie, wie bspw. das OpenTelemetry-Projekt zeigt [4]. OpenTelemetry befindet sich derzeit bei der Cloud Native Computing Foundation in der Inkubationsphase und stellt eine Sammlung von standardisierten Tools, APIs und SDKs bereit, mit der Telemetriedaten (Metriken, Protokolle und Traces) instrumentiert, generiert, gesammelt und exportiert werden können, um die Leistung und das Verhalten von Software-Systemen zu analysieren. OpenTelemetry standardisiert somit zwar Observability, zielt aber kaum darauf ab, die Säulentrennung in Metriken, Tracing und Logging zu überwinden.

Die Diskussion um die Observabillity geht jedoch zunehmend über diese drei Säulen hinaus und nimmt eine differenziertere und auch integriertere Sichtweise ein. Es gibt ein größer werdendes Bewusstsein dafür, diese drei Säulen zu integrieren und zu vereinheitlichen, und es wird mehr Wert auf die Analyse gelegt.

12 Faktoren

Die Zwölf-Faktoren-App ist eine Methode [5], um Software-As-A-Service-Anwendungen zu bauen, die ein besonderes Augenmerk auf die Dynamik des organischen Wachstums einer App über die Zeit, die Dynamik der Zusammenarbeit zwischen den Entwicklern die an einer Codebase zusammenarbeiten und der Vermeidung der Kosten von Software-Erosion legen. Im Kern gibt es 12 Regeln (Faktoren), die eingehalten werden sollten, um gut betreibbare und evolutionär entwickelbare verteilte Anwendungen zu entwickeln. Diese Methodik harmoniert sehr gut mit Microservice-Architektur-Ansätzen und cloud-nativen Betriebsumgebungen, weswegen sich die 12-Faktoren-Methodik zunehmender Beliebtheit erfreut.

Die 12-Faktoren-Methodik enthält übrigens keinen Faktor, der sich explizit auf Observability bezieht, schon gar nicht im Dreiklang von Metriken, Tracing und Logging. Allerdings wird im Faktor XI das Logging explizit erwähnt: "Logs sind der Stream von aggregierten, nach Zeit sortierten Ereignissen und zusammengefasst aus den Output Streams aller laufenden Prozesse und unterstützenden Dienste. Logs sind üblicherweise ein Textformat mit einem Ereignis pro Zeile." Ferner: "Eine Zwölf-Faktor-App kümmert sich nie um das Routing oder die Speicherung ihres Output Streams. Sie sollte nicht versuchen, in Logdateien zu schreiben oder diese zu verwalten. Stattdessen schreibt jeder laufende Prozess seinen Stream von Ereignissen auf stdout. Bei einem lokalen Deployment sichtet ein Entwickler diesen Stream im Vordergrund seines Terminals, um das Verhalten der App zu beobachten. […] Auf Staging- oder Produktionsdeploys werden die Streams aller Prozesse von der Laufzeitumgebung erfasst, mit allen anderen Streams der App zusammengefasst und zu einem oder mehreren Zielen geleitet, zur Ansicht oder langzeitigen Archivierung. Diese Archivierungsziele sind für die App weder sichtbar noch konfigurierbar – sie werden vollständig von der Laufzeitumgebung aus verwaltet."

Was hier zitiert wird, ist im Kern der Logging-Anteil des Observability-Dreiklangs bestehend aus Metriken, Tracing und eben Logging. Die Logging-Instrumentierung ist dabei für Entwickler recht einfach und funktioniert meist programmiersprachenspezifisch aber grundsätzlich nach dem folgendem in Python veranschaulichtem Prinzip.

Oft muss hierzu eine Logging-Bibliothek importiert werden, die meist sogenannte Log-Level wie bspw. Debug, Info, Warning, Error, Fatal, usw. definiert. Während die Anwendung ausgeführt wird, wird meist über eine Umgebungsvariable ein Loglevel gesetzt, z. B. INFO. Alle Logaufrufe oberhalb dieses Loglevels werden dann in ein Logfile geschrieben. 

import logging
logging.basicConfig(filename='example.log', level=logging.DEBUG)
logging.debug(’Performing user check')
user = “Nane Kratzke”
logging.info(f'User { user } tries to log in.')
logging.warning(f'User { user } not found')
logging.error(f'User { user } has been banned.')

Zeile 5 würde bspw. folgenden Eintrag in einer Logdatei erzeugen:

INFO 2022-01-27 16:17:58 – User Nane Kratzke tries to log in

Bei einer 12-Faktor-App würde dieses Logging so konfiguriert werden, dass zu loggende Ereignisse direkt auf Stdout (Konsole) geschrieben würden. Die Laufzeitumgebung (z. B: Kubernetes mit installiertem FileBeat-Service) kümmert sich dann um das Routing der Logdaten an die entsprechende Datenbank. Dies nimmt dem Entwickler Arbeit ab, die er ansonsten in eine Logverarbeitung investieren müsste.

Diese Art des Loggings ist über viele Programmiersprachen gut unterstützt und lässt sich bspw. mit dem ELK-Stack (oder anderen Logging-Stacks) hervorragend konsolidieren.

Strukturiertes Logging

Logging (anders als Distributed Tracing und Metrikerhebung) wird von Entwicklern häufig nicht einmal als Instrumentierung wahrgenommen und daher automatisch durchgeführt. Man kann diese Instrumentierung etwas systematisieren und zum sogenannten "strukturierten Logging" ausbauen. Auch hier ist das Prinzip eigentlich sehr einfach. Man loggt einfach keine Textzeilen wie

INFO 2022-01-27 16:17:58 – User Nane Kratzke tries to log in

stattdessen aber dieselbe Information in strukturierter Form, bspw. mittels JSON:

{„event“: „Log in“, „user“: „Nane Kratzke“, „result“: „not found“, “error”: “User banned” }

In beiden Fällen wird Text auf die Konsole geschrieben. Im zweiten Fall wird allerdings ein Format genutzt, dass besser auswertbar ist. Im Falle von

User Max Mustermann tries to log in

müsste bspw. der Text erst einmal analysiert werden, um den Nutzer zu bestimmen. Das ist im großen Maßstab aufwändig und kann bei vielen Logdaten auch sehr berechnungsintensiv werden kann.

Im Fall des strukturierten Loggings kann diese Information jedoch einfach aus dem JSON-Datenfeld "user" extrahiert werden. Insbesondere komplexere Auswertungen werden mit strukturiertem Logging dadurch wesentlich einfacher. Die Instrumentierung wird aber nicht nennenswert komplexer, insbesondere da es Logging Libraries für das strukturierte Logging gibt. Das Logging könnte dann bspw. so aussehen:

log12.error('Log in’, user=user, result='Not found’, reason='Banned’)

Die resultierenden Logfiles sind für Administratoren weiterhin lesbar (wenn auch etwas unhandlicher) aber wesentlich besser durch Datenbanken wie bspw. ElasticSearch verarbeit- und -analysierbar.

INFO 2022-01-27 16:17:58 – { „event“: „Log in“, „user“: „Max Mustermann“, „result“: „success“ }

Auch quantitative Metriken lassen sich auf diese Weise erfassen. Damit kann strukturiertes Logging somit auch für die erste Säule – der Erfassung quantitativer Metriken– genutzt werden.

log12.info('Open requests’, requests=len(requests))

INFO 2022-01-27 16:17:58 – { „event“: „Open Requests“, „requests“: 42 }

Und mit diesem Ansatz lassen sich letztlich auch Tracings erstellen. Für jede Transaktion, die ein verteiltes System durchläuft, wird beim Distributed Tracing eine sogenannte Trace ID erstellt. Die einzelnen Schritte sind sogenannte Spans. Auch diese erhalten eine ID (Span-ID). Die Span-ID wird dann mit der Trace-ID verknüpft und die Laufzeit gemessen und protokolliert. Auf diese Weise kann man den zeitlichen Verlauf von verteilten Transaktionen entlang von beteiligten Komponenten verfolgen und bspw. die Dauer einzelner Bearbeitungsschritte ermitteln.

An der Technischen Hochschule Lübeck wird hierfür gerade an einer Logging-Bibliothek (für Python) gearbeitet, die auch diese Tracing-Informationen mittels strukturiertem Logging abbilden kann. Auf diese Weise kann man mit nur einem Instrumentierungsansatz (dem strukturierten Logging) sowohl

• quantitative Daten (Metriken),
• qualitative Ereignisse (Logging) als auch
• Laufzeit-Informationen zwischen abhängigen Arbeitsschritten (Tracing)

erfassen. Das resultierende Observability-System reduziert sich damit von Abb. 2 zu Abb. 4.

Diese Art der Observability wurde an mehreren Anwendungsfällen erfolgreich in einem fleBeat-/elasticSearch-basierten Observability-Stack evaluiert.

1. Zum einen konnte nachgewiesen werden, dass eine solche Art des Loggings problemlos dazu genutzt werden kann, klassische Metrikerhebungen vorzunehmen. Hierzu wurden in mehreren Kubernetes-Clustern BlackBox-Metriken wie bspw. CPU, Memory, Storage für die Infrastruktur (Nodes) aber auch der "Nutzlast" (Pods) erfolgreich erfasst und ausgewertet (s. Abb. 5).
2. Zum anderen wurde ein High-Volume-Anwendungsfall untersucht. Es wurden dabei alle englischsprachigen Tweets auf dem öffentlichen Twitter-Stream geloggt. Hierbei wurden etwa 1 Mio. Events pro Stunde über einen Zeitraum von einer Woche geloggt und mittels FileBeat an eine ElasticSearch-Datenbank weitergeleitet. Die meisten Systeme werden weitaus weniger Events generieren (s. Abb. 6).
3. Daneben wird diese Art des Loggings mittlerweile durch den Autor in mehreren internen Systemen eingesetzt (u. a. webbasierte Entwicklungsumgebungen, QR-Code-Dienste und in E-Learning-Systemen zur Erfassung der Zugriffshäufigkeiten auf Lerninhalte und Lernverhalten).

Alle Anwendungsfälle haben dabei gezeigt, dass strukturiertes Logging sehr einfach in der Instrumentierung ist und sehr gut mit bestehenden Observability-Stacks harmoniert (insb. Kubernetes, Filebeat, ElasticSearch, Kibana).