Diagnoseprotokollierung mit dem NGINX-JavaScript-Modul

NGINX | 29. September 2020

Liam CrillySenior Director, Produktmanagement

Fehlerbehebung in der Produktionsumgebung ohne Anpassung des Fehlerprotokolls

Redaktion – Dieser Blog ist einer von mehreren, die sich mit Protokollierung mit NGINX und NGINX Plus befassen. Siehe auch:

Dies ist außerdem einer von vielen Blogbeiträgen über Anwendungsfälle für das NGINX-JavaScript-Modul. Die vollständige Liste finden Sie unter „Anwendungsfälle für das NGINX-JavaScript-Modul“.

NGINX unterstützt Unternehmen jeder Größe beim Betrieb ihrer geschäftskritischen Websites, Anwendungen und APIs. Unabhängig von der Größenordnung und der gewählten Bereitstellungsinfrastruktur ist der Produktivbetrieb nicht einfach. In diesem Artikel befassen wir uns mit nur einer der Herausforderungen einer Produktivbereitstellung: der Protokollierung. Genauer gesagt geht es um den Balanceakt, genügend detaillierte Protokolle für die Fehlerbehebung zu erfassen, ohne dabei von unnötigen Daten überschwemmt zu werden.

Grundlagen der Protokollierung

NGINX bietet zwei verschiedene Protokollierungsmechanismen: Zugriffsprotokollierung für Clientanfragen und Fehlerprotokollierung für den Fall, dass etwas schiefgeht. Diese Mechanismen sind sowohl in den HTTP- als auch in den Stream-Modulen (TCP/UDP) verfügbar, hier konzentrieren wir uns jedoch auf den HTTP-Datenverkehr. (Es gibt außerdem einen dritten Protokollierungsmechanismus, der die Debug-Schweregradstufe verwendet, auf den wir hier jedoch nicht eingehen.)

Eine typische standardmäßige NGINX-Protokollierungskonfiguration sieht wie folgt aus.

http {    
                      log_format  main  
                      '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';
 
    access_log /var/log/nginx/access.log main; # Log using the 'main' format
    error_log  /var/log/nginx/error.log  warn; # Log up to 'warn' severity level
    ...
}

Die log_format-Direktive beschreibt den Inhalt und die Struktur der Protokolleinträge, die erstellt werden, wenn die access_log-Direktive in die Konfiguration aufgenommen wird. Das obige Beispiel ist eine Erweiterung des von vielen Webservern verwendeten Common Log Format (CLF). Mit der error_log-Direktive legen Sie den Schweregrad der zu protokollierenden Meldungen fest, nicht jedoch den Inhalt oder das Format der Einträge, da diese fest vorgegeben sind. Mehr dazu im nächsten Abschnitt.

Weitere erwähnenswerte Aspekte der NGINX-Protokollierung sind:

Protokollierungsdirektiven werden automatisch von untergeordneten Konfigurationskontexten übernommen. Beispielsweise wird eine access_log-Direktive im http-Kontext auf alle server{}-Blöcke angewendet.
Eine Protokollierungsdirektive in einem untergeordneten Kontext überschreibt geerbte Direktiven.
Im selben Kontext können mehrere Protokollierungsdirektiven vorhanden sein. Beispielsweise könnten zwei access_log-Direktiven verwendet werden, um sowohl eine standardmäßige CLF-Protokolldatei als auch ein zweites, detaillierteres Protokoll zu erstellen.

Die Realität der Protokollierung in Produktionsumgebungen

Im Allgemeinen möchten wir das Zugriffsprotokoll für Analysen und Nutzungsstatistiken und das Fehlerprotokoll zur Fehlererkennung und -behebung verwenden. Der Betrieb eines Produktivsystems ist jedoch selten so einfach. Hier sind einige häufige Herausforderungen:

