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)
Change History (5)
by , 5 years ago
Attachment: | nginx.conf added |
---|
comment:1 by , 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;
Sample config