Möglichkeiten zur Echtzeit-Fehlererkennung in Logs

Beim Betrieb komplexer Softwaresysteme sind Fehler trotz guter Qualitätssicherung nicht immer vermeidbar. Als Beispiel greifen wir uns eine unangenehme Situation heraus: Der Product Owner oder Teamleiter von einem Shop-System wird von der Buchhaltung angerufen, weil in den letzten Tagen bei einigen Zahlungen keine Referenznummern mehr übertragen werden. Warum hat das nicht die IT, sondern erst der Fachanwender gemerkt? Schauen wir uns zunächst an, wie man solche Fehler in Produktion finden könnte und wo noch weitergedacht werden kann.

Überwachung von Logmeldungen anhand von Schwellenwerten

In Logfiles werden Aktivitäten von Anwendungen protokolliert. Beim Betrieb einer Webanwendung haben sie den praktischen Nutzen, dass Probleme und Fehler darin ersichtlich werden. Herausfordernd wird der Umgang allerdings bei Anwendungen, die sehr große Datenmengen an Logs erzeugen, die sich mit bloßem Auge oder der Suchfunktion im Editor nicht mehr überblicken lassen.

In professionalisierten Betrieben werden Logfiles daher an zentraler Stelle gesammelt und durchsuchbar gemacht. Den Job bis hierher übernehmen Produkte wie der ELK Stack (Elasticsearch, Logstash und Kibana) von Elastic. So sind Betrieb, Support und Entwicklung in die Lage versetzt, die Nadel im Heuhaufen zu finden. Im Beispiel mit den verschwundenen Zahlungsreferenzen kann nun nachgesehen werden, was der Grund für das Problem war. Womöglich wurden durch eine neue Funktionalität im Shop Feldwerte falsch übergeben oder ein Antwort-Code wurde falsch interpretiert. Das Problem kann gelöst werden.

Im Nachhinein kann im Logfile-Monitor ein Schwellenwert für verdächtige Log-Meldungen definiert werden, der eine Eskalation auslöst. Beispielsweise könnte eine E-Mail an den Entwicklungs-Support geschickt werden, wenn zweimal pro Stunde die verdächtige Meldung im Log erscheint. Durch solch starre Schwellenwerte ergibt sich jedoch die Gefahr von

• False Positives, also die Eskalation, obwohl es gar kein Problem gibt bzw.
• False Negatives, also keine Eskalation, obwohl es ein Problem gibt.

Diese reaktionäre Herangehensweise hat offensichtliche Nachteile. In den Augen der Fachanwender hat die IT ihre Systeme nicht im Griff, wenn sie von Fachbereichen auf Fehler hingewiesen werden muss. Für die Entwicklung entsteht die unschöne Situation, dass an Problemen erst gearbeitet werden kann, wenn der Schaden bereits passiert ist und der Lösungsdruck damit entsprechend groß ist.

Oberservability überwacht Metriken

Diese Einschränkungen versuchen ‚Observability‘-Produkte wie etwa Splunk, Elastic Observability oder honeycomb.io zu adressieren.

Hier werden Standardmetriken gemessen wie etwa der HTTP Status. Beispielsweise im Fall, dass ein Microservice nicht funktionsfähig ist, weil ein Migrationsskript nicht eingespielt wurde, wird dieser womöglich mit Status 500 (Internal Server Error) antworten. Der Nutzer sieht nur eine Fehlerseite.

Observabilityprodukte würden in diesem Moment ausschlagen und den Betrieb in Echtzeit warnen. Meist kommen Observabilityprodukte auch mit APM (Application Performance Management) Metriken. Hier werden Stellen, die (plötzlich) eine negative Performance aufzeigen, hervorgehoben. Fehler könnten sein, dass eine SQL-Abfrage lange dauert, weil das Statement bei zu großen Datenmengen nicht richtig implementiert ist oder eine Berechnung im Code bei einer speziellen Datenkonstellation zu lange dauert.

Überwachung von Businesscode

Aber was ist nun mit den verloren gegangenen Zahlungsreferenzen für die Buchhaltung? Durch Programmierfehler in Businesscode entstandene Fehlreaktionen der Systeme lassen zumeist keine Standardmetriken ausschlagen. Deshalb sieht es auch für Observability eher schlecht aus. Viel mehr wird der Fall mit einer Logmeldung und der Ausführung des fehlerhaften Codeblocks quittiert. Genau diese Logmeldung könnte allerdings zur Erkennung einer Unregelmäßigkeit genutzt werden. Um die Idee zu illustrieren, nehmen wir ein zufällig generiertes Log als Beispiel.

In diesem Beispiel loggen 4 Klassen ("logger", "db", "paymant" und "crm") auf 3 Leveln ("INFO", "WARN", "ERROR"). Testweise wurden 2 Logs erzeugt:

"Ohne Auffälligkeiten": Alle 4 Klassen loggen gleich häufig. Alle Loglevel treten gleichmäßig auf