Startseite

Konzept für Protokolldateien in Server-Anwendungen

Ich programmiere seit vielen Jahren Web basierte Server-Anwendungen unterschiedlichster Art. Als Softwareentwickler habe ich auf die produktiven Systeme sicherheitshalber keinen Zugriff. Deswegen muss ich Fehler in der Regel ausschließlich anhand von Protokolldateien analysieren.

Ich habe daher ein großes Interesse an möglichst vielen detaillierten Log-Meldungen. Dem gegenüber steht die Aufgabe des Betriebes, mit dem verfügbaren Speicherplatz auszukommen und gute Performance sicher zu 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 Felermeldungen "invalid date"

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

ERROR JSON parsing failed, invalid date, month cannot be 13

Leider konnten wir nicht herausfinden, was den Fehler auslöst. Es ist auch kein Zusammenhang zu den jüngsten Updates erkennbar.

Behebe den Fehler mit höchster Priorität bis spätestens morgen früh, denn dann beginnt unsere monatliche Werbeaktion mit den beliebten Schnäppchen.

Weil das Schicksal ein Schweinehund ist, stelle ich als Entwickler fest, dass diese Fehlermeldung aus einer Bibliothek kommt, die an gefühlt zweihundert Stellen im Programm verwendet wird. Was für ein Albtraum!

Kommt dir das bekannt vor? Dann solltest du unbedingt weiter lesen!

Mein Weg aus dem Sumpf

Hier kommt spontan der Wunsch auf, das Debug Logging zu aktivieren. Doch das kommt angesichts der erwarteten Lastspitze nicht in Frage. Wir brauchen einen guten Kompromiss, und der sieht so aus:

Das Programm soll zwei Protokolldateien schreiben, und zwar

Daraus ergibt sich folgendes: Im Normalfall (wenn alles gut läuft) werden beide Dateien überhaupt nicht beschrieben. Es gibt höchstens ab und zu mal eine Info, dass jemand sein Passwort offenbar vergessen hat. Die zweite Datei debug.log bleibt im Normalfall komplett leer.

Wenn jedoch ein Fehler auftritt, dann wird auch die Datei debug.log beschrieben. Und zwar nicht nur mit der eigentlichen Fehlermeldung, sondern mit bis zu 100 weiteren Details zur Vorgeschichte. Das Resultat könnte so ausehen:

server.log

2021-02-02 18:00:00 [0001] INFO Load new product catalog
2021-02-02 19:13:03 [1023] INFO User d.holzkopf locked after too many failed logins
2021-02-02 19:45:47 [3854] INFO User d.holzkopf unlocked by customer care agent m.lillifee
2021-02-02 19:48:06 [9854] ERROR JSON parsing failed, invalid date, month cannot be 13
2021-02-02 19:48:06 [0034] ERROR JSON parsing failed, invalid date, month cannot be 13

Da haben wir wieder die gefürchtete Fehlermeldung, sogar zweimal gleichzeitig. Aber dank der zweiten Protokolldatei lässt sich dieser Fehler nun sehr schnell auflären, denn da steht drin:

debug.log

2021-02-02 19:48:03 [9854] DEBUG Received checkout request with user=d.holzkopf, order=412515
2021-02-02 19:48:04 [9854] DEBUG User d.holzkopf selected payment method paypal for order 412515
2021-02-02 19:48:04 [9854] DEBUG Sending HTTP POST request to https://api-m.paypal.com/v2/payments/payment/PAY-2GG279541U471931P/execute
2021-02-02 19:48:06 [9854] DEBUG Received HTTP response status=200, body=
{
  "id": "2GG279541U471931P",
  "status": "COMPLETED",
  "status_details": {},
  "amount": {
    "total": "10.99",
    "currency": "EUR"
  },
  "final_capture": true,
  "seller_protection": {
    "status": "ELIGIBLE",
    "dispute_categories": [
      "ITEM_NOT_RECEIVED",
      "UNAUTHORIZED_TRANSACTION"
    ]
  },
  "seller_receivable_breakdown": {
    "gross_amount": {
      "total": "10.99",
      "currency": "EUR"
    },
    "paypal_fee": {
      "value": "0.33",
      "currency": "EUR"
    },
    "net_amount": {
      "value": "10.66",
      "currency": "EUR"
    }
  },
  "invoice_id": "412515",
  "create_time": "2021-02-02T19:48:04",
  "update_time": "2021-13-02T19:48:06",
  "links": [
    {
      "href": "https://api-m.paypal.com/v2/payments/captures/2GG279541U471931P",
      "rel": "self",
      "method": "GET"
    },
    {
      "href": "https://api-m.paypal.com/v2/payments/captures/2GG279541U471931P/refund",
      "rel": "refund",
      "method": "POST"
    },
    {
      "href": "https://api-m.paypal.com/v2/payments/authorizations/0VF52814937998046",
      "rel": "up",
      "method": "GET"
    }
  ]
}
2021-02-02 19:48:06 [9854] DEBUG Payment succeeded, updating payment transaction records in DB
2021-02-02 19:48:06 [9854] ERROR JSON parsing failed, invalid date, month cannot be 13
Stack Trace:
   jsonbuddy.com/parser/json/converter line 422
   jsonbuddy.com/parser/json/parser line 150
   stefanfrings.de/webshop/partner/paypal line 422
   stefanfrings.de/webshop/service/payment line 74
   stefanfrings.de/webshop/service/checkout line 823
   stefanfrings.de/webshop/facade/shop line 487
   webframeworker.com/worker/rest/handler line 99
