Startseite

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 Felermeldungen "invalid date"

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

Invalid date, month cannot be 13

Im Logfile finden wir keine Informationen, wo der ungültige Wert her kommt. Am letzten Software-Update liegt es jedenfalls nicht.

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

Die Fehlermeldung kommt von einer vielfach genutzten Bibliothek, so dass der Fehler "überall" sein könnte. Um die Stelle zielgerichtet zu finden, statt raten zu müssen, würde ich gerne das Debug Logging aktivieren. Doch das kommt angesichts der erwarteten Lastspitze nicht in Frage.

Lösungsvorschlag

Deswegen schlage ich folgenden Kompromiss vor: Das Programm soll zwei Protokolldateien schreiben, und zwar

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 der_holzkopf locked after too many failed logins
2021-02-02 19:45:47 [3854] INFO prinzessin_lillifee unlocked account of der_holzkopf 
2021-02-02 19:48:06 [9854] ERROR Invalid date, month cannot be 13
2021-02-02 19:48:06 [0034] ERROR Invalid date, month cannot be 13

debug.log

2021-02-02 19:48:03 [9854] DEBUG Received checkout request with user=der_holzkopf, order=412515
2021-02-02 19:48:04 [9854] DEBUG User der_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 Invalid date, month cannot be 13
Stack Trace:
   jsontools.eu/converter/date line 112
   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 Invalid date, month cannot be 13
Stack Trace:
   jsontools.eu/converter/date line 112
   sqltech.nl/mysql/client/converter line 78
   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 die Problemursache ganz schnell erkennen. In diesem Fall ist es eine fehlerhafte Antwort von Paypal, ich habe die Stelle hervorgehoben.

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 einer Fehlermeldung zu erkennen.

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 Systemleistung zu machen.

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:

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.