Tail -f ist eine schlechte Idee

vorhergehende Artikel in: Java Komponenten sQLshell
23.10.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):

Screenshot 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:

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

Screenshot 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:

Screenshot 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:

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

Aktualisierung vom 23. Oktober 2022

Noch ein Nachsatz zur Analyse von Logdateien auf der Linux-Kommandozeile: Es ist natürlich ebenfalls möglich, in den entsprechenden Dateien bestimmte Muster zur besseren Hervorhebung einzufärben (sofern es das benutzte (Pseudo-)Terminal unterstützt) - wie das funktioniert wird zum Beispiel hier oder hier beschrieben. Wird eine entsprechende Kommandozeile

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

auf die für die Tests eingesetzte Logdatei angewendet, ergibt sich zum Beispiel im Gnome-Terminal folgendes Ergebnis:

Screenshot Anzeige einer Logdatei im Gnome-Terminal mit farblich hervorgehobenen Log-Kategorien

Artikel, die hierher verlinken

EpochDateFormat.java

31.10.2022

Nachdem ich neulich festgestellt habe - voller Verwunderung festgestellt - dass es keine Möglichkeit gibt, mittels der in Java zur Verfügung stehenden DateFormat-Implementierungen Unix-Epochs zu parsen und zu erzeugen, musste ich selbst zur Tastatur greifen...

OpenSource - lieben, hassen - oder beides?

31.07.2022

Ich habe neulich zwei verschiedene Ideen verfolgt, die mich beide dazu brachten, OpenSource-Projekte mit meinem Input zu veredeln. Dabei sah ich, was schlecht an OpenSource-Projekten ist und warum deren Existenz trotzdem eine richtig gute Sache ist!

Alle Artikel rss Wochenübersicht Monatsübersicht Github Repositories Gitlab Repositories Mastodon Über mich home xmpp


Vor 5 Jahren hier im Blog

  • I'm An Old Cowhand (Hot Club of Cowtown)

    12.02.2019

    Und wieder einmal etwas von Hot Club Of Cowtown

    Weiterlesen...

Neueste Artikel

  • LinkCollections 2024 I

    Nach der letzten losen Zusammenstellung (für mich) interessanter Links aus den Tiefen des Internet von 2023 folgt hier gleich die erste für dieses Jahr:

    Weiterlesen...
  • Neovim - die Reise geht weiter

    Ich habe mich wieder einmal hingesetzt nachdem das Problem der Autocompletion gelöst war und überlegt, welche Funktionen ich besonders häugin oder intensiv in der aktuellen IDE nutze um dann herauszufinden, wie und ob ich diese Funktionalitäten mit nvim ebenfalls erreichen könnte.

    Weiterlesen...
  • InfluxShell als Plugin für die sQLshell

    Ich habe in der Vergangenheit bereits darüber berichtet, wie ich Komponenten, die ursprünglich für die sQLshell entwickelt wurden angepasst habe, um ein Frontend für die Zeitreihendatenbank Influx zu schaffen.

    Weiterlesen...

Manche nennen es Blog, manche Web-Seite - ich schreibe hier hin und wieder über meine Erlebnisse, Rückschläge und Erleuchtungen bei meinen Hobbies.

Wer daran teilhaben und eventuell sogar davon profitieren möchte, muß damit leben, daß ich hin und wieder kleine Ausflüge in Bereiche mache, die nichts mit IT, Administration oder Softwareentwicklung zu tun haben.

Ich wünsche allen Lesern viel Spaß und hin und wieder einen kleinen AHA!-Effekt...

PS: Meine öffentlichen GitHub-Repositories findet man hier - meine öffentlichen GitLab-Repositories finden sich dagegen hier.