------------------------------------------------------------------------------
2021-02-02 19:48:03 [0034] DEBUG Received checkout request with user=flotte.biene, order=412519
2021-02-02 19:48:03 [0034] DEBUG User flotte.biene selected payment method paypal for order 412519
2021-02-02 19:48:04 [0034] DEBUG Sending HTTP POST request to https://api-m.paypal.com/v2/payments/payment/PAY-2GG279333471931P/execute
2021-02-02 19:48:06 [0034] DEBUG Received HTTP response status=200, body=
{
  "id": "2GG279333471931P",
  "status": "COMPLETED",
  "status_details": {},
  "amount": {
    "total": "140.99",
    "currency": "EUR"
  },
  "final_capture": true,
  "seller_protection": {
    "status": "ELIGIBLE",
    "dispute_categories": [
      "ITEM_NOT_RECEIVED",
      "UNAUTHORIZED_TRANSACTION"
    ]
  },
  "seller_receivable_breakdown": {
    "gross_amount": {
      "total": "140.99",
      "currency": "EUR"
    },
    "paypal_fee": {
      "value": "0.99",
      "currency": "EUR"
    },
    "net_amount": {
      "value": "140.00",
      "currency": "EUR"
    }
  },
  "invoice_id": "412519",
  "create_time": "2021-02-02T19:48:04",
  "update_time": "2021-13-02T19:48:06",
  "links": [
    {
      "href": "https://api-m.paypal.com/v2/payments/captures/2GG279333471931P",
      "rel": "self",
      "method": "GET"
    },
    {
      "href": "https://api-m.paypal.com/v2/payments/captures/2GG279333471931P/refund",
      "rel": "refund",
      "method": "POST"
    },
    {
      "href": "https://api-m.paypal.com/v2/payments/authorizations/0VF5282537998046",
      "rel": "up",
      "method": "GET"
    }
  ]
}
2021-02-02 19:48:06 [0034] DEBUG Payment succeeded, updating payment transaction records in DB
2021-02-02 19:48:06 [0034] ERROR JSON parsing failed, invalid date, month cannot be 13
Stack Trace:
   jsonbuddy.com/parser/json/converter line 422
   jsonbuddy.com/parser/json/parser line 150
   stefanfrings.de/webshop/partner/paypal line 422
   stefanfrings.de/webshop/service/payment 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 kann ich als Entwickler ganz schnell erkennen, an welcher Stelle im Code der Fehler aufgetreten ist und was die Ursache war. Die "13" finde ich nämlich in der Antwort von Paypal wieder. Also kann ich dem Betrieb zurück melden, er soll das Ticket bitte nach Paypal weiter leiten. Der Fehler liegt nicht bei uns.

Da habe ich nochmal Glück gehabt! Wir wissen nicht nur wer den Schwarzen Peter hat, sondern wir haben alle nötigen Infos, um die Daten zu reparieren. Es geht kein Geld mehr verloren. Der Chef ist zufrieden und ich kann das Wochenende feiern.

Zugegeben, die obige Darstellung ist vereinfacht. Doch die echten Fälle sehen ähnlich aus - wenn auch mit deutlich mehr Log-Meldungen.

