Konzept für Protokolldateien in Server-Anwendungen

Als Softwareentwickler habe ich auf die produktiven Systeme sicherheitshalber keinen Zugriff, muss mich daher im Fehlerfall mit Auszügen aus Logfiles begnügen. Darum habe ich ein großes Interesse an möglichst detaillierten Log-Meldungen. Der Betrieb muss jedoch mit dem verfügbaren Speicherplatz auszukommen, den Datenschutz gewährleisten, und gute Performance sicher stellen. Debug-Meldungen sind daher in produktiven Umgebungen meistens deaktiviert.

Nun wird man an einem Freitag Morgen mit so einem Ticket begrüßt:

Betrifft: Vermehrte Fehlermeldungen "invalid date"

Seit ein paar Tagen schlagen viele Bestellungen in unserem Online Shop mit der folgenden Meldung fehl:

Shipping date 2024-05-10 is no working date

Das stimmt aber nicht, der 10. Mai ist ein Arbeitstag. Wir sehen auch andere Termine in ähnlichen falschen Meldungen. Die Kalender Tabelle ist mit allen Terminen für Deutschland korrekt befüllt, und wir haben auch einen Neustart versucht, weil wir ein Problem mit dem Cache vermuteten.

Bitte behebe den Fehler mit hoher Priorität, denn wir erwarten morgen wegen der Werbeaktion besonders viel Traffic.

Anhang: server.log

2024-05-08 18:00:00 [0014] INFO Load updated product catalog
2024-05-08 19:13:03 [1023] INFO User der_holzkopf locked after too many failed logins
2024-05-08 19:45:47 [3854] INFO Admin prinzessin_lillifee unlocked account of der_holzkopf 
2024-05-08 19:48:06 [7534] ERROR Shipping date 2024-05-10 is no working date
2024-05-08 19:48:06 [9854] ERROR Shipping date 2024-05-13 is no working date

Die Fehlermeldung kommt von meinem eigenen Code. Die Analyse vom Betrieb war völlig korrekt. Um den Fall weiter zu analysieren, möchte ich Debug Meldungen haben, doch das kommt angesichts der erwarteten Lastspitze nicht in Frage.

Lösungsvorschlag

Die Datei server.log enthält wie gehabt nur INFO, WARNING und ERROR Meldungen.
Nur im Fehlerfall wird zusätzlich die Datei debug.log beschrieben, ggf. mit Stack-Trace und vorherigen DEBUG Meldungen von dem fehlgeschlagenen Thread.

debug.log

2024-05-08 19:48:03 [7534] DEBUG Received checkout request for user=der_holzkopf, order=412515
2024-05-08 19:48:03 [7534] DEBUG Request Accept-Language is nl_NL,de_DE,en_GB
2024-05-08 19:48:03 [7534] DEBUG Shop locale is
2024-05-08 19:48:03 [7534] DEBUG System locale is US
2024-05-08 19:48:03 [7534] DEBUG Fall back to system locale US
2024-05-08 19:48:04 [7534] DEBUG User der_holzkopf selected payment method PAYPAL for order 412515
2024-05-08 19:48:04 [7534] DEBUG Sending HTTP POST request to https://api-m.paypal.com/v2/payments/payment/PAY-2GG279541U471931P/execute
2024-05-08 19:48:06 [7534] DEBUG Received HTTP response status=200, body= ...
2024-05-08 19:48:06 [7534] DEBUG Payment auth succeeded, updating order status in DB
2024-05-08 19:48:06 [7534] DEBUG Checking if 2024-05-10 is a working day in US
2024-05-08 19:48:06 [7534] ERROR Shipping date 2024-05-10 is no working date
Stack Trace:
   stefanfrings.de/webshop/service/fulfilment line 74
   stefanfrings.de/webshop/service/checkout line 823
   stefanfrings.de/webshop/facade/shop line 487
   webframeworker.com/worker/rest/handler line 99
