Logging und Zustände

« | 05 Mar 2022 | »

Wenn man mit Hintergrunddiensten arbeitet, die sich schwerer debuggen lassen und an keine UI oder Konsole gebunden sind, bekommt ein uraltes Schema wieder eine große Bedeutung: Nämlich leicht lesbare Logdateien.

Basierend auf den Erfahrungen mit anderen Bibliotheken wurde im GATE Framework auch ein “etwas anderes” Logging-System integriert.

---

Viele Softwarekomponenten erachten Logs als Debugging-Feature, das keinen Standards zu folgen braucht.
Genau deshalb gibt es keinen mir bekannten übergreifenden Standard, was in einem Log-Eintrag genau drinnen stehen sollen.

Das fängt an mit reinen Textzeilen, wo jede Zeile eine unformatierte Nachricht sein kann und endet bei CSV oder anders separierten Textzeilen, die beliebig viele Felder beinhalten können.

Die meisten beginnen noch ziemlich gleich, nämlich mit einem Zeitstempel, doch schon die Frage, wie der aufgebaut sein soll, zieht zahlreiche Interpretationsunterschiede (z.B. UTC oder Lokalzeit) nach sich.
Auch gibt es häufig LOGLEVELS, die die nachfolgende Nachricht als INFO, WARNING oder ERROR qualifizieren sollen.
Und auch sie sind in jedem Projekt anders aufgebaut.

GATE LogEntry Definition

Das GATE Logging Framework definiert ein Interface, um eigene Logger zu implementieren und um diese auch “global” registrieren zu können.
Die vorbereitete Standardimplementierung ist ebenso Text-Datei-basiert, setzt jedoch Dateisperren ein, um ein gegenseitiges Überschreiben von mehreren Threads zu verhindern.

• Format:
  Die Felder in einer Logzeile werden durch TAB Zeichen getrennt, um weiter maschinenlesbaren Code zu generieren, der aber bei der Ausgabe auf der Konsole zumindest “halbwegs” formatiert ist und die Felder zumindest teilweise tabellarisch dargestellt werden.
• Zeit:
  Die Uhrzeit soll immer als ISO 8601 formatierte Lokalzeit dargestellt werden und eine Auflösung von Millisekunden haben. z.B.: 2022-03-05T23:59:59.999+01:00
  • Durch ISO 8601 lässt sich die lokale Zeit immer auf eine vergleichbare globale umrechnen und trotzdem gehen wichtige Infos, wie die lokale Datumsgrenze nicht verloren.
    Denn häufig macht es Sinn sehen zu können, ob Probleme eher am lokalen Morgen auftreten (z.B. Arbeitsschichtbeginn), oder nach Mitternacht, wenn oft Backups oder andere Mechanismen anspringen.
  • Eine Auflösung von Millisekunden erscheint mir in der Regel hoch genug, da oft auch Betriebssysteme gar keine höhere Auflösung zuverlässig liefern können. (Ausnahme bestätigen natürlich die Regel.)
• Prozess + Thread-ID:
  So lassen sich Log-Einträge wunderbar eindeutig einer Ausführung zuordnen. Prozess-IDs lassen Rückschlüsse auf Neustarts oder Abstürze zu, während Thread-IDs parallele Ausführungen identifizieren können.
• Log-Type (oder auch log-level):
  Hier habe ich mir einen neuen einfallen lassen, den man sonst selten antrifft, nämlich STATUS und dieser reiht sich wie folgt ein:
  • TRACE: Jede (auch noch so unwichtige) Aktion wird geloggt.
  • DEBUG: Alle internen Zwischenschritte werden geloggt, die vor allem dem Programmierer helfen sollen.
  • INFO: Logt alle logischen Schritte, damit ein Anwender den Ablauf eines Prozesses nachvollziehen kann.
  • STATUS: Logt alle großen “Meilensteine”, also Statusänderungen, die durch den Abschluss einer Teiloperation erreicht werden.
  • WARN: Logt Warnungen, also Fehler, die noch nicht sonderlich kritisch sind, aber trotzdem beobachtet werden sollten.
  • ERROR: Logt Fehler, die das Erreichen des Pogrammzieles verhindern können oder verhindert haben.
  • FATAL: Logt extrem kritische Fehler, die eine spätere “Verbesserung” der Situation ausschließen.
• Result-Code:
  Da fast alle GATE-APIs diese Codes nutzen, die Fehler einigermaßen abstrakt beschreiben können, werden sie auch hier geloggt.
• Native-Code:
  Zusätzlich zum generischen Result-Code kann optional der originale Fehler als Zahl ausgedrückt werden. Dieser hat dann je nach benutzter API eine andere Bedeutung, hilft aber beim Debugging. Meist stammt er aber von GetLastError() oder errno.
• Origin/Module:
  Name des Ursprungs oder des Modules, in dem das Log-Ereignis aufgetreten ist. Hier kann man eine Kombination aus Software-Paket und Klasse oder Funktion eintragen.
• Message:
  Diese Text Nachricht soll vor allem dem Endanwender konkret schildern, was genau passiert ist.
• Source/Location: Optional kann man dann noch Quellcode-Datei + Zeilennummer speichern, um den exakten Ort des Problems ausfindig machen zu können.

Bei der Initialisierung des Logging-Frameworks kann man auch konfigurieren, ab welchem Loglevel Daten mitgeschrieben werden sollen.

Und genau deshalb habe ich mich für den Loglevel STATUS als reduzierte Form von INFO entschieden, um nicht den Überblick in Detailinformationen zu verlieren.

Denn während Probleme (ab WARN) hoffentlich eher selten in Logs vermerkt sind, stellt das Level INFO oft sehr viele Details ein, die anfangs alle sinnvoll wirken, aber bei größeren Projekten gerne auswuchern.

Mit STATUS soll also nicht jede geöffnete Datei abgebildet werden, sondern nur das Erreichen von “operativ-relevanten” Zuständen.
Ein klassisches Beispiel wäre der “Operational” Zustand eines Dienstes, nachdem er zahlreiche Initialisierungsschritte und kleinere Hilfsdienste ausgeführt hat.

Im produktiven Betrieb lässt sich so einfach nach >= STATUS filtern um schnell einen Überblick zu bekommen.

Fazit

Der Microservice-Hosting Dienst gatesvc nutzt vorerst das “einfache” Dateilogging um seine Zustände nachvollziehbar niederzuschreiben und damit konnte ich vom Docker, Nanoserver bis hin zu BSD Daemon Startups wieder einige Bugs finden und bekämpfen.

Langfristig macht es vielleicht Sinn sich einen eigenen Logging-Dienst zu basteln, der die Logs systematischer und ohne Dateisperren verwaltet, doch die aktuelle Implementierung glänzt durch Einfachheit und Unabhängigkeit.

Mal sehen, wie sich das weiterentwickelt.

---

PS: Eines kann ich jedenfalls ausschließen:
Nämlich dass komplexe Fehlerfallen wie log4j bei mir Einzug erhalten, die ungefragt die zu loggende Nachricht auf Muster parsen und diese dann auch noch ausführen wollen.