Möglichkeiten zur Echtzeit-Fehlererkennung in Logs

Dienstag, 9.3.2021

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

01.02.2021T08:41:41.141196 ERROR org.viadee.shopproject.logger
01.02.2021T08:41:41.224196 ERROR org.viadee.shopproject.db
01.02.2021T08:41:41.251196 WARN org.viadee.shopproject.payment
01.02.2021T08:41:41.269196 INFO org.viadee.shopproject.logger
01.02.2021T08:41:41.307196 WARN org.viadee.shopproject.db
01.02.2021T08:41:41.369196 WARN org.viadee.shopproject.db
01.02.2021T08:41:41.430196 ERROR org.viadee.shopproject.logger
01.02.2021T08:41:41.432196 INFO org.viadee.shopproject.db
01.02.2021T08:41:41.477196 ERROR org.viadee.shopproject.db
01.02.2021T08:41:41.564196 WARN org.viadee.shopproject.db
01.02.2021T08:41:41.592196 INFO org.viadee.shopproject.db
01.02.2021T08:41:41.612196 ERROR org.viadee.shopproject.crm
 
"Mit Unregelmäßigkeit": In der ersten Hälfte des Logs wie zuvor. In der zweiten Hälfte des Logs, loggt die "payment"-Klasse 4 mal wahrscheinlicher als zuvor. In dieser Klasse treten nur noch "ERROR"-Meldungen auf.
 
01.02.2021T08:41:50.681196 ERROR org.viadee.shopproject.payment
01.02.2021T08:41:50.770196 ERROR org.viadee.shopproject.crm
01.02.2021T08:41:50.774196 WARN org.viadee.shopproject.crm
01.02.2021T08:41:50.791196 INFO org.viadee.shopproject.crm
01.02.2021T08:41:50.821196 WARN org.viadee.shopproject.db
01.02.2021T08:41:50.856196 ERROR org.viadee.shopproject.crm
01.02.2021T08:41:50.912196 INFO org.viadee.shopproject.db
01.02.2021T08:41:50.927196 WARN org.viadee.shopproject.db
01.02.2021T08:41:50.944196 INFO org.viadee.shopproject.db
01.02.2021T08:41:50.996196 ERROR org.viadee.shopproject.payment
01.02.2021T08:41:51.036196 INFO org.viadee.shopproject.crm
01.02.2021T08:41:51.045196 ERROR org.viadee.shopproject.logger
 

Zur Analyse der Logs werden die Einträge in 5-Sekunden-Intervallen zu einem Bin hinzugefügt. Gezählt werden in diesen Intervallen die Anzahl von Meldungen der einzelnen Level und der einzelnen Klassen. Dadurch entsteht folgendes aggregiertes Log für den Fall ohne Auffälligkeiten:

Bin
INFOInBin
WARNInBin
ERRORInBin
paymentInBin
loggerInBin
crmInBin
dbInBin
1 59 53 83 46 50 41 58
2 71 66 72 49 45 54 61
...              
49 58 74 64 55 52 49 40

Bei einer plötzlich auftretenden Anomalie geht man davon aus, dass es einen Zusammenhang gibt zwischen der Menge einzelner ERROR-Meldungen in einem Bin und dem Zeitintervall. Zur Analyse wurde ein Generalisiertes Lineares Modell (GLM) genutzt, das untersucht, ob der Bin und die Klasse "payment" einen Einfluss auf die Auftritt-Wahrscheinlichkeit von "ERROR"-Leveln haben.

Aus dem Modellergebnis greifen wir uns eine relevante Zahl heraus: der p-Wert gibt an, ob ein Faktor einen signifikanten Einfluss auf das Ergebnis hat. Bei unserem Modell sagt ein niedriger p-Wert aus, dass es eine plötzliche Veränderung der Auftrittwahrscheinlichkeit von ERROR-Meldungen in der Klasse "payment" gibt. Wir können ihn als Wahrscheinlichkeit dafür betrachten, dass gerade alles normal läuft.

  • p-Wert beim Log ohne Auffälligkeiten: 0,921
  • p-Wert beim Log mit Auffälligkeiten: 0,000

Andere Modellergebnisse geben darüber hinaus Aufschluss darüber, ob es sich um einen plötzlicher Anstieg oder eine Abnahme handelt.

Die beschriebene Herangehensweise hat die Einschränkung, dass einzelne Klassen und Level zur Beobachtung hinzugefügt werden müssen. Der p-Wert, ab dem eine Eskalation ausgelöst werden soll, muss je Klasse eingestellt werden. Bei Änderungen im Code können auch Veränderungen der Logmeldungen-Verteilung auftreten, sodass der p-Wert nachjustiert werden muss.

Als nächsten Schritt kann die Erkennung von Anomalien einer künstlichen Intelligenz überlassen werden. Auch ein fest vorgegebenes statistisches Modell ist nicht notwendig. Stattdessen kann im regelmäßigen Betrieb ein Machine Learning Modell trainiert werden. Bei Abweichung von dieser ‚normalen‘ Verteilung von Meldungen – einer Anomalie – kann ein Eskalationsprozess angestoßen werden. Dies ist ein etabliertes Muster zum Einsatz von KI in automatisierten Geschäftsprozessen.

Eine solche Herangehensweise hat den Charme, dass in der Entwicklung gezielt mit der Implementierung von Logzeilen eine Eskalation provoziert werden kann, wenn z.B. bei einer Ausnahmebehandlung Unsicherheit entsteht. Genau diese Sonderfälle und Ausnahmen sind bei Systemtests kaum zu provozieren, sodass das gewünschte Verhalten im Zweifel erst im Produktivbetrieb geprüft werden kann. Insofern könnte der Fokus auf Anomalien und Sonderfälle in Produktion erheblich zum Qualitätsbewusstsein des Entwicklungsteams beitragen.

Die beschriebenen Analyseverfahren bieten bis dato ungesehene Möglichkeiten, Logmonitoring von Business Code zu ermöglichen. Es besteht die Möglichkeit, Aufwände für hochspezialisierte Monitoring-Lösungen zu vermeiden. Wenn Sie Interesse an einer intelligenten Logfile-Analyse haben, dann lassen Sie uns gemeinsam auf KI-Potentialanalyse gehen!


zurück zur Blogübersicht

Diese Beiträge könnten Sie ebenfalls interessieren

Keinen Beitrag verpassen – viadee Blog abonnieren

Jetzt Blog abonnieren!

Kommentare

Dr. Frank Köhne

Dr. Frank Köhne

Dr. Frank Köhne ist Beratender Manager bei viadee IT-Unternehmensberatung, Co-Leiter des F&E-Bereiches Data Science und zuständig für Hochschulkooperationen im Raum Münster. Er engagiert sich im Programm-Komitee für den NAVIGATE-Kongress.

Frank Köhne bei Xing  Frank Köhne auf Twitter  Frank Köhne auf LinkedIn