Updates

• 23. Oktober 2022

In meinem $dayjob musste ich vor einigen Monaten einmal einen Bug untersuchen. Das hat eine (für mich) überraschenende Tatsache ans Licht gebracht und mich wieder daran erinnert, was ich zum Thema Forensik gelernt habe: Man braucht Zeit und Ruhe, um das Problem und die hinterlassenen Zeichen gründlich zu untersuchen und so zum Kern des Problems vorzudringen.

In dem erwähnten Szenario ging es um einen Bug, der mit Hilfe von Log-Dateien untersucht werden sollte. Dabei stellte sich heraus, dass die Einträge in den Log-Dateien nicht chronologisch geordnet waren- manchmal kam ein Logeintrag mit einem früheren Zeitstemmpel in der Logdatei nach Einträgen mit späteren Zeitstempeln.

Wenn man Log-Dateien nicht gründlich analysiert, kann man sich davon täuschen lassen und Ereignisse in einer falschen Reihenfolge interpretieren!

Die Ursache dafür ist ein Implementierungsdetail in der dort verwendeten Log-Bibliothek Log4J gewesen - diese nimmt Aufträge zum Logging zunächst entgegen und reiht diese in einer Warteschlange ein - Ein anderer Thread entnimmt diese Aufträge und schreibt diese dann in eine Datei. Ist die Warteschlange voll, wenn versucht wird einen weiteren Auftrag anzuhängen, wird dieser an der Warteschlange vorbei direkt in die Datei geschrieben, was dazu führen kann, dass der resultierende Eintrag so viele Zeilen zu früh in der Log-Datei auftaucht, wie tief die Warteschlange war. Das ist das Standardverhalten - man kann versuchen, es durch entsprechende Konfiguration zu ändern, allerdings würde das den Rahmen dieses Artikels sprengen.

Ich habe eine weitere weit verbreitete Logging-Bibliothek names logback getestet und es hat sich gezeigt, dass auch diese dasselbe Verhalten zeigt, wie im nachfolgenden Screenshot hervorgehoben ist (für diesen Test habe ich fünf Threads gestartet, die jeweils 10 Log-Messages schreiben sollten):

Beispiel für zeitliche Verwirrung in einer mit logback erstellten Log-Datei

Das erklärt auch den Titel dieses Artikels - wenn ich mir einfach mittels tail -f die Log-Dateien ansehe, bekomme ich unter Umständen nicht die exakte zeitliche Reihenfolge der Logeinträge zu Gesicht. Daher ist es immer besser, tiefergehende Analysen mit entsprechenden Werkzeugen durchzuführen.

Ein solches Werkzeug kann schon die Linux-Kommandozeile sein, in der man Logdateien einfach mittels der Anweisung

sort -n -t" " -k2 /tmp/log.txt >/tmp/log_sorted.txt

entsprechend einer bestimmten Spalte sortieren kann - im vorliegenden Beispiel benutzen wir die durch Leerzeichen getrennte (-t" ") Spalte Nummer 2 (-k2) als Sortierkriterium.

Andere Möglichkeiten sind etwa die Verwendung spezialisierter Anwendungen wie etwa die sQLshell oder auf Elasticsearch basierende Installationen, die es erlauben, Filter und/oder Transformationen auf einzelne Spalten einer Log-Datei anzuwenden. Leider habe ich noch keinen Log-Viewer gefunden, bei dem man solche Transformationen auf einfache Art und Weise durchführen könnte.

Die zwei folgenden Screenshots zeigen die Inhalte der Log-Datei aus dem Beispiel in die sQLshell importiert - da die sQLshell anders als sort das Konzept von Timestamps versteht, müssen wir hier nicht nach der künstlich angelegten Spalte sortieren, sondern können dazu direkt das Timestamp-Feld benutzen:

Beispiel für zeitliche Verwirrung in einer mit logback erstellten Log-Datei - importiert in die sQLshell

Beispiel für korrekte Sortierung der Inhalte einer mit logback erstellten Log-Datei - importiert in die sQLshell

Man muss dazu - wie bereits oben angemerkt - nicht unbedingt die sQLshell bzw. deren Plugin LogAnalyzer benutzen - allerdings kann man erst einmal importiert diverse Komfortfunktionalitäten nutzen - wie etwa das auf Regeln basierende Hervorheben bestimmter Spalten - hier demonstriert am Filtern nach Log-Leveln:

Beispiel für regelbasierte Hervorhebung bestimmter Inhalte einer mit logback erstellten Log-Datei in der sQLshell

Natürlich kann man in den Log-Dateien nach dem erfolgreichen Import auch mittels SQL-Ausdrücken suchen:

Beispiel für Filterung bestimmter Inhalte einer mit logback erstellten Log-Datei in der sQLshell mittels SQL-Abfragesyntax

Aktualisierung vom 23. Oktober 2022

cat /tmp/log.txt|sed  "s,TRACE,$(tput setaf 1)&$(tput sgr0),g"|sed  "s,DEBUG,$(tput setaf 2)&$(tput sgr0),g"|more

Artikel, die hierher verlinken