----------------------------------------------------------
2024-05-08 19:55:18 [9854] DEBUG Received checkout request for user=flotte_biene, order=412516
2024-05-08 19:55:18 [9854] DEBUG Request Accept-Language is de_DE,en_US
2024-05-08 19:55:19 [9854] DEBUG Shop locale is 
2024-05-08 19:55:19 [9854] DEBUG System locale is US
2024-05-08 19:55:19 [9854] DEBUG Fall back to system locale US
2024-05-08 19:55:19 [9854] DEBUG User flotte_biene selected payment method VOUCHER for order 412516
2024-05-08 19:55:20 [9854] DEBUG The voucher 253466251 is valid
2024-05-08 19:55:22 [9854] DEBUG Payment auth succeeded, updating order status in DB
2024-05-08 19:55:23 [9854] DEBUG Checking if 2024-05-13 is a working day in US
2024-05-08 19:55:23 [9854] ERROR Shipping date 2024-05-13 is no working date
Stack Trace:
   stefanfrings.de/webshop/service/fulfilment line 74
   stefanfrings.de/webshop/service/checkout line 823
   stefanfrings.de/webshop/facade/shop line 487
   webframeworker.com/worker/rest/handler line 99

Anhand dieser zweiten Protokolldatei erkenne ich die Problemursache. Die Shop-Locale ist leer und die System-Locale ist "US". Eins von beiden hätte auf "DE" stehen müssen.

Zugegeben, die obige Darstellung ist vereinfacht. Aber in der Realität kommt es oft vor, dass man nachträglich Zugriff auf DEBUG Meldungen braucht, um die wahre Ursache eines Fehlers zu erkennen. In diesem Fall wären weitere Details in der ERROR Meldung nutzlos, weil man daran nicht erkennen wäre, wo das falsche Land "US" her kommt. Was ich wirklich oft brauche ist die Vorgeschichte zum Fehler.

Da im server.log nur die Problemfälle aufgezeichnet werden, brauche ich mir keine Sorgen um Speicherplatz und Systemleistung zu machen. Das ständige Generieren und Puffern von Debug Meldungen im RAM kostet ein bisschen, aber viel weniger, als wenn man sie ständig ausschreiben würde. Vor allem ist das besser, als wie ein dummer Ochse vor dem Berg zu stehen, weil man nicht einmal das Verhalten seines eigenen Codes erklären kann.

Implementierung

Für jeden Thread wird ein eigener Puffer mit einem Fassungsvermögen von bis zu 100 debug Meldungen verwendet. Sollte ein Puffer voll werden, fallen die ältesten Meldungen heraus. Nur wenn ein Fehler auftritt, wird der gesamte Pufferinhalt zusammen mit der eigentlichen Fehlermeldung und dem Stack-Trace (falls vorhanden) in die Datei debug.log geschrieben.

Hinweise zu Programmiersprachen:

In C++ mit Qt registriert man mit qInstallMessageHandler(myHandler) eine eigene Funktion welche die gepufferte Ausgabe macht. Als Puffer nutze ich eine Thread-lokale QList, die automatisch am Ende des Threads verfällt.
In Java benutzen die meisten Programme Apache Log4j oder Logback indirekt durch die Simple Log Facade (SLF4J). Als Puffer nutze ich eine Thread-lokale LinkedList, die automatisch am Ende des Threads verfällt.
- Bei Log4j 1.x erbe ich von AppenderSkeleton und implementiere die Methode append(). In der Datei log4j.xml konfiguriere ich den Appender.
- Bei Log4j 2.x erbe ich von AbstractAppender und implementiere die Methode append(). In der Datei log4j.xml konfiguriere ich den Appender.
- Bei LogBack erbe ich von AppenderBase<E> und implementiere die Methode append(). In der Datei logback.xml bzw. logback-spring.xml konfiguriere ich den Appender.
- Beim JBoss/Wildfly Server erbe ich von PeriodicRotatingFileHandler und überschreibe die Methode doPublish(). Dieser Code muss in ein Modul (nicht Deployment) platziert werden und in standalone.xml konfiguriert werden.
In Python erbe ich von logging.Handler und implementiere die Methode emit(). Mit logging.root.addHandler(meinHandler) sorge ich dafür, dass alle Ausgaben durch meinen Handler laufen. Als Puffer nutze ich eine Thread-Lokale deque.
In Go gibt es keine Threads. Dort bekommt jeder Request einen individuellen Kontext welcher eine eindeutige RequestID und einen Logger enthält, dessen Handler den Puffer implementiert. Am Ende des Request verfällt der Logger/Handler/Puffer automatisch zusammen mit dem Kontext. Außerdem registriere ich meinen Logger mit slog.SetDefault(), damit die wenigen Meldungen der Bibliotheken ebenfalls durch meinen Logger formatiert ausgegeben werden.

Ich bin zuversichtlich, dass man dieses Konzept in jeder Programmiersprache irgendwie implementieren kann. Und ich weiß aus vielfacher Erfahrung, dass es sich lohnt.