Opened 3 months ago

Last modified 3 months ago

#1841 new defect

Dynamic access log and rewrites

Reported by: peterpramb@… Owned by:
Priority: major Milestone:
Component: nginx-core Version: 1.16.x
Keywords: access_log existence_failed Cc:
uname -a: Linux grpaidf1.domain 2.6.32-754.17.1.el6.x86_64 #1 SMP Thu Jun 20 11:47:12 EDT 2019 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.16.1 built by gcc 4.4.7 20120313 (Red Hat 4.4.7-23) (GCC) built with OpenSSL 1.1.1c 28 May 2019 TLS SNI support enabled configure arguments: --with-cc-opt='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic -Wno-unused -fPIC -I/usr/include/pcre -I/usr/include/zlib -I/opt/sits/openssl/openssl11/include' --with-ld-opt='-L/opt/sits/openssl/openssl11/lib64 -Wl,-rpath=/opt/sits/openssl/openssl11/lib64' --prefix=/opt/sits/nginx/nginx116 --conf-path=conf/nginx.conf --pid-path=run/nginx.pid --lock-path=run/nginx.lock --error-log-path=logs/error_global --http-log-path=logs/access_global --http-client-body-temp-path=run/client --http-proxy-temp-path=run/proxy --http-fastcgi-temp-path=run/fastcgi --http-uwsgi-temp-path=run/uwsgi --http-scgi-temp-path=run/scgi --user=nginx --group=nginx --with-debug --with-file-aio --with-pcre --with-pcre-jit --with-threads --with-http_ssl_module --with-http_v2_module --with-http_realip_module --with-http_addition_module --with-http_xslt_module=dynamic --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_auth_request_module --with-http_secure_link_module --with-http_degradation_module --with-http_slice_module --with-http_stub_status_module

Description

This is a follow up to #1051, which I still can reproduce in a current version.

When using dynamic access logs (that is variables in the file name) together with any sort of rewrites (in this case custom error pages) no access log is written when requesting something inexistant and errors like the following appear:

2019/08/27 23:17:45 [error] 8713#8713: *3 testing file "/opt/sits/nginx/nginx116/html/" existence failed (2: No such file or directory) while logging request, client: 127.0.0.1, server: localhost, request: "GET /plgr HTTP/1.0"

A minimal nginx config to reproduce is attached, as well as the debug output of a sample request.

After adding some debug messages it turned out that the error message is misleading and not actually caused by something inaccessible. Instead an empty path name is passed internally due to an extra loop run (that is there is nothing more to check), causing the error.

Here is the relevant (custom) debug output:

2019/08/27 23:17:45 [debug] 8713#8713: *3 http log handler
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_http_log_script_write(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_http_log_script_write(): ngx_http_map_uri_to_path(): path="/opt/sits/nginx/nginx116/html/50x.html"(len:39), root=len:30
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_http_log_script_write(): after_truncate: path="/opt/sits/nginx/nginx116/html/"(len:39)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_open_file_wrapper(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): ngx_openat_file(name="opt", fd=#12, mode=67584, create=0, access=0)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_open_file_wrapper(): for_loop_end: p="sits/nginx/nginx116/html/"(addr:0000000001CC0DE5), cp="/sits/nginx/nginx116/html/"(addr:0000000001CC0DE4), end=""(addr:0000000001CC0E07)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): ngx_openat_file(name="sits", fd=#14, mode=67584, create=0, access=0)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_open_file_wrapper(): for_loop_end: p="nginx/nginx116/html/"(addr:0000000001CC0DEA), cp="/nginx/nginx116/html/"(addr:0000000001CC0DE9), end=""(addr:0000000001CC0E07)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): ngx_openat_file(name="nginx", fd=#12, mode=67584, create=0, access=0)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_open_file_wrapper(): for_loop_end: p="nginx116/html/"(addr:0000000001CC0DF0), cp="/nginx116/html/"(addr:0000000001CC0DEF), end=""(addr:0000000001CC0E07)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): ngx_openat_file(name="nginx116", fd=#14, mode=67584, create=0, access=0)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_open_file_wrapper(): for_loop_end: p="html/"(addr:0000000001CC0DF9), cp="/html/"(addr:0000000001CC0DF8), end=""(addr:0000000001CC0E07)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): ngx_openat_file(name="html", fd=#12, mode=67584, create=0, access=0)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_open_file_wrapper(): for_loop_end: p=""(addr:0000000001CC0DFE), cp="/"(addr:0000000001CC0DFD), end=""(addr:0000000001CC0E07)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): enter
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): ngx_openat_file(name="", fd=#14, mode=2048, create=0, access=0)
2019/08/27 23:17:45 [debug] 8713#8713: *3 ngx_openat_file_owner(): ngx_openat_file(): failed (invalid file)
2019/08/27 23:17:45 [error] 8713#8713: *3 testing file "/opt/sits/nginx/nginx116/html/" existence failed (2: No such file or directory) while logging request, client: 127.0.0.1, server: localhost, request: "GET /plgr HTTP/1.0"
2019/08/27 23:17:45 [error] 8713#8713: *3 testing file "/opt/sits/nginx/nginx116/html/" existence failed (2: No such file or directory) while logging request, client: 127.0.0.1, server: localhost, request: "GET /plgr HTTP/1.0"
2019/08/27 23:17:45 [debug] 8713#8713: *3 run cleanup: 0000000001CCF878

Please note that this only happens with some sort of rewrites, not when for example accessing htdocs directly.

Why this access check is executed at all during access log writing is another question, though.

Attachments (4)

nginx.conf (885 bytes) - added by peterpramb@… 3 months ago.
Sample config
nginx.run (102 bytes) - added by peterpramb@… 3 months ago.
Sample command
nginx-1.16.1-debug.patch (3.9 KB) - added by peterpramb@… 3 months ago.
Debug patch
nginx-1.16.1-debug.log (15.8 KB) - added by peterpramb@… 3 months ago.
Debug log

Download all attachments as: .zip

Change History (5)

Changed 3 months ago by peterpramb@…

Sample config

Changed 3 months ago by peterpramb@…

Sample command

Changed 3 months ago by peterpramb@…

Debug patch

Changed 3 months ago by peterpramb@…

Debug log

comment:1 Changed 3 months ago by peterpramb@…

Possible fix:

--- nginx-1.16.1/src/core/ngx_open_file_cache.c.orig 2019-08-13 14:51:43.000000000 +0200
+++ nginx-1.16.1/src/core/ngx_open_file_cache.c      2019-08-28 17:11:24.835827809 +0200
@@ -647,7 +647,7 @@ ngx_open_file_wrapper(ngx_str_t *name, n
     }
 
     p = name->data;
-    end = p + name->len;
+    end = p + ngx_strlen(p);
 
     at_name = *name;
 
Note: See TracTickets for help on using tickets.