Nginx ist ein verbreiteter Webserver, der auch weitere Funktionen anbietet und daher z.B. als Reverse Proxy laufen kann. Gerade da kann es passieren, dass etwas nicht richtig funktioniert – warum ist nicht ersichtlich. Im schlimmsten Falle liefert die hinter dem Reverse Proxy liegende Anwendung keine weitere Informationen und ist gar proprietär, sodass man dort wenig bis gar nicht eingreifen kann. Nginx bietet verschiedene Möglichkeiten zur Fehlersuche, die bedingt durch die Architektur teils etwas komplexer sind.
Grundlegende Anlaufstellen
Bevor man tiefer gehend mit dem Debug-Protokoll im nächsten Abschnitt sucht, würde ich es auf den einfacheren Wegen probieren. Das Access-Log liegt meist unter /var/log/nginx/access.log, sofern nicht anders definiert. In Containern wird es auf stdout geschrieben und lässt sich bei Docker beispielsweise mit docker logs -f $containerName abrufen. Darin werden alle Zugriffe protokolliert, sodass man z.B. den HTTP Statuscode sieht, der zurückgesendet wurde. Auch das Fehlerprotokoll (error.log) kann hilfreich sein. Nginx protokolliert dort Fehler im Kontext des Webservers, etwa nicht gefundene Dateien. CGI-Programme können ihre Logs dort ebenfalls weiterleiten. Je nach Konfiguration befinden die sich in einer anderen Logdatei/einem anderen Container. Ein Blick in die Protokolle der anderen involvierten Anwendungen schadet nicht, sofern die Anfragen dort ankommen – etwa der Anwendung, die hinter Nginx läuft.
Sollten die Protokolle nicht existieren oder leer sein, müssen sie ggf. zunächst aktiviert werden. Dafür bietet Nginx die Direktiven access_log und error_log. Bei Letzterem unterteilt der Webserver die Ereignisse in warn, error, crit, alert, emerg.1
error_log /var/logs/nginx/error.log warn;Debuglogs in Nginx
Sollte das nicht ausreichen, bietet Nginx Debuglogs. Sie protokollieren zahlreiche zusätzliche Informationen. Darunter beispielsweise die HTTP-Header und bei der Verwendung als Reverse Proxy mit dem ngx_http_proxy_module Modul ebenfalls die an das Backend-System weitergeleiteten Header. Es gibt nur einen Haken: Diese Debug-Protokolle können nicht ohne weiteres aktiviert werden, wie man es etwa aus (neueren) Apache 2.4 Versionen kennt. Dort lässt sich dynamisch das LogLevel für bestimmte Module deutlich feiner setzen, etwa so:
LogLevel error proxy:trace5Nginx muss dagegen mit Debug-Flag kompiliert werden, damit das debug Level zusätzlich zu den oben genannten zur Verfügung steht.2 Wie Nginx kompiliert wird, hatte ich in diesem Beitrag bereits gezeigt. Allerdings wollte ich die ganzen Abhängigkeiten nicht auf einem produktiven System installieren, nur um dort zeitweise die Debug-Logs nutzen zu können. Also habe ich mit folgendem Dockerfile alles in einen Container gepackt:
FROM debian:stable-slim
RUN apt-get update \
&& apt-get install -y gcc build-essential libpcre3-dev zlib1g-dev wget
WORKDIR /tmp
RUN wget -O nginx.tar.gz https://nginx.org/download/nginx-1.24.0.tar.gz \
&& mkdir /opt/nginx-src \
&& tar xf nginx.tar.gz -C /opt/nginx-src --strip-components=1
WORKDIR /opt/nginx-src
RUN ./configure --prefix=/opt/nginx --with-debug
RUN make install
ENTRYPOINT ["/opt/nginx/sbin/nginx", "-g", "daemon off;"]Passend dazu eine docker-compose.yml:
services:
nginx-debug:
build: .
mem_limit: 1G
volumes:
- ./nginx.conf:/opt/nginx/conf/nginx.conf
ports:
- 80:80Sowie die Nginx Konfigurationsdatei:
#user nobody;
worker_processes 1;
error_log /dev/stdout debug;
events {
worker_connections 1024;
}
http {
include mime.types;
default_type application/octet-stream;
log_format main '$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for"';
# alternativ /proc/1/fd/1
access_log /dev/stdout main;
sendfile on;
keepalive_timeout 65;
server {
listen 80;
server_name localhost;
location / {
proxy_pass http://backend-server;
}
}
}Das ist bewusst sehr minimalistisch gehalten und verwendet daher HTTP ohne Verschlüsselung, weil ich zur Eingrenzung des Problems möglichst vieles ausschließen wollte. Mit einer eigenen Zertifizierungsstelle signierte TLS-Zertifikate für HTTPS-Verbindungen gehörten auch dazu. Außerdem lässt sich dies so für andere Zwecke als Vorlage nutzen, ohne ggf. unnötige Module zu enthalten. Wer weitere benötigt, kann diese hinzufügen – etwa das http_ssl_module für TLS-Verbindungen. Eine Liste aller Module mit ihrem jeweiligen Argument, das zu Aktivierung an den configure Befehl übergeben werden muss, steht unter nginx.org bereit.3
Um das Image mit unserem selbst kompilierten Nginx zu erzeugen und einen Container zu starten, genügen die bekannten Docker Compose Befehle:
DOCKER_BUILDKIT=0 docker compose up --buildDOCKER_BUILDKIT verwende ich gerne, um die vollständige Ausgabe zu erhalten. Docker Compose ab V2 versucht Platz zu sparen, in dem längere Ausgaben nicht vollständig angezeigt werden. Das mag in Ordnung sein, wenn alles funktioniert. Gibt es jedoch Probleme, finde ich das äußerst ungeschickt, wenn nur Teile der Fehlermeldungen sichtbar sind. Vor allem wenn das nicht der ursächliche Fehler war, sondern ein Folgefehler, sodass die relevanten Meldungen nicht zu sehen sind.
Einschränkungen
Achtung: Das Debug-Protokoll schreibt sehr viele Einträge! Man sollte dies daher keinesfalls uneingeschränkt auf produktiven Systemen einsetzen. Im besten Falle findet man nichts mehr in den Logs. Im schlimmsten Falle schießt man es damit ab, weil durch das Protokollieren viel Last generiert wird. Außerhalb von (kleinen) Testumgebungen sollte daher unbedingt begrenzt werden, für welche Clients Debug-Protokolle angelegt werden. Dafür steht die Direktive debug_connection bereit:
events {
debug_connection 192.168.1.1;
}Was wird protokolliert?
Anbei ein Beispiel eines HTTP-Aufrufes. Ich habe wegen der Länge ein paar Zeilen gekürzt. Man sieht wie zuvor angesprochen sämtliche eingehende HTTP-Header und die an den Backend-Server weitergeleiteten. Würde man beispielsweise mit proxy_set_header einen Header nur für das Backend setzen, so erscheint dieser nicht bei http header – dies sind die vom Client eingehenden. Sondern weiter unten bei http proxy header.
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http request line: "GET /login?reqUrl=%2F HTTP/1.1"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http uri: "/login"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http args: "reqUrl=%2F"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http exten: ""
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 posix_memalign: 0000556B725264E0:4096 @16
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http process request header line
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Host: localhost"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/119.0"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Accept-Language: de,en-US;q=0.7,en;q=0.3"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Accept-Encoding: gzip, deflate, br"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Connection: keep-alive"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Cookie: LAVAGNA_SESSION_ID=xyz"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Upgrade-Insecure-Requests: 1"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Sec-Fetch-Dest: document"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Sec-Fetch-Mode: navigate"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Sec-Fetch-Site: none"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header: "Sec-Fetch-User: ?1"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http header done
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 event timer del: 3: 266058067
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 rewrite phase: 0
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 test location: "/"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 using configuration "/"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http cl:-1 max:1048576
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 rewrite phase: 2
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 post rewrite phase: 3
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 generic phase: 4
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 generic phase: 5
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 access phase: 6
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 access phase: 7
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 post access phase: 8
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 generic phase: 9
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 generic phase: 10
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http init upstream, client timer: 0
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 epoll add event: fd:3 op:3 ev:80002005
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http script copy: "Host"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http script var: "backend-server"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http script copy: "Connection"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http script copy: "close"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http script copy: ""
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http script copy: ""
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/119.0"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Accept-Language: de,en-US;q=0.7,en;q=0.3"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Accept-Encoding: gzip, deflate, br"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Upgrade-Insecure-Requests: 1"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Sec-Fetch-Dest: document"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Sec-Fetch-Mode: navigate"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Sec-Fetch-Site: none"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header: "Sec-Fetch-User: ?1"
nginx-debug-1 | 2023/11/01 17:46:14 [debug] 7#0: *1 http proxy header:
nginx-debug-1 | "GET /login?reqUrl=%2F HTTP/1.0
nginx-debug-1 | Host: backend-server
nginx-debug-1 | Connection: close
nginx-debug-1 | User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/119.0
nginx-debug-1 | Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8
nginx-debug-1 | Accept-Language: de,en-US;q=0.7,en;q=0.3
nginx-debug-1 | Accept-Encoding: gzip, deflate, br
nginx-debug-1 | Upgrade-Insecure-Requests: 1
nginx-debug-1 | Sec-Fetch-Dest: document
nginx-debug-1 | Sec-Fetch-Mode: navigate
nginx-debug-1 | Sec-Fetch-Site: none
nginx-debug-1 | Sec-Fetch-User: ?1
nginx-debug-1 |
nginx-debug-1 | "