Da die Datei server.log nicht mit zu vielen Details geflutet wird, und in der Datei debug.log nur die Problemfälle aufgezeichnet werden, brauchen wir uns keine Sorgen um Speicherplatz und Sytemleistung zu machen. In einer Java Anwendung für QVC habe ich gemessen, dass dieses Verfahren ungefähr 5% CPU Leistung kostet. Verglichen mit dem Nutzen finde ich das völlig OK.

Implementierung

Bezüglich der Datei server.log gibt es nichts großartig zu erklären. Das ist eine ganz normale Protokolldatei mit einstellbarem Filter nach Log-Level. Für die zweite Datei müssen Vorkehrungen im Programmcode getroffen werden:

Da der Server viele Benutzer gleichzeitig bedient, brauchen wir eine Möglichkeit, die parallelen Vorgängen voneinander zu unterscheiden. In vielen Programmiersprachen können wir dazu die Thread-ID verwenden.

In Go gibt es keine Threads, sondern Go-Routinen, die haben aber leider keine ID. Stattdessen können wir ganz am Anfang bei jedem hereinkommenden HTTP-Request eine fortlaufende Nummer vergeben und diese dann im sogenannten "context" an alle Unterfunktionen durch reichen. Bei den obigen Log-Meldungen ist das die Nummer in den eckigen Klammern.

Das Prinzip lässt sich auf regelmäßige Hintergrund-Jobs erweitern. Der Scheduler, der z.B. regelmäßige Datenpflege durchführt, könnte jedem Durchlauf eine neue Nummer geben.

Nun benutzen wir Thread-Lokale bzw. Context-spezifische FIFO Puffer mit einem Fassungsvermögen von 100 Log-Meldungen. Das heißt: Wenn das Programm gerade 20 Benutzer gleichzeitig bedient, dann hat es 20 solcher FIFO Puffer im Speicher. Jeder Thread (bzw. Go-Routine) sammelt dort die anfallenden Log-Meldungen für sich selbst. Sollte ein Puffer voll werden, fallen hinten die ältesten Meldungen heraus und gehen verloren. Nur wenn ein Fehler erkannt wird, dann wird der gesamte Pufferinhalt zusammen mit der eigentlichen Fehlermeldung und einem Stack-Trace in die Datei Debug.log geschrieben. Danach wird der Puffer geleert.

Zu beachten sind hierbei Effekte der Nebenläufigkeit. Insbesondere bei Go kann sich ein Request auf mehrere Go-Routinen aufteilen, die unter Umständen gleichzeitig in den Puffer schreiben. Man muss ihn also durch einen Mutex schützen.

Auch bei der Ausgabe in die Datei debug.log kann es zu zeitgleichen Schreibzugriffen kommen. Linux hat damit kein Problem, sofern die Ausgabe in einem zusammenhängenden Block passiert und dieser nicht größer als 4 Kilobyte ist. Andernfalls können die Ausgaben von parallelen Vorgängen durcheinander geraten.

Java verwendet standardmäßig einen recht großen Schreib-Puffer. Es kann daher durchaus passieren, dass die benötigen Meldungen erst einige Minuten nach dem Auftreten des Fehlers in der Protokolldatei landen. Dies lässt sich durch einen Aufruf der flush() Methode beschleunigen, aber dadurch wird das ganze Programm stark ausgebremst. Deswegen empfehle ich, flush() nur nach Fehlermeldungen zu benutzen - wenn überhaupt.

Ein weiterer zu berücksichtigender Aspekt ist, dass Bibliotheken oft andere Logger-Klassen verwenden, als die eigene. Dem begegne ich je nach Programmiersprache/Framework unterschiedlich:

Wenn man so viele Daten im Speicher hält, besteht ein relativ hohes Risiko für ein Speicherleck. Es ist absolut notwendig, den Puffer am Ende des Threads (bzw. der Go-Routine) wieder frei zu geben. Teste deinen Code sehr gründlich, denn wenn dein neuer Logger das System regelmäßig lahm legt, wird er nicht akzeptiert. Einen zweiten Versuch wird man dir wohl kaum gestatten.

Ich bin zuversichtlich, dass man dieses Konzept in jeder Programmiersprache implementieren kann. Der Nutzen ist gewaltig: Maximale Information im Fehlerfall bei zugleich moderaten Kosten. Ich wende dieses Konzept seit 20 Jahren erfolgreich in sämtlichen Server-Anwendungen an.