Opened 3 weeks ago

Last modified 2 weeks 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 weeks ago.
Sample config
nginx.run (102 bytes) - added by peterpramb@… 3 weeks ago.
Sample command
nginx-1.16.1-debug.patch (3.9 KB) - added by peterpramb@… 3 weeks ago.
Debug patch
nginx-1.16.1-debug.log (15.8 KB) - added by peterpramb@… 3 weeks ago.
Debug log

Download all attachments as: .zip

Change History (5)

Changed 3 weeks ago by peterpramb@…

Sample config

Changed 3 weeks ago by peterpramb@…

Sample command

Changed 3 weeks ago by peterpramb@…

Debug patch

Changed 3 weeks ago by peterpramb@…

Debug log

comment:1 Changed 2 weeks 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.