Caddy: php_fastcgi sends request for "GET index." to php-fpm

[AlexMax]

OS:

• Linux DESKTOP-52N20QO 5.5.10-200.fc31.x86_64 #1 SMP Wed Mar 18 14:21:38 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
• Fedora release 31 (Thirty One)

Version:

• Caddy: v2.0.0-beta.19 h1:6kbQ5jf/lWjD+o3uuq7rnfrvw+x5UU3tuwGpZsLKr7M=
• PHP: PHP 7.3.15

Trying to get some local development done, so I'm using Caddy as a local development server. I run Caddy as a user and PHP-FPM is running in the background as whatever user it tends to be.

What I'm getting on the other end is bizarre.

http://localhost:8080 {
    log {
        level DEBUG
    }

    root            * app/webroot
    php_fastcgi     127.0.0.1:9000
    file_server
}

This results in a "File not found" error screen when browsing to the local page, delivered by php-fpm. Looking in the access log on php-fpm results in a very strange log message:

127.0.0.1 -  23/Mar/2020:16:48:41 -0400 "GET /index." 404

Index dot. No .php at the end.

Here's a debug log of the request from Caddy's point of view:

2020/03/23 20:48:41.508 ERROR   http.log.access handled request {"request": {"method": "GET", "uri": "/", "proto": "HTTP/1.1", "remote_addr": "[::1]:32998", "host": "localhost:8080", "headers": {"User-Agent": ["Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:74.0) Gecko/20100101 Firefox/74.0"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"], "Accept-Language": ["en-US,en;q=0.5"], "Pragma": ["no-cache"], "Accept-Encoding": ["gzip, deflate"], "Connection": ["keep-alive"], "Upgrade-Insecure-Requests": ["1"], "Cache-Control": ["no-cache"]}}, "common_log": "::1 - - [23/Mar/2020:16:48:41 -0400] \"GET / HTTP/1.1\" 404 16", "latency": 0.000594888, "size": 16, "status": 404, "resp_headers": {"Server": ["Caddy"], "Status": ["404 Not Found"], "X-Powered-By": ["PHP/7.3.15"], "Content-Type": ["text/html; charset=UTF-8"]}}
2020/03/23 20:48:41.659 INFO    http.log.access handled request {"request": {"method": "GET", "uri": "/favicon.ico", "proto": "HTTP/1.1", "remote_addr": "[::1]:32998", "host": "localhost:8080", "headers": {"Cache-Control": ["no-cache"], "User-Agent": ["Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:74.0) Gecko/20100101 Firefox/74.0"], "Accept": ["image/webp,*/*"], "Accept-Language": ["en-US,en;q=0.5"], "Accept-Encoding": ["gzip, deflate"], "Connection": ["keep-alive"], "Pragma": ["no-cache"]}}, "common_log": "::1 - - [23/Mar/2020:16:48:41 -0400] \"GET /favicon.ico HTTP/1.1\" 200 15086", "latency": 0.005532169, "size": 15086, "status": 200, "resp_headers": {"Server": ["Caddy"], "Etag": ["\"q731upbn2\""], "Content-Type": ["image/vnd.microsoft.icon"], "Last-Modified": ["Thu, 12 Mar 2020 13:37:37 GMT"], "Accept-Ranges": ["bytes"], "Content-Length": ["15086"]}}

Any clue as to what this could be, or even what debugging steps I should be taking? At the very least It'd be nice to know what fastcgi parameters are being passed without having to break out Wireshark.

[francislavoie]

Do you mind trying beta 18, just to see if this is a regression? https://github.com/caddyserver/caddy/releases/tag/v2.0.0-beta.18

I think we might've broken something.

https://github.com/caddyserver/caddy/commit/f2ce81cc8b5adcd453566d292ac0b0b47fc64e99 might be the culprit

[AlexMax]

Switching to beta 18 the request appears to be less malformed:

127.0.0.1 -  23/Mar/2020:17:23:44 -0400 "GET /index.php" 404

However, it's still not actually finding the file in that directory:

opalexmax@DESKTOP-52N20QO deploy2 % ls app/webroot 
css  env-prod.html  favicon.ico  font  img  index.html  index.php  js  semantic

This is what the log tells me now:

2020/03/23 21:23:44.184 ERROR   http.log.access handled request {"request": {"method": "GET", "uri": "/", "proto": "HTTP/1.1", "remote_addr": "[::1]:33424", "host": "localhost:8080", "headers": {"User-Agent": ["Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:74.0) Gecko/20100101 Firefox/74.0"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"], "Accept-Language": ["en-US,en;q=0.5"], "Accept-Encoding": ["gzip, deflate"], "Connection": ["keep-alive"], "Upgrade-Insecure-Requests": ["1"], "Cache-Control": ["max-age=0"]}}, "common_log": "::1 - - [23/Mar/2020:17:23:44 -0400] \"GET / HTTP/1.1\" 404 16", "latency": 0.000621927, "size": 16, "status": 404, "resp_headers": {"Server": ["Caddy"], "Status": ["404 Not Found"], "X-Powered-By": ["PHP/7.3.15"], "Content-Type": ["text/html; charset=UTF-8"]}}
2020/03/23 21:23:44.184 ERROR   http.log.access handled request {"request": {"method": "GET", "uri": "/", "proto": "HTTP/1.1", "remote_addr": "[::1]:33424", "host": "localhost:8080", "headers": {"Accept-Encoding": ["gzip, deflate"], "Connection": ["keep-alive"], "Upgrade-Insecure-Requests": ["1"], "Cache-Control": ["max-age=0"], "User-Agent": ["Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:74.0) Gecko/20100101 Firefox/74.0"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"], "Accept-Language": ["en-US,en;q=0.5"]}}, "common_log": "::1 - - [23/Mar/2020:17:23:44 -0400] \"GET / HTTP/1.1\" 404 16", "latency": 0.000621927, "size": 16, "status": 404, "resp_headers": {"Status": ["404 Not Found"], "X-Powered-By": ["PHP/7.3.15"], "Content-Type": ["text/html; charset=UTF-8"], "Server": ["Caddy"]}}

The original bug aside, being unable to find the index file might be a misconfiguration on my part. But I don't really know, since I don't know which directory PHP is looking in for that index.php and why it can't be found.

[francislavoie]

I think you may need to specify the root like this: root * ./app/webroot, just a hunch. I'll try this out myself later this evening to confirm.

[mholt]

Actually I think his root directive is okay. In fact I think he could remove the *.

Now that is really weird, I wouldn't have expected a simple change like that to break... hmm... needs more tests. 🤔

[francislavoie]

Alright, awesome. I figured out what's going on.

So there's two different bugs here.

First, the regression with split which is broken in beta19. (FYI split is a subdirective of transport fastcgi, see https://caddyserver.com/docs/caddyfile/directives/reverse_proxy, and php_fastcgi is a shortcut to reverse_proxy with some added goodies).

Second is that Caddy is not resolving the relative path to an absolute path before passing it to fastcgi. This is apparent because if you just remove php_fastcgi and serve the PHP files as plaintext, they get served just fine with your config.

Thanks a ton for opening the issue @AlexMax, very much appreciated 😄

[mholt]

Oh... ha... that was dumb. 🙄

See 235357a. I had changed the field from string to []string, and it just so happens that len() is valid for both of those types, so... no compiler error... and I didn't even look to see where else SplitPath was used.

@AlexMax Try again? There should be build artifacts with the CI results you can download, if you prefer that.

The root path thing still needs addressing though. Edit: PR opened for that too. #3182

[fu-sen]

I was able to see this bug in beta 19. The OS also occurs on Windows + php-cgi.
In the case of the PHP built-in server, it works fine because the PHP side handles it,
but it partially ignores the settings in the Caddyfile. (That's Caddy's unintended use of PHP)

[AlexMax]

Thanks for the quick fix, but unfortunately, it does not appear to me that the issue is solved on my end. Is there a way I can turn on debug logging of FastCGI connections, so I can tell what parameters are being passed?

[DavidOliver]

I tried out beta 19 with PHP-FPM and was getting 'File not found' for PHP files. I'm now using 235357a as per here, and am successfully getting HTML responses from PHP.

[francislavoie]

@AlexMax what part of it isn't working for you? I don't think we have a way to log the fastcgi params currently. Maybe it could be added as a debug log line @mholt ?

[mholt]

Hm, yes, more details please. We're convinced this is fixed so if it's not we need to know more to be convinced otherwise.

And yes we can add a debug log line with all the env vars sent upstream. Or phpinfo() can print them in the meantime.

@DavidOliver: Thank you for testing and confirming! Appreciate your support!

[mholt]

Debug logging added in 745cb0e.

[fu-sen]

Build commit https://github.com/caddyserver/caddy/commit/9af05719bc99e36001d86c1f9af7015d856334b0 on Windows 10. Works fine, including PHP.

[AlexMax]

For some strange reason, I'm not getting any extra fastcgi logging in either 745cb0e or 9af0571. Did I have to change my config to enable it and see the FastCGI connection?

In any case, I finally broke out the Wireshark and I think I figured out what's going on. The FastCGI parameters passed by 9af0571 do in fact appear to be leading to real file locations, so any issue that I encounter beyond that is 100% a permissions problem on my end.

Still, given that my issue inadvertently led to two real fixes, I think this issue was productive. Thanks for your time.

[mholt]

Did I have to change my config to enable it and see the FastCGI connection?

Enable debug-level logging. In the Caddyfile, you can use:

{
    debug
}

at the top.

Glad you figured it out! Thanks for following up.