Opened 2 years ago

Closed 2 years ago

#2398 closed defect (wontfix)

Debug output is wrong for try_files directive with code as last argument

Reported by: Firm@… Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.18.x
Keywords: Cc:
uname -a: Linux inwin 5.15.0-50-generic #56-Ubuntu SMP Tue Sep 20 13:23:26 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.18.0 (Ubuntu)
built with OpenSSL 3.0.2 15 Mar 2022
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -O2 -ffile-prefix-map=/build/nginx-qDpDX0/nginx-1.18.0=. -flto=auto -ffat-lto-objects -flto=auto -ffat-lto-objects -fstack-protector-strong -Wformat -Werror=format-security -fPIC -Wdate-time -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -flto=auto -ffat-lto-objects -flto=auto -Wl,-z,relro -Wl,-z,now -fPIC' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --modules-path=/usr/lib/nginx/modules --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-compat --with-debug --with-pcre-jit --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_v2_module --with-http_dav_module --with-http_slice_module --with-threads --add-dynamic-module=/build/nginx-qDpDX0/nginx-1.18.0/debian/modules/http-geoip2 --with-http_gzip_static_module --without-http_browser_module --without-http_geo_module --without-http_limit_req_module --without-http_limit_conn_module --without-http_memcached_module --without-http_referer_module --without-http_split_clients_module --without-http_userid_module

Description (last modified by Firm@…)

Looks as debug_output mistakenly writes file check string in it's output while actually making right things.

nginx.conf:

user www-data;
worker_processes auto;
pid /run/nginx.pid;
include /etc/nginx/modules-enabled/*.conf;

events {
  worker_connections 768;
  debug_connection 127.0.0.1/32;
}

http {
# skipped default settings from package's nginx.conf
  server {
    listen 80;

    location / { return 403; }
    location /test {
      root /var/www/html;
      try_files $uri =404;
      proxy_pass http://127.0.0.1:8080;
    }
  }

  server {
    listen 8080;

    location /test {
      return 302 /test1;
    }
  }  
}

Create file /var/www/html/test/test.html (empty, using touch).

Then execute curl -v "_ttp://127.0.0.1/test/test.html", it returns 302 as expected.

Now execute curl -v "_ttp://127.0.0.1/test/test.html_", it returns 404 as expected too. And what debug log says:

2022/10/11 14:02:12 [debug] 12395#12395: *132 try files handler
2022/10/11 14:02:12 [debug] 12395#12395: *132 http script var: "/test/test.html_"
2022/10/11 14:02:12 [debug] 12395#12395: *132 trying to use file: "/test/test.html_" "/var/www/html/test/test.html_"
2022/10/11 14:02:12 [debug] 12395#12395: *132 trying to use file: "=404" "/var/www/html=404"
2022/10/11 14:02:12 [debug] 12395#12395: *132 http finalize request: 404, "/test/test.html_?" a:1, c:1
2022/10/11 14:02:12 [debug] 12395#12395: *132 http special response: 404, "/test/test.html_?"
2022/10/11 14:02:12 [debug] 12395#12395: *132 http set discard body
2022/10/11 14:02:12 [debug] 12395#12395: *132 HTTP/1.1 404 Not Found

Ok, let's create file /var/www/html=404 (empty, using touch). And execute curl -v "_ttp://127.0.0.1/test/test.html_" again. We get 404 although we have file named /var/www/html=404 and debug log still shows that nginx checks file existence:

2022/10/11 14:07:36 [debug] 12395#12395: *135 try files handler
2022/10/11 14:07:36 [debug] 12395#12395: *135 http script var: "/test/test.html_"
2022/10/11 14:07:36 [debug] 12395#12395: *135 trying to use file: "/test/test.html_" "/var/www/html/test/test.html_"
2022/10/11 14:07:36 [debug] 12395#12395: *135 trying to use file: "=404" "/var/www/html=404"
2022/10/11 14:07:36 [debug] 12395#12395: *135 http finalize request: 404, "/test/test.html_?" a:1, c:1
2022/10/11 14:07:36 [debug] 12395#12395: *135 http special response: 404, "/test/test.html_?"
2022/10/11 14:07:36 [debug] 12395#12395: *135 http set discard body
2022/10/11 14:07:36 [debug] 12395#12395: *135 HTTP/1.1 404 Not Found

Regards,
Alexander

Change History (2)

comment:1 by Firm@…, 2 years ago

Description: modified (diff)

comment:2 by Maxim Dounin, 2 years ago

Resolution: → wontfix
Status: new → closed

Thank you for your observation.

That's the debug logging, which is to be used by developers. It is expected to be usable for debugging, but might not accurately describe what actually happens, and usually requires looking into the code to understand the details.

In this particular case, debug logging does not try to distinguish between non-last and last try_files arguments, and simply logs argument evaluation details before any position-specific handling happens. This is expected to be good enough to understand the code flow.

Hope this helps.

Note: See TracTickets for help on using tickets.