Score:2

nginx try_files is causing doubled path components that make requests fail

bi flag

I'm trying to make two adjacent folders, /var/www/site and /var/www/overlay@site coexist in a single site (for file permission and deployment tooling purposes).

I've tried adjusting a base configuration like (with HTTPS config removed):

server {
    server_name example.com;
    root /var/www/site;

    location / { try_files $uri $uri/ =404; }
}

into this, moving the root up a level:

server {
    server_name example.com;
    root /var/www;

    location / { try_files /site$uri /site$uri/ /overlay@site$uri /overlay@site$uri/ =404; }
}

but this makes the pages all return 404 for some reason I can't understand. If I enable debug logging, it appears to be trying to load e.g. /var/www/site/site/index.html, and I'm not sure where the doubled site is coming from.

Here's the debug.log for a request:

2021/12/18 14:56:22 [notice] 451123#451123: signal process started
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_do_handshake: -1
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_get_error: 2
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL handshake handler: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 ssl new session: 775CFEDA:32:169
2021/12/18 14:56:37 [debug] 451127#451127: *1 ssl new session: D9E5A8B9:32:169
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_do_handshake: 1
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL: TLSv1.3, cipher: "TLS_AES_256_GCM_SHA384 TLSv1.3 Kx=any Au=any Enc=AESGCM(256) Mac=AEAD"
2021/12/18 14:56:37 [debug] 451127#451127: *1 reusable connection: 1
2021/12/18 14:56:37 [debug] 451127#451127: *1 http wait request handler
2021/12/18 14:56:37 [debug] 451127#451127: *1 malloc: 00005590274BA790:1024
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_read: 399
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_read: -1
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_get_error: 2
2021/12/18 14:56:37 [debug] 451127#451127: *1 reusable connection: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 posix_memalign: 00005590274DBCB0:4096 @16
2021/12/18 14:56:37 [debug] 451127#451127: *1 http process request line
2021/12/18 14:56:37 [debug] 451127#451127: *1 http request line: "GET / HTTP/1.1"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http uri: "/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http args: ""
2021/12/18 14:56:37 [debug] 451127#451127: *1 http exten: ""
2021/12/18 14:56:37 [debug] 451127#451127: *1 posix_memalign: 00005590274DCCC0:4096 @16
2021/12/18 14:56:37 [debug] 451127#451127: *1 http process request header line
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "User-Agent: Mozilla/5.0+(compatible; UptimeRobot/2.0; http://www.uptimerobot.com/)"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "Accept-Language: en-US,en;q=0.8"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "Accept-Charset: ISO-8859-1,UTF-8;q=0.7,*;q=0.7"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "Connection: close"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "cache-control: no-cache"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "Referer: https://www.witchoflight.com"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "host: www.witchoflight.com"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header: "accept-encoding: gzip, deflate"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http header done
2021/12/18 14:56:37 [debug] 451127#451127: *1 event timer del: 3: 3230777386
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 rewrite phase: 1
2021/12/18 14:56:37 [debug] 451127#451127: *1 test location: "/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 using configuration "/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http cl:-1 max:1048576
2021/12/18 14:56:37 [debug] 451127#451127: *1 rewrite phase: 3
2021/12/18 14:56:37 [debug] 451127#451127: *1 rewrite phase: 4
2021/12/18 14:56:37 [debug] 451127#451127: *1 post rewrite phase: 5
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 6
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 7
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 8
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 9
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 10
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 11
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 12
2021/12/18 14:56:37 [debug] 451127#451127: *1 post access phase: 13
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 14
2021/12/18 14:56:37 [debug] 451127#451127: *1 try files handler
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script copy: "/www.witchoflight.com"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script var: "/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 trying to use file: "/www.witchoflight.com/" "/var/www/www.witchoflight.com/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script copy: "/www.witchoflight.com"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script var: "/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 trying to use dir: "/www.witchoflight.com/" "/var/www/www.witchoflight.com/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 try file uri: "/www.witchoflight.com/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 15
2021/12/18 14:56:37 [debug] 451127#451127: *1 content phase: 16
2021/12/18 14:56:37 [debug] 451127#451127: *1 content phase: 17
2021/12/18 14:56:37 [debug] 451127#451127: *1 content phase: 18
2021/12/18 14:56:37 [debug] 451127#451127: *1 open index "/var/www/www.witchoflight.com/index.html"
2021/12/18 14:56:37 [debug] 451127#451127: *1 internal redirect: "/www.witchoflight.com/index.html?"
2021/12/18 14:56:37 [debug] 451127#451127: *1 rewrite phase: 1
2021/12/18 14:56:37 [debug] 451127#451127: *1 test location: "/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 test location: ".gitignore"
2021/12/18 14:56:37 [debug] 451127#451127: *1 using configuration "/"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http cl:-1 max:1048576
2021/12/18 14:56:37 [debug] 451127#451127: *1 rewrite phase: 3
2021/12/18 14:56:37 [debug] 451127#451127: *1 rewrite phase: 4
2021/12/18 14:56:37 [debug] 451127#451127: *1 post rewrite phase: 5
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 6
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 7
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 8
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 9
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 10
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 11
2021/12/18 14:56:37 [debug] 451127#451127: *1 access phase: 12
2021/12/18 14:56:37 [debug] 451127#451127: *1 post access phase: 13
2021/12/18 14:56:37 [debug] 451127#451127: *1 generic phase: 14
2021/12/18 14:56:37 [debug] 451127#451127: *1 try files handler
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script copy: "/www.witchoflight.com"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script var: "/www.witchoflight.com/index.html"
2021/12/18 14:56:37 [debug] 451127#451127: *1 trying to use file: "/www.witchoflight.com/www.witchoflight.com/index.html" "/var/www/www.witchoflight.com/www.witchoflight.com/index.html"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script copy: "/www.witchoflight.com"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http script var: "/www.witchoflight.com/index.html"
2021/12/18 14:56:37 [debug] 451127#451127: *1 trying to use dir: "/www.witchoflight.com/www.witchoflight.com/index.html" "/var/www/www.witchoflight.com/www.witchoflight.com/index.html"
2021/12/18 14:56:37 [debug] 451127#451127: *1 trying to use file: "=404" "/var/www=404"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http finalize request: 404, "/www.witchoflight.com/index.html?" a:1, c:2
2021/12/18 14:56:37 [debug] 451127#451127: *1 http special response: 404, "/www.witchoflight.com/index.html?"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http set discard body
2021/12/18 14:56:37 [debug] 451127#451127: *1 uploadprogress error-tracker error: 404
2021/12/18 14:56:37 [debug] 451127#451127: *1 uploadprogress error-tracker not tracking in this location
2021/12/18 14:56:37 [debug] 451127#451127: *1 xslt filter header
2021/12/18 14:56:37 [debug] 451127#451127: *1 HTTP/1.1 404 Not Found
Server: nginx/1.18.0 (Ubuntu)
Date: Sat, 18 Dec 2021 19:56:37 GMT
Content-Type: text/html
Transfer-Encoding: chunked
Connection: close
Content-Encoding: gzip

