Erst wenn ein Softwaresystem in Produktion genommen wird und seinen Dienst verrichtet, nützt es. Allerdings treten in Produktion immer wieder Probleme auf: Es tauchen Bugs auf, die während der Entwicklung entstanden sind, oder die Performanz des Systems ist nicht gut genug.
Um diese Probleme zu bemerken und anschließend analysieren zu können, müssen wir in das laufende System gucken und den Ablauf, der zum Fehler geführt hat, nachvollziehen können. Genau hierfür ist der Einsatz von Logging, Metriken und Tracing gedacht.
Dieser Artikel gibt einen Einstieg in die ersten beiden Themengebiete und erläutert, wie diese in einer Microservice-Architektur umgesetzt werden können.
Logging
Mit Logging hat der Entwickler die Möglichkeit, an ausgewählten Stellen ein Event mit Informationen über den Systemzustand zu erzeugen. Diese Events können nun außerhalb des Systems mitbekommen, gesammelt und ausgewertet werden. Durch die Auswertung der Logevents kann erkannt werden, ob das zu überwachende System fehlerfrei läuft. Wird dabei jedoch ein Fehler entdeckt, kann man über eine Benachrichtigung das Team darauf aufmerksam machen. Dieses kann den Fehler anschließend analysieren und sich um eine Behebung kümmern.
Natürlich besitzt nicht jedes Logevent die gleiche Wichtigkeit. Somit lohnt es sich, die vorhandenen Loglevel sinnvoll einzusetzen. In meinen Projekten haben sich dabei die folgenden Regeln bewährt:
- Logevents mit dem Level Error oder Fatal werden für Fehler oder Probleme genutzt, die einen manuellen Eingriff vom Team verlangen oder nur durch einen Neustart behoben werden können.
- Mit Warn werden Probleme gemeldet, von denen sich das System von selbst wieder erholen kann. Ein Beispiel ist ein Problem, das dadurch verursacht wurde, dass ein externes System aktuell nicht verfügbar ist.
- Info dient dazu, relevante Ereignisse zu loggen, die von Interesse sind und im normalen Ablauf des Systems entstehen. Dies umfasst zum Beispiel den Start eines Jobs oder die Abarbeitung eines Anwendungsfalls durch einen HTTP-Request.
- Um im Fehlerfall zusätzliche Informationen zur Hand zu haben, wird das Level Debug genutzt. Hiermit sollte wenigstens jede Anfrage und Antwort bei der Kommunikation mit einem Fremdsystem geloggt werden.
- Alle weiteren, vor allem für Entwickler, relevanten Events werden im Level Trace geloggt.
Alle so erzeugten Logevents müssen nun gesammelt werden. Das Sammeln in Dateien ist jedoch in einem verteilten System meistens nicht mehr praktikabel. Es gibt eine Menge von Services mit gegebenenfalls mehreren Instanzen pro Service. Somit ist bereits das Beschaffen aller Dateien zur Fehleranalyse relativ schwer.
Aus diesem Grund sollte in einem verteilten System ein zentraler Service für Logging betrieben werden. Die Kernaufgaben umfassen dabei das Speichern und Indexieren der Events sowie das Bereitstellen einer grafischen Oberfläche, um die Events analysieren zu können. Zudem müssen die Events eventuell vor dem Speichern noch transformiert oder harmonisiert werden.
Mit dem Elastic (früher ELK) Stack gibt es hier eine weit verbreitete Open-Source-Lösung, die sich in vielen meiner Projekte bewährt hat. Dieser Stack besteht dabei aus den drei Komponenten ElasticSearch, Kibana und Logstash und wird in manchen Fällen durch Redis ergänzt. ElasticSearch, eine Dokumentenorientierte Datenbank mit Volltextsuche, ist für die Speicherung aller Logevents verantwortlich. Kibana ist eine grafische Benutzeroberfläche auf ElasticSearch. In dieser kann man alle vorhandenen Logevents durchsuchen und filtern oder Visualisierungen auf diesen erzeugen.
Die Hauptaufgabe von Logstash ist es, schließlich die Logevents vom zu überwachenden Service zu ElasticSearch zu transportieren. Dazu kann Logstash zum Beispiel eine Datei überwachen und bei neuen Zeilen in dieser tätig werden oder man leitet die Standardausgabe des Service direkt in Logstash hinein. In beiden Fällen verringert der „Umweg“ über Logstash die Kopplung zwischen unserem System und dem eigentlichen Logservice. Dies ermöglicht das Starten des Service während der Entwicklung, ohne dass man als Entwickler auch einen Logservice starten muss.
Neben dem reinen Transportieren der Logevents bietet Logstash auch die Möglichkeit, die eingehenden Events zu transformieren. Da ElasticSearch JSON-Dokumente speichert, müssen alle Logevents vorher auch in solche umgewandelt werden. So können zum Beispiel in einem klassischen Log4j-Pattern-Layout geschriebene Events mittels Logstash in ihre Bestandteile zerlegt und anschließend als strukturiertes Dokument in ElasticSearch gespeichert werden. Zusätzlich zur Zerlegung müssen hier häufig auch noch mehrere Zeilen zu einem Logevent zusammengefasst werden. Vor allem Stacktraces führen zu mehrzeiligen Events.
Um alle diese potenziell fehleranfälligen Transformationen zu vermeiden, bietet es sich an, bereits direkt in der Applikation ein strukturiertes Dokumentenformat zu benutzen. Als Standard hat sich hier das Graylog Extended Log Format etabliert. Zudem findet man für fast jedes Logging-Framework auf der JVM einen GELF Appender.
Wird die Menge aller Logevents sehr groß, so besteht die Gefahr, dass Logstash oder auch ElasticSearch überfordert werden. Um dies zu verhindern, bietet es sich an, die Events zu puffern. Zu diesem Zweck wird häufig Redis als Queue genutzt und es entsteht ein Setup, wie in Abbildung 1 zu sehen.
Durch den Einsatz eines solchen Stacks befinden sich die Logevents aller Services nun in einem zentralen System und sind dort auswertbar. Genau an dieser Stelle zeigt sich jedoch die nächste Herausforderung für Logging in einem verteilten System: Die Abarbeitung eines Anwendungsfalls erfolgt häufig über mehrere Services hinweg. Bei einer Fehleranalyse möchte man jedoch einfach und schnell alle Logevents sehen, die zur Abarbeitung dieses Anwendungsfalls gehören.
In einem nicht-verteilten System konnte man sich in diesem Fall häufig mit einer Kombination von Datumsstempel, Thread-ID und der Kenntnis über die Aufrufreihenfolge von Methoden oder Komponenten behelfen. Bei einem verteilten System helfen diese Indikatoren jedoch in keinem Fall mehr.
Die Lösung für dieses Problem besteht darin, bei Beginn eines Anwendungsfalls oder Prozesses eine für diesen Vorgang eindeutige ID zu generieren. Anschließend sorgt man dafür, dass diese, auch Request- oder Trace-ID genannte, ID bei jedem Logevent mit ausgegeben wird. Üblicherweise wird hierzu bei Logging-Frameworks auf der JVM der Mapped Diagnostic Context (MDC) genutzt. In diesem legt man Schlüssel-Wert-Paare ab, die anschließend automatisch mit ausgegeben werden. Zu beachten ist hierbei, dass der MDC meistens auf ThreadLocals basiert. Wird also der Thread innerhalb des Systems gewechselt, muss man dafür sorgen, auch den MDC mit in den neuen Thread zu transferieren. Tut man dies nicht, geht der Kontext verloren.
Somit lassen sich die Logevents, die innerhalb des ersten Systems erzeugt werden, schon einmal zuordnen. Doch wie schafft man es nun, auch die Logevents der weiteren aufgerufenen Systeme zuzuordnen?
Um dieses Problem zu lösen, muss man dafür sorgen, bei Anfragen zu externen Systemen auch die ID zu übertragen. Für HTTP-Requests nutzt man hierzu einen Header und auch andere Protokolle, wie JMS oder Kafka, bieten in der Regel die Möglichkeit an, Header zu setzen und auszulesen.
Metriken
Metriken bilden im Gegensatz zu Logging keine Events ab, sondern ermöglichen einen Blick in den aktuellen Zustand des Systems. Eine Kerneigenschaft von Metriken ist dabei, dass diese sich verdichten lassen.
Spricht man über Metriken, so kann man grundsätzlich zwischen den folgenden drei Ebenen unterscheiden:
- Systemmetriken bilden die unterste Ebene. Auf dieser werden Werte wie CPU-Auslastung oder Netzwerksättigung gemessen. Die Erfassung findet somit zumeist außerhalb der eigentlichen Applikation auf dem Host statt.
- Die nächsthöhere Ebene bilden Anwendungsmetriken. Wie der Name bereits suggeriert, werden diese in der Applikation selbst erhoben. Typische Werte sind hier Anzahl und Dauer von verarbeiteten HTTP-Requests, die Auslastung von Threadpools oder die Anzahl der in der Applikation aufgetretenen Exceptions.
- Auf der dritten und höchsten Ebene werden fachliche Metriken, sogenannte Key Performance Indicators (KPI), erfasst. Diese werden vom Fachbereich definiert und bilden in der Regel einen direkt erfassbaren geschäftlichen Wert ab. Beispiele wären hier die Anzahl der verkauften Produkte des letzten Tages oder die Anzahl der Nutzer, die im letzten Schritt des Bestellprozesses abgesprungen sind.
Um Metriken für die Überwachung eines Systems einzusetzen, muss eine Reihe von Schritten durchgeführt werden (s. Abb. 2).
Zuerst müssen die relevanten Metriken überhaupt erhoben werden. Dazu muss man für jede Metrik festlegen, mit welchem Typ man diese erfassen möchte. Die meisten Frameworks auf der JVM, zum Beispiel Dropwizard Metrics, stellen hierzu fünf verschiedene Typen zur Verfügung.
- Eine Gauge stellt eine View über einen im System vorhandenen oder abfragbaren Wert dar. Dazu übergibt man bei der Erzeugung eine Funktion, die ausgeführt wird, wenn man die Gauge nach ihrem aktuellen Wert fragt. Somit enthält eine Gauge keinen eigenen Zustand. Beispiele für die Nutzung sind die Größe eines Caches oder die Anzahl verfügbarer Produkte in einem Shop.
- Ein Counter sieht von außen betrachtet genau wie eine Gauge aus. Im Unterscheid zu dieser besitzt ein Counter jedoch Zustand in Form des aktuellen Wertes. Um diesen zu ändern, bietet ein Counter Methoden zum Verringern und Erhöhen des Wertes an. Metriken wie die Anzahl aller bisher bearbeiteter HTTP-Requests lassen sich somit gut mit einem Counter abbilden.
- Um festzustellen, wie oft ein bestimmtes Event eingetreten ist, lässt sich ein Meter verwenden. Ein Meter muss somit bei jedem Auftritt des Events benachrichtigt werden. Zusätzlich zur reinen Benachrichtigung nutzt ein Meter noch den Zeitpunkt der Benachrichtigung, um einen zeitlichen Bezug abzubilden. Die Frage „Wie viele Suchen wurden in den letzten 5 Minuten durchgeführt?“ kann somit beantwortet werden.
- Um eine Verteilung von numerischen Werten abzubilden, nutz man ein Histogramm. Um dies sinnvoll zu tun, müssen sich die Werte jedoch vergleichen lassen. Eine Abbildung von zum Beispiel HTTP-Status-Codes ist somit nur bedingt sinnvoll. Um die Anzahl von Suchergebnissen darzustellen, eignet sich ein Histogramm jedoch hervorragend. Anschließend lassen sich dann Aussagen der Form „80 Prozent aller Suchen hatten weniger als 5 und 95 Prozent weniger als 2 Ergebnisse“ treffen.
- Die letzte Metrik ist der Timer. Ein Timer ist eine spezielle Form des Histogramms, da der gemessene numerische Wert eine Zeitspanne darstellt. Eine typische Frage, die somit beantwortet werden kann, ist zum Beispiel „Wie viele Prozent der Suchen dauerten maximal 5 Sekunden?“.
Systemmetriken lassen sich mit den passenden Tools, wie collectd, zumeist automatisch erfassen. Für Anwendungsmetriken nutzt man häufig eine Mischung aus Tools, die Metriken für Standardsoftwarekomponenten automatisch ermitteln, und einem Framework zur Erfassung von Metriken innerhalb der eigenen Applikation. Zur Erfassung der Metriken von Standardsoftwarekomponenten lässt sich zum Beispiel Telegraf verwenden. Als Framework zur eigenen Erfassung von Metriken hat sich für Java das bereits erwähnte Dropwizard Metrics als De-facto-Standard etabliert.
Die so erfassten Metriken sollten nun in einem zentralen System aggregiert werden. Um die Metriken dort hinein zu bekommen, haben wir zwei Möglichkeiten. Entweder jeder Service pusht die erfassten Metriken dort hinein oder das zentrale System holt sich die Daten bei den Services ab.
Für das Pushen ins zentrale System spricht vor allem, dass der Service selbst entscheiden kann, wann er Metriken pusht, und dass das zentrale System nicht alle Services kennen muss. Somit muss ein Service, der gerade unter Last ist, nicht zusätzlich auch noch seine Metriken ausliefern.
Beim Pullen hingegen muss nicht jeder Service das zentrale System kennen. Somit ist es einfacher möglich, das zentrale System zu wechseln oder sogar mehrere Metriksysteme zu nutzen. Zudem können die Intervalle, in denen die Metriken abgeholt werden, zentral gesteuert werden.
Natürlich ist auch eine Kombination möglich. So kann zum Beispiel pro Docker-Host ein Agent laufen, der die Metriken der Docker-Container pullt, um sie anschließend in das zentrale System zu pushen.
Nachdem die Metriken zu einem zentralen System gelangt sind, findet die Speicherung der Metriken statt. Bevorzugt werden dabei Datenbanken genutzt, die darauf optimiert sind, Zeitreihen zu speichern. Die beiden Produkte, die sich hier aktuell besonders hervortun, sind InfluxDB und Prometheus.
Um die so gesammelten Metriken anschließend grafisch aufzubereiten, wird ein Dashboard benötigt. Weit verbreitet ist hier Grafana, da es nahezu über alle gängigen Datenbanken gestülpt werden kann. Ein so erstelltes Dashboard zeigt Abbildung 3.
Neben dem Einsatz von Dashboards dient das „Complex event processing“ (CEP) dazu, aus der Menge aller Metriken eine abstrahierte Sicht zu erzeugen. So werden hier Metriken aus verschiedenen Layern und Services zu höherwertigen Metriken aggregiert, auf deren Basis anschließend Alarme erzeugt werden können. Es ist zum Beispiel nicht zwangsweise nötig, einen Alarm zu generieren, sollte eine einzelne Instanz eines Service ausfallen, solange der von diesem Service unterstützte Geschäftsprozess weiterhin erledigt werden kann. Sollten allerdings mehrere Instanzen ausfallen, muss natürlich ein Alarm generiert werden.
Die dritte Komponenten, die auf den gemessenen Metriken aufsetzt, ist die Anomaly Detection. Diese sorgt dafür, dass Trends in den Metriken gefunden werden und bei größeren Abweichungen Alarm geschlagen wird. Eine solche Analyse erkennt zum Beispiel, wenn die Anzahl der Checkouts in einem Onlineshop im Vergleich zu bisher gemessenen Werten ungewöhnlich niedrig ist. Somit lassen sich nicht nur harte Grenzen für Alarme, wie „Anzahl Checkouts kleiner fünf“, sondern auch relative Werte festlegen. Dadurch wird im Idealfall die Anzahl der versendeten Alarme deutlich verringert und das Vertrauen in das gesamte Metriksystem steigt.
Der letzte Schritt besteht darin, Alerting hinzuzufügen. Hierzu werden für wichtige Metriken Schwellwerte definiert. Werden diese Werte über- oder unterschritten, wird ein Alarm erzeugt, der anschließend über Kommunikationskanäle wie Slack, E-Mail oder SMS an die passenden Personen versandt wird. Bei geschickter Auswahl der Metriken und deren Schwellwerte lassen sich Probleme bereits pro aktiv erkennen und beheben, bevor merkliche Auswirkungen für den Nutzer des Systems entstehen.
Fazit
Fassen wir zusammen: Die Überwachung eines Systems besteht aus den beiden Bestandteilen Logging und Metriken.
Beim Logging sollten die vorhandenen Loglevel sinnvoll und konsistent eingesetzt werden und es bietet sich an, ein strukturiertes Format wie GELF zu loggen. Zudem bietet ein zentrales Logsystem die Möglichkeit, Logevents aus verschiedenen Services zu sammeln und gemeinsam zu analysieren. Weiterhin muss man dafür sorgen, dass zusammengehörige Logevents von verschiedenen Services korreliert werden können. Hierzu nutzt man eine Trace-ID, die man bei Remote-Calls dem aufgerufenen Service mitgibt.
Metriken ermöglichen es, einen Einblick in den aktuellen Zustand des Systems zu erlangen. Man unterscheidet dabei zwischen System-, Anwendungs- und fachlichen Metriken. Diese werden, über push oder pull, in einer Zeitreihendatenbank gespeichert und können anschließend ausgewertet werden. Durch Anomaly Detection, Complex Event Processing und Alarming ist es möglich, gezielt auf Probleme im System aufmerksam zu machen.
Neben diesen beiden Gebieten lohnt sich zudem noch ein Blick auf das Thema Tracing. Hierzu bietet der Artikel von Alexander Schwartz einen guten Einstieg, in dem er erklärt, wie Tracing mit Zipkin in Java umgesetzt werden kann.