Opened 5 years ago

Last modified 5 years ago

#1841 new defect

Dynamic access log and rewrites

Reported by: Peter Pramberger 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 Peter Pramberger 5 years ago.
Sample config
nginx.run​ (102 bytes ) - added by Peter Pramberger 5 years ago.
Sample command
nginx-1.16.1-debug.patch​ (3.9 KB ) - added by Peter Pramberger 5 years ago.
Debug patch
nginx-1.16.1-debug.log​ (15.8 KB ) - added by Peter Pramberger 5 years ago.
Debug log

Download all attachments as: .zip

Change History (5)

by Peter Pramberger, 5 years ago

Attachment: nginx.conf​ added

Sample config

by Peter Pramberger, 5 years ago

Attachment: nginx.run​ added

Sample command

by Peter Pramberger, 5 years ago

Attachment: nginx-1.16.1-debug.patch​ added

Debug patch

by Peter Pramberger, 5 years ago

Attachment: nginx-1.16.1-debug.log​ added

Debug log

comment:1 by Peter Pramberger, 5 years ago

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.