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:
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.
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.
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:
Ich bin zuversichtlich, dass man dieses Konzept in jeder Programmiersprache irgendwie implementieren kann. Und ich weiß aus vielfacher Erfahrung, dass es sich lohnt.