Symfony app under symlinked dir, subpath handled by file_server instead of php_fastcgi

1. Caddy version (caddy version):

v2.4.5 on Debian 10

2. How I run Caddy:

As a single systemd service.

a. System environment:

b. Command:

/usr/bin/caddy run --environ --config /etc/caddy/Caddyfile

(run by systemd)

c. Service/unit/compose file:

File located in /lib/systemd/system/caddy.service:

[Unit]
Description=Caddy
Documentation=https://caddyserver.com/docs/
After=network.target network-online.target
Requires=network-online.target

[Service]
Type=notify
User=caddy
Group=caddy
ExecStart=/usr/bin/caddy run --environ --config /etc/caddy/Caddyfile
ExecReload=/usr/bin/caddy reload --config /etc/caddy/Caddyfile
TimeoutStopSec=5s
LimitNOFILE=1048576
LimitNPROC=512
PrivateTmp=true
ProtectSystem=full
AmbientCapabilities=CAP_NET_BIND_SERVICE

[Install]
WantedBy=multi-user.target

d. My complete Caddyfile or JSON config:

Main caddyfile:

{
        email pierstoval@gmail.com
}

{{main dedicated server domain name}} {
        root * /var/www/html
        file_server
}

import vhosts/*

The problem is related to one single vhost file:

demo.orbitale.io {
        root * /var/www/demo.orbitale.io/www/
        encode gzip
        php_fastcgi unix//run/php/php8.0-fpm.sock {
                resolve_root_symlink
        }
        file_server
        tls {{tls custom email config}}
        log {
                output file {{log file path}} {
                        roll_size 512mb
                        roll_keep_for 720h
                }
        }
}

3. The problem I’m having:

When going to this website: https://demo.orbitale.io/faker_online/
Submitting the form should trigger an XHR Request to https://demo.orbitale.io/faker_online/fake/, but it returns a 404 not found.

4. Error messages and/or full log output:

Caddy’s log when curl-ing to the /fake/ url of the above app:

{"level":"error","ts":1634500209.361947,"logger":"http.log.access.log4","msg":"handled request","request":{"remote_addr":"109.29.59.153:58600","proto":"HTTP/2.0","method":"POST","host":"demo.orbitale.io","uri":"/faker_online/fake/","headers":{"Content-Type":["application/x-www-form-urlencoded"],"Dnt":["1"],"Sec-Fetch-Site":["same-origin"],"Cache-Control":["no-cache"],"Accept-Language":["fr,fr-FR;q=0.8,en-US;q=0.5,en;q=0.3"],"Referer":["https://demo.orbitale.io/faker_online/"],"Origin":["https://demo.orbitale.io"],"Content-Length":["66"],"Sec-Fetch-Dest":["empty"],"Pragma":["no-cache"],"Accept":["text/html"],"Accept-Encoding":["gzip, deflate, br"],"Te":["trailers"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:93.0) Gecko/20100101 Firefox/93.0"],"Sec-Fetch-Mode":["cors"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h2","proto_mutual":true,"server_name":"demo.orbitale.io"}},"common_log":"109.29.59.153 - - [17/Oct/2021:19:50:09 +0000] \"POST /faker_online/fake/ HTTP/2.0\" 404 0","user_id":"","duration":0.000339369,"size":0,"status":404,"resp_headers":{"Server":["Caddy"]}}

5. What I already tried:

I activated debug in the Caddyfile, and it allowed me to see that Caddy uses the file_server handler and not the php_fastcgi one:

oct. 17 19:50:58 piers caddy[21277]: {"level":"debug","ts":1634500258.6447387,"logger":"http.handlers.file_server","msg":"sanitized path join","site_root":"/var/www/demo.orbitale.io/www/","request_path":"/faker_online/fake/","result":"/var/www/demo.orbitale.io/www/faker_online/fake/"}

I tried adding the resolve_root_symlink directive in the php_fastcgi block, but it changed nothing.

I tried changing the PHP version from 8.0 to 7.4, nothing changed (I guess then it’s not a php-fpm issue).

I also tried removing the file_server directive, and what happens is interesting:
The request to /fake/ now returns an HTTP 200, but … the Symfony app isn’t called. And I know it because according to the source code (you can see it here), it shouldn’t return an empty HTTP 200 Response. The reponse must at least contain Results:<br>. Which isn’t the case here. That’s how I know the Symfony app isn’t even called.

EDIT: I also tried adding this to the vhost file:

php_fastcgi /faker_online unix//run/php/php8.0-fpm.sock {
    root /var/www/demo.orbitale.io/repos/faker_online/public/
}

The idea was to create a custom php_fastcgi with a matcher that would help redefining the root directive… But it didn’t work either.

6. Links to relevant resources:

It is worth noting that the app is under a symlink:

/var/www/demo.orbitale.io/www $ ls -Gg
total 0
lrwxrwxrwx 1 29 sept. 11  2019 faker_online -> ../repos/faker_online/public/

I have no idea on whether it can be a problem, nor how to fix it.

This server hosts several other PHP apps, including Symfony ones (like this one, which works fine, with the same Caddyfile config, the only difference is that the root points to the {project path}/public directory of the project, and no symlink is involved).

2 Likes

My hunch is that Caddy isn’t finding an index.php file to rewrite to. Do you have an index.php file at /var/www/demo.orbitale.io/repos/faker_online/public/index.php?

Can you post your full debug logs for a request you expect to work? Ideally it should show information about the rewrites happening.

I wrote a pretty in-depth explanation about a week ago on how the php_fastcgi directive works. Read this and see if the points align with the behaviour you’re seeing:

If you remove file_server, then there’s no directive that ends up handling the request, so you encounter Caddy’s default behaviour, which is to respond with an empty HTTP 200. That’s because “technically it worked as configured”, you didn’t configure Caddy to actually do anything with the request so it’s not actually an error on Caddy’s part.

I think in this case, you’ll definitely need this, otherwise Caddy won’t resolve the symlink before passing the request onto your php-fpm service.

2 Likes

I actually have an index.php file in the aforementioned public/ directory :no_mouth:

I also already looked multiple times at this specific explanation you link in order to understand better how the fastcgi directive works.

I’m gonna post some more debug output this morning (Paris timezone here), but what worries me is that the config isn’t really different than most PHP setup, and the only difference is that it’s a symlink-as-subdirectory :confused:

I’m gonna make more tests today and come back to you with as much info as I can :muscle:

1 Like

Some news, I tested something else:

Created a {root}/test/index.php file with only <?php echo "Hello!\n"; so that I know PHP is executed or not.
Vhost is still the same as in the first post

Running Caddy with debug activated.

Here are the curl calls results for the working part:

$ curl -i https://demo.orbitale.io/test/
HTTP/2 200
content-type: text/html; charset=UTF-8
server: Caddy
content-length: 7
date: Mon, 18 Oct 2021 08:37:34 GMT

Hello!

(so PHP is working)

Caddy server logs (sorry it’s a bit heavy, and I deliberately removed the TLS handshake because I think it’s useless):

oct. 18 08:38:35 piers caddy[21759]: {"level":"debug","ts":1634546315.346239,"logger":"http.handlers.rewrite","msg":"rewrote request","request":{"remote_addr":"176.31.100.117:45554","proto":"HTTP/2.0","method":"GET","host":"demo.orbitale.io","uri":"/test/","headers":{"User-Agent":["curl/7.64.0"],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h2","proto_mutual":true,"server_name":"demo.orbitale.io"}},"method":"GET","uri":"/test/index.php"}
oct. 18 08:38:35 piers caddy[21759]: {"level":"debug","ts":1634546315.34636,"logger":"http.reverse_proxy.transport.fastcgi","msg":"roundtrip","request":{"remote_addr":"176.31.100.117:45554","proto":"HTTP/2.0","method":"GET","host":"demo.orbitale.io","uri":"/test/index.php","headers":{"X-Forwarded-For":["176.31.100.117"],"X-Forwarded-Proto":["https"],"User-Agent":["curl/7.64.0"],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h2","proto_mutual":true,"server_name":"demo.orbitale.io"}},"dial":"/run/php/php8.0-fpm.sock","env":{"AUTH_TYPE":"","CONTENT_LENGTH":"","CONTENT_TYPE":"","DOCUMENT_ROOT":"/var/www/demo.orbitale.io/www","DOCUMENT_URI":"/test/index.php","GATEWAY_INTERFACE":"CGI/1.1","HTTPS":"on","HTTP_ACCEPT":"*/*","HTTP_HOST":"demo.orbitale.io","HTTP_USER_AGENT":"curl/7.64.0","HTTP_X_FORWARDED_FOR":"176.31.100.117","HTTP_X_FORWARDED_PROTO":"https","PATH_INFO":"","QUERY_STRING":"","REMOTE_ADDR":"176.31.100.117","REMOTE_HOST":"176.31.100.117","REMOTE_IDENT":"","REMOTE_PORT":"45554","REMOTE_USER":"","REQUEST_METHOD":"GET","REQUEST_SCHEME":"https","REQUEST_URI":"/test/","SCRIPT_FILENAME":"/var/www/demo.orbitale.io/www/test/index.php","SCRIPT_NAME":"/test/index.php","SERVER_NAME":"demo.orbitale.io","SERVER_PROTOCOL":"HTTP/2.0","SERVER_SOFTWARE":"Caddy/v2.4.5","SSL_CIPHER":"TLS_CHACHA20_POLY1305_SHA256","SSL_PROTOCOL":"TLSv1.3"}}
oct. 18 08:38:35 piers caddy[21759]: {"level":"debug","ts":1634546315.3468094,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"unix//run/php/php8.0-fpm.sock","request":{"remote_addr":"176.31.100.117:45554","proto":"HTTP/2.0","method":"GET","host":"demo.orbitale.io","uri":"/test/index.php","headers":{"User-Agent":["curl/7.64.0"],"Accept":["*/*"],"X-Forwarded-For":["176.31.100.117"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h2","proto_mutual":true,"server_name":"demo.orbitale.io"}},"headers":{"Content-Type":["text/html; charset=UTF-8"]},"status":200}
oct. 18 08:38:35 piers caddy[21759]: {"level":"info","ts":1634546315.3469555,"logger":"http.log.access.log4","msg":"handled request","request":{"remote_addr":"176.31.100.117:45554","proto":"HTTP/2.0","method":"GET","host":"demo.orbitale.io","uri":"/test/","headers":{"User-Agent":["curl/7.64.0"],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h2","proto_mutual":true,"server_name":"demo.orbitale.io"}},"common_log":"176.31.100.117 - - [18/Oct/2021:08:38:35 +0000] \"GET /test/ HTTP/2.0\" 200 7","user_id":"","duration":0.000810674,"size":7,"status":200,"resp_headers":{"Server":["Caddy"],"Content-Type":["text/html; charset=UTF-8"]}}

Now with the failing case

$ curl -i https://demo.orbitale.io/test/something
HTTP/2 404
server: Caddy
content-length: 0
date: Mon, 18 Oct 2021 08:41:17 GMT

The logs are quite different, since it doesn’t resolve the index.php file at all:

oct. 18 08:41:17 piers caddy[21759]: {"level":"debug","ts":1634546477.9844272,"logger":"http.handlers.file_server","msg":"sanitized path join","site_root":"/var/www/demo.orbitale.io/www/","request_path":"/test/something","result":"/var/www/demo.orbitale.io/www/test/something"}
oct. 18 08:41:17 piers caddy[21759]: {"level":"error","ts":1634546477.984569,"logger":"http.log.access.log4","msg":"handled request","request":{"remote_addr":"176.31.100.117:45580","proto":"HTTP/2.0","method":"GET","host":"demo.orbitale.io","uri":"/test/something","headers":{"User-Agent":["curl/7.64.0"],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h2","proto_mutual":true,"server_name":"demo.orbitale.io"}},"common_log":"176.31.100.117 - - [18/Oct/2021:08:41:17 +0000] \"GET /test/something HTTP/2.0\" 404 0","user_id":"","duration":0.000274313,"size":0,"status":404,"resp_headers":{"Server":["Caddy"]}}

I’m starting to think there might be a problem with my php_fastcgi configuration, especially the fact that the index.php isn’t at the root of the root directive, and it seems that so Caddy won’t try to find an index.php file in the requested path.

Is it possible to customize the site_root for a specific HTTP Request path?

1 Like

So for this one, the try_files will be looking for /var/www/demo.orbitale.io/www/index.php, i.e. your root plus the index.php as the last try in try_files.

From your ls earlier, I assume that doesn’t exist, which is why it doesn’t trigger a rewrite (you’d see a rewrite in the logs otherwise) and subsequently doesn’t get fed to php-fpm and falls through to file_server.

2 Likes

This topic was automatically closed after 30 days. New replies are no longer allowed.