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 ist die Datei debug.log leer. Wenn jedoch ein Fehler auftritt, wird die Fehlermeldung zusammen zusammen mit dem Stack Trace und weiteren Details zur Vorgeschichte in diese Datei geschrieben. 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 aufklä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 intensiv genutzten Java Enterprise Anwendung habe ich gemessen, dass dieses Verfahren weniger als 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.

Nun benutzen wir Thread-Lokale 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 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.

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.

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. Die FIFO Puffer sind dann dementsprechend Bestandteil des Contextes.

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 irgendwie 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.