nginx try_files is causing doubled path components that make requests fail

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

Solution 1:

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.)