2021/12/18 14:56:37 [debug] 451127#451127: *1 write new buf t:1 f:0 00005590274DD280, pos 00005590274DD280, size: 190 file: 0, size: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 http write filter: l:0 f:0 s:190
2021/12/18 14:56:37 [debug] 451127#451127: *1 http output filter "/www.witchoflight.com/index.html?"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http copy filter: "/www.witchoflight.com/index.html?"
2021/12/18 14:56:37 [debug] 451127#451127: *1 image filter
2021/12/18 14:56:37 [debug] 451127#451127: *1 xslt filter body
2021/12/18 14:56:37 [debug] 451127#451127: *1 http postpone filter "/www.witchoflight.com/index.html?" 00005590274DD478
2021/12/18 14:56:37 [debug] 451127#451127: *1 http gzip filter
2021/12/18 14:56:37 [debug] 451127#451127: *1 malloc: 0000559027619160:12288
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip alloc: n:1 s:5952 a:8192 p:0000559027619160
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip alloc: n:512 s:2 a:1024 p:000055902761B160
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip alloc: n:512 s:2 a:1024 p:000055902761B560
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip alloc: n:512 s:2 a:1024 p:000055902761B960
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip alloc: n:256 s:4 a:1024 p:000055902761BD60
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip in: 00005590274DD4A8
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip in_buf:00005590274DD350 ni:00005590262646C0 ai:100
2021/12/18 14:56:37 [debug] 451127#451127: *1 malloc: 000055902761C170:4096
2021/12/18 14:56:37 [debug] 451127#451127: *1 deflate in: ni:00005590262646C0 no:000055902761C170 ai:100 ao:4096 fl:0 redo:0
2021/12/18 14:56:37 [debug] 451127#451127: *1 deflate out: ni:0000559026264724 no:000055902761C17A ai:0 ao:4086 rc:0
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip in_buf:00005590274DD350 pos:00005590262646C0
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip in: 00005590274DD4B8
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip in_buf:00005590274DD3A0 ni:0000559026264E20 ai:62
2021/12/18 14:56:37 [debug] 451127#451127: *1 deflate in: ni:0000559026264E20 no:000055902761C17A ai:62 ao:4086 fl:4 redo:0
2021/12/18 14:56:37 [debug] 451127#451127: *1 deflate out: ni:0000559026264E5E no:000055902761C1EB ai:0 ao:3973 rc:1
2021/12/18 14:56:37 [debug] 451127#451127: *1 gzip in_buf:00005590274DD3A0 pos:0000559026264E20
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 0000559027619160
2021/12/18 14:56:37 [debug] 451127#451127: *1 http chunk: 123
2021/12/18 14:56:37 [debug] 451127#451127: *1 write old buf t:1 f:0 00005590274DD280, pos 00005590274DD280, size: 190 file: 0, size: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 write new buf t:1 f:0 00005590274DD588, pos 00005590274DD588, size: 4 file: 0, size: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 write new buf t:1 f:0 000055902761C170, pos 000055902761C170, size: 123 file: 0, size: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 write new buf t:0 f:0 0000000000000000, pos 0000559026237155, size: 7 file: 0, size: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 http write filter: l:1 f:1 s:324
2021/12/18 14:56:37 [debug] 451127#451127: *1 http write filter limit 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 posix_memalign: 0000559027618E60:512 @16
2021/12/18 14:56:37 [debug] 451127#451127: *1 malloc: 0000559027611C10:16384
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL buf copy: 190
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL buf copy: 4
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL buf copy: 123
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL buf copy: 7
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL to write: 324
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_write: 324
2021/12/18 14:56:37 [debug] 451127#451127: *1 http write filter 0000000000000000
2021/12/18 14:56:37 [debug] 451127#451127: *1 http copy filter: 0 "/www.witchoflight.com/index.html?"
2021/12/18 14:56:37 [debug] 451127#451127: *1 http finalize request: 0, "/www.witchoflight.com/index.html?" a:1, c:2
2021/12/18 14:56:37 [debug] 451127#451127: *1 http request count:2 blk:0
2021/12/18 14:56:37 [debug] 451127#451127: *1 http finalize request: -4, "/www.witchoflight.com/index.html?" a:1, c:1
2021/12/18 14:56:37 [debug] 451127#451127: *1 http request count:1 blk:0
2021/12/18 14:56:37 [debug] 451127#451127: *1 http close request
2021/12/18 14:56:37 [debug] 451127#451127: *1 http log handler
2021/12/18 14:56:37 [debug] 451127#451127: *1 geoip2 http log handler
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 000055902761C170
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 0000000000000000
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 00005590274DBCB0, unused: 1
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 00005590274DCCC0, unused: 1469
2021/12/18 14:56:37 [debug] 451127#451127: *1 close http connection: 3
2021/12/18 14:56:37 [debug] 451127#451127: *1 SSL_shutdown: 1
2021/12/18 14:56:37 [debug] 451127#451127: *1 reusable connection: 0
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 0000559027611C10
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 00005590274BA790
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 000055902750CEC0, unused: 8
2021/12/18 14:56:37 [debug] 451127#451127: *1 free: 0000559027618E60, unused: 384
Score:1
bi flag

The issue here turned out to be the /site$uri/ entries. They receive a redirect from the index rule, and so a request to e.g. /foo gets found at /site/foo/index.html, and that does an internal redirect to /site/foo/index.html, which then fails because it can't find /site/site/foo/index.html.

I was able to solve this by adding

location /site/ { try_files $uri =404; }
location /overlay@site/ { try_files $uri =404; }

but this seems to still have some quirks related to redirections. I get a more robust fix changing my overlay to work like:

server {
    server_name example.com;
    root /var/www/site;

    location / { try_files $uri $uri/ @overlay; }
    location @overlay {
        root /var/www/overlay@site;
        try_files $uri $uri/ =404;
    }
}

(Thanks to Paul Khuong helping me diagnose the issue.)

djdomi avatar
za flag
remember to accept your own answer else we will bw remember u til the end of life on zhis question
mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.