Zugriffsprotokolle enthalten nicht genügend Details für die Fehlerbehebung
Fehlerprotokolle enthalten auf der Protokollierungsstufe info zwar viele nützliche Details, sind für den normalen Betrieb jedoch zu ausführlich.
Das Format des Fehlerprotokolls ist fest vorgegeben und kann daher nicht angepasst werden, um besonders relevante Variablen aufzunehmen.
Einträge im Fehlerprotokoll enthalten nicht den Kontext der Anfrage und lassen sich nur schwer dem entsprechenden Eintrag im Zugriffsprotokoll zuordnen.

Darüber hinaus kann es beim Ändern der NGINX-Konfiguration, um den Detaillierungsgrad der Protokollierung in einer Produktionsumgebung zu erhöhen oder zu verringern, erforderlich sein, einen Änderungskontrollprozess zu durchlaufen und die Konfiguration erneut bereitzustellen. Das ist zwar vollkommen sicher, aber etwas umständlich, wenn ein akutes Problem untersucht wird, etwa: „Warum steigt die Zahl der 4xx- und 5xx-Fehler plötzlich an?“ Dieser Aufwand erhöht sich natürlich noch, wenn mehrere NGINX-Instanzen innerhalb eines Clusters denselben Datenverkehr verarbeiten.

Ein zweites Zugriffsprotokoll für Fehler verwenden

Das Format des Zugriffsprotokolls anzupassen, um die für jede Anfrage erfassten Daten anzureichern, ist ein gängiger Ansatz für erweiterte Analysen, lässt sich jedoch für Diagnose- oder Fehlerbehebungszwecke nur schlecht skalieren. Dem primären Zugriffsprotokoll zwei Aufgaben zuzuweisen, ist eine wenig zweckmäßige Lösung, da wir für die Fehlerbehebung in der Regel wesentlich mehr Informationen benötigen als für gewöhnliche Analysen. Das Hinzufügen zahlreicher Variablen zum primären Zugriffsprotokoll kann das Protokollvolumen durch Daten, die nur gelegentlich nützlich sind, drastisch erhöhen.

Stattdessen können wir ein zweites Zugriffsprotokoll verwenden und nur dann darin protokollieren, wenn ein Fehler auftritt, der eine Fehlerdiagnose erfordert. Die Direktive „access_log“ unterstützt die bedingte Protokollierung mit dem Parameter „if“ – Anfragen werden nur protokolliert, wenn die angegebene Variable einen Wert ungleich null und ungleich einer leeren Zeichenfolge ergibt.

