Nginx Error Log Entries Written to Access.log – Troubleshooting

http-status-code-403loggingnginx

I'm trying to configure fail2ban for 403 errors from Nginx.
But for some reason my error.log file is empty and all 403 (and all 4XX, 5XX) errors are going to access.log.
However, I checked my config and it looks fine.

server {
    listen 80;
    server_name example.com;

    return 301 https://$host$request_uri;
}

server {
    listen 443;
    server_name example.com;

    access_log  /var/log/nginx/example.com/access.log;
    error_log   /var/log/nginx/example.com/error.log;

    ssl on;
    include /etc/nginx/conf.d/letsencrypt;
    include /etc/nginx/conf.d/verify-client;

    location / {
        include /etc/nginx/conf.d/403-if-not-verified;

        proxy_pass http://...;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "upgrade";
        proxy_set_header Host $http_host;

        proxy_set_header X-Real-IP $remote_addr;
        proxy_set_header X-Forward-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forward-Proto http;
        proxy_set_header X-Nginx-Proxy true;

        proxy_redirect off;
    }

    location ^~ /.well-known {
        root /usr/share/nginx/html/;
        allow all;
    }
}

Result:

root@raspberrypi:/var/log/nginx/example.com# ls -la
total 12
drwxr-xr-x  2 www-data adm 4096 Aug 28 09:55 .
drwxr-xr-x 12 www-data adm 4096 Aug 28 08:53 ..
-rw-r--r--  1 www-data adm 1417 Aug 28 09:55 access.log
-rw-r--r--  1 www-data adm    0 Aug 28 09:55 error.log

access.log:

192.168.1.1 - - [28/Aug/2021:09:46:29 +0300] "GET / HTTP/1.1" 403 135 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:91.0) Gecko/20100101 Firefox/91.0"
192.168.1.1 - - [28/Aug/2021:09:49:53 +0300] "GET / HTTP/1.1" 403 135 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:91.0) Gecko/20100101 Firefox/91.0"
192.168.1.1 - - [28/Aug/2021:09:50:53 +0300] "GET / HTTP/1.1" 403 135 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:91.0) Gecko/20100101 Firefox/91.0"
192.168.1.1 - - [28/Aug/2021:09:52:02 +0300] "GET / HTTP/1.1" 403 135 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:91.0) Gecko/20100101 Firefox/91.0"
192.168.1.1 - - [28/Aug/2021:09:52:30 +0300] "GET / HTTP/1.1" 403 135 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:91.0) Gecko/20100101 Firefox/91.0"

All the include configs contain just certificate-related stuff, nothing to do with logging.

upd. Also, I tried to put error_log directive inside of / location, but nothing has changed.

upd2. Tried changing log level to debug, got this:

2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL ALPN supported by client: h2
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL ALPN supported by client: http/1.1
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL ALPN selected: http/1.1
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL_do_handshake: -1
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL_get_error: 2
2021/08/28 11:07:32 [debug] 10257#10257: *134281 reusable connection: 0
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL handshake handler: 0
2021/08/28 11:07:32 [debug] 10257#10257: *134281 ssl new session: 95794EF3:32:165
2021/08/28 11:07:32 [debug] 10257#10257: *134281 ssl new session: 05E7BF5A:32:166
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL_do_handshake: 1
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL: TLSv1.3, cipher: "TLS_AES_128_GCM_SHA256 TLSv1.3 Kx=any Au=any Enc=AESGCM(128) Mac=AEAD"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 reusable connection: 1
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http wait request handler
2021/08/28 11:07:32 [debug] 10257#10257: *134281 posix_memalign: 01341900:256 @16
2021/08/28 11:07:32 [debug] 10257#10257: *134281 malloc: 012C1660:1024
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL_read: 464
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL_read: -1
2021/08/28 11:07:32 [debug] 10257#10257: *134281 SSL_get_error: 2
2021/08/28 11:07:32 [debug] 10257#10257: *134281 reusable connection: 0
2021/08/28 11:07:32 [debug] 10257#10257: *134281 posix_memalign: 013043B0:4096 @16
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http process request line
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http request line: "GET / HTTP/1.1"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http uri: "/"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http args: ""
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http exten: ""
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http process request header line
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Host: example.com"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:91.0) Gecko/20100101 Firefox/91.0"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Accept-Language: en-US,en;q=0.5"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Accept-Encoding: gzip, deflate, br"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Connection: keep-alive"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Upgrade-Insecure-Requests: 1"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Sec-Fetch-Dest: document"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Sec-Fetch-Mode: navigate"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Sec-Fetch-Site: none"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Sec-Fetch-User: ?1"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header: "Cache-Control: max-age=0"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 http header done
2021/08/28 11:07:32 [debug] 10257#10257: *134281 event timer del: 3: 215143200
2021/08/28 11:07:32 [debug] 10257#10257: *134281 generic phase: 0
2021/08/28 11:07:32 [debug] 10257#10257: *134281 rewrite phase: 1
2021/08/28 11:07:32 [debug] 10257#10257: *134281 test location: "/"
2021/08/28 11:07:32 [debug] 10257#10257: *134281 using configuration "/"

upd3. Permissions for both log files are the same, so means ok.

Best Answer

error.log contains detailed information about errors that happen on the server side, that is, HTTP error codes 5xx and other startup / internal errors.

It is not meant for logging all HTTP error status codes.

If you want to only log specific HTTP errors, you can create a second access_log entry with filtering. The example below is from nginx documentation with slight modification:

map $status $loggable {
    default 0;
    ~^4 1;
}

access_log /path/to/log combined if=$loggable;

The map is used to check status code and set $loggable variable accordingly. Default action is to not log, and if the HTTP status code starts with 4, then the request is logged.

Related Topic