map $status $is_error {    
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default 0;
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main;

Bei dieser Konfiguration übergeben wir die Variable $status an einen map-Block, um den Wert der Variable $is_error zu bestimmen. Dieser wird anschließend vom Parameter access_log der Direktive if ausgewertet. Wenn $is_error den Wert 1 ergibt, schreiben wir einen speziellen Protokolleintrag in die Datei access_debug.log.

Diese Konfiguration erkennt jedoch keine Fehler, die während der Verarbeitung einer Anfrage auftreten, letztlich aber behoben werden und daher zum Status 200 OK führen. Ein Beispiel hierfür ist der Lastenausgleich von NGINX zwischen mehreren Upstream-Servern. Tritt beim ausgewählten Server ein Fehler auf, leitet NGINX die Anfrage unter den durch die Direktive proxy_next_upstream festgelegten Bedingungen an den nächsten Server weiter. Solange einer der Upstream-Server erfolgreich antwortet, erhält der Client eine erfolgreiche Antwort, die mit dem Status 200 protokolliert wird. Aufgrund der Wiederholungsversuche dürfte die Benutzererfahrung jedoch beeinträchtigt sein, und möglicherweise ist nicht sofort ersichtlich, dass ein Upstream-Server fehlerhaft ist. Schließlich haben wir den Status 200 protokolliert.

Wenn NGINX versucht, Anfragen an mehrere Upstream-Server weiterzuleiten, werden deren Adressen alle in der Variable $upstream_addr erfasst. Dasselbe gilt für andere $upstream_*-Variablen, zum Beispiel $upstream_status, in der der Antwortcode jedes kontaktierten Servers erfasst wird. Wenn diese Variablen also mehrere Einträge enthalten, wissen wir, dass etwas schiefgelaufen ist – wahrscheinlich gibt es ein Problem mit mindestens einem der Upstream-Server.

Wie wäre es, wenn wir auch in die Datei access_debug.log schreiben, wenn die Anfrage an mehrere Upstream-Server weitergeleitet wurde?

map $upstream_status $multi_upstreams {    
"~,"    1; # Has a comma
    default 0;
} 

map $status $is_error {
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default $multi_upstreams; # If we tried more than one upstream server
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main; # Regular logging

Hier verwenden wir einen weiteren map-Block, um eine neue Variable ($multi_upstreams) zu erzeugen, deren Wert davon abhängt, ob $upstream_status ein Komma (,) enthält. Ein Komma bedeutet, dass mehrere Statuscodes vorhanden sind und somit mehrere Upstream-Server angesprochen wurden. Diese neue Variable bestimmt den Wert von $is_error, wenn $status keinem der aufgeführten Fehlercodes entspricht.

An diesem Punkt verfügen wir über unser reguläres Zugriffsprotokoll und eine spezielle Datei namens access_debug.log, die fehlerhafte Anfragen enthält. Allerdings haben wir das Protokollformat access_debug noch nicht definiert. Stellen wir nun sicher, dass die Datei access_debug.log alle Daten enthält, die wir zur Diagnose von Problemen benötigen.

JSON-Protokollierung mit JavaScript

Diagnosedaten in die Datei access_debug.log zu schreiben, ist nicht schwierig. NGINX stellt über 100 Variablen für die HTTP-Verarbeitung bereit, und wir können eine spezielle log_format-Direktive definieren, die so viele davon erfasst, wie wir benötigen. Allerdings hat es einige Nachteile, für diesen Zweck ein einfaches Protokollformat zu erstellen.

Es handelt sich um ein benutzerdefiniertes Format – Sie müssen einem Log-Parser beibringen, wie er es einliest.
Einträge können sehr lang und für Menschen bei der Live-Fehlerbehebung schwer lesbar sein
Um die Einträge interpretieren zu können, müssen Sie ständig das Protokollformat nachschlagen.
Nichtdeterministische Werte wie „alle Anfrage-Header“ können nicht protokolliert werden.

Diese Herausforderungen lassen sich bewältigen, indem wir Protokolleinträge mithilfe des NGINX-JavaScript-Moduls<.htmla> (njs) in einem strukturierten Format wie JSON schreiben. Das JSON-Format wird außerdem von Protokollverarbeitungssystemen wie Splunk, LogStash, Graylog und Loggly umfassend unterstützt. Indem wir die log_format-Syntax in eine JavaScript-Funktion auslagern, profitieren wir von der nativen JSON-Syntax und erhalten Zugriff auf alle NGINX-Variablen sowie auf zusätzliche Daten aus dem njs-„r“-Objekt.

js_import conf.d/json_log.js;js_set $json_debug_log json_log.debugLog;

log_format access_debug escape=none $json_debug_log; # Offload to njs 
access_log /var/log/nginx/access_debug.log access_debug if=$is_error;

Die js_import-Direktive gibt die Datei an, die den JavaScript-Code enthält, und importiert sie als Modul. Der Code selbst ist hier zu finden. Immer wenn wir einen Zugriffsprotokolleintrag schreiben, der das Protokollformat access_debug verwendet, wird die Variable $json_debug_log ausgewertet. Dazu wird die JavaScript-Funktion debugLog ausgeführt, wie in der js_set-Direktive definiert.

Diese Kombination aus JavaScript-Code und NGINX-Konfiguration erzeugt Diagnoseprotokolle, die wie folgt aussehen.

$ tail --lines=1 /var/log/nginx/access_debug.log | jq{
   "timestamp": "2020-09-21T11:25:55+00:00",
   "connection": {
      "request_count": 1,
      "elapsed_time": 0.555,
      "pipelined": false,
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c",
         "session_reused": false,
         "client_cert": {
            "status": "NONE"
         }
      }
   },
   "request": {
      "client": "127.0.0.1",
      "port": 443,
      "host": "foo.example.com",
      "method": "GET",
      "uri": "/one",
      "http_version": 1.1,
      "bytes_received": 87,
      "headers": {
         "Host": "foo.example.com:443",
         "User-Agent": "curl/7.64.1",
         "Accept": "*/*"
      }
   },
   "upstreams": [
      {
         "server_addr": "10.37.0.71",
         "server_port": 443,
         "connect_time": null,
         "header_time": null,
         "response_time": 0.551,
         "bytes_sent": 0,
         "bytes_received": 0,
         "status": 504
      },
      {
         "server_addr": "10.37.0.72",
         "server_port": 443,
         "connect_time": 0.004,
         "header_time": 0.004,
         "response_time": 0.004,
         "bytes_sent": 92,
         "bytes_received": 4161,
         "status": 200
      }
   ],
   "response": {
      "status": 200,
      "bytes_sent": 186,
      "headers": {
         "Content-Type": "text/html",
         "Content-Length": "4161"
      }
   }
}

Das JSON-Format ermöglicht es uns, Informationen zur gesamten HTTP-Verbindung (einschließlich SSL/TLS), zur Anfrage, zu den Upstreams und zur Antwort in separaten Objekten abzulegen. Beachten Sie, dass der erste Upstream (10.37.0.71) den Status 504 (Gateway Timeout) zurückgab, bevor NGINX den nächsten Upstream (10.37.0.72) ausprobierte, der erfolgreich antwortete. Der Timeout von einer halben Sekunde (angegeben als response_time im ersten Element des Objekts upstreams) ist für den Großteil der Gesamtlatenz dieser erfolgreichen Antwort verantwortlich (angegeben als elapsed_time im Objekt connection).

Hier ist ein weiteres Beispiel für einen (gekürzten) Protokolleintrag zu einem Clientfehler, der durch ein abgelaufenes Clientzertifikat verursacht wurde.

{   
"timestamp": "2020-09-22T10:20:50+00:00",
   "connection": {
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e",
         "session_reused": false,
         "client_cert": {
            "status": "FAILED:certificate has expired",
            "serial": "1006",
            "fingerprint": "0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d",
            "subject": "emailAddress=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US",
            "issuer": "CN=Demo Intermediate CA,OU=Demo CA,O=nginx,ST=CA,C=US",
            "starts": "Sep 20 12:00:11 2019 GMT",
            "expires": "Sep 20 12:00:11 2020 GMT",
            "expired": true,
         ...
   "response": {
      "status": 400,
      "bytes_sent": 283,
      "headers": {
      "Content-Type": "text/html",
      "Content-Length": "215"
   }
}

Zusammenfassung

Indem wir umfangreiche Diagnosedaten nur dann generieren, wenn ein Fehler auftritt, ermöglichen wir die Fehlerbehebung in Echtzeit, ohne dass eine Neukonfiguration erforderlich ist. Erfolgreiche Anfragen werden nicht beeinträchtigt, da der JavaScript-Code erst ausgeführt wird, wenn wir in der Protokollierungsphase einen Fehler erkennen, nachdem das letzte Byte an den Client gesendet wurde.

Die vollständige Konfiguration ist auf GitHub verfügbar – probieren Sie sie doch einfach in Ihrer Umgebung aus. Wenn Sie NGINX Plus noch nicht verwenden, starten Sie noch heute eine kostenlose 30-Tage-Testversion oder kontaktieren Sie uns, um Ihre Anwendungsfälle zu besprechen.