v2.6.4 php-fpm gets stuck in read state

[Jimbolino]

Since we upgraded from v2.6.3 to v2.6.4, we are experiencing some problems with our php-fpm backend

The problem is that the php-fpm process gets stuck in a "read" state (and not go back to "accept" state).
Eventually php's pm.max_children is reached and the entire server will be killed by ec2's health checker.

I've done some debugging with strace, but have not found a pattern, because the servers gets lots of traffic, but the problem only occurs every once in a while. (maybe once in a 1000 requests)

root@frontend:~# strace -p 39614
strace: Process 39614 attached
read(5, 

root@frontend:~# nsenter -t 39614 --net lsof -n -p 39614 | grep 5u
php-fpm 39614 www-data    5u  IPv6 287757      0t0     TCP 172.18.0.3:9000->172.18.0.4:44492 (ESTABLISHED)

172.18.0.3 = app_php_1.app_default
172.18.0.4 = app_caddy_1.app_default

Im afraid that #5367 might need to be revisited.
I've reverted back to v2.6.3 and the problem is gone.

[mholt]

Thanks for the report. What is your config?

[Jimbolino]

Caddyfile:

{
    debug
    skip_install_trust
    auto_https disable_redirects
    on_demand_tls {
        ask {$CADDY_ON_DEMAND_ASK_URL}
    }
    admin caddy:8080 {
        origins {$CADDY_ADMIN_ALLOWED_ORIGINS}
    }
    storage redis {
        host {$CADDY_CLUSTERING_REDIS_HOST}
        port {$CADDY_CLUSTERING_REDIS_PORT}
        db {$CADDY_CLUSTERING_REDIS_DB}
        tls_enabled {$CADDY_CLUSTERING_REDIS_TLS}
    }
}

(global) {
    header server maglr
}

(frontend) {
    root * /app/docs

    route {
        # If the requested file does not exist, try index files
        @indexFiles file {
            try_files {path} {path}/index.php index.php
            split_path .php
        }
        rewrite @indexFiles {http.matchers.file.relative}

        # Proxy PHP files to the FastCGI responder
        @phpFiles path *.php
        reverse_proxy @phpFiles php:9000 {
            transport fastcgi {
                split .php
            }
        }
    }

    encode zstd gzip
    file_server {
        hide .htaccess
    }
    header -x-powered-by
}

(security) {
    header referrer-policy strict-origin-when-cross-origin
    header strict-transport-security max-age=31536000
    header x-content-type-options nosniff
}

*.maglr.localhost, *.localhost, https://127.0.0.1 {
    tls internal
    import frontend
    import global
}

https:// {
    tls {
        on_demand
    }

    import security
    import frontend
    import global
}


http:// {
    handle /health {
        respond "OK" 200
    }
    @notHealth {
        not path /health.php
    }
    handle {
        redir @notHealth https://{host}{uri}
    }
    import frontend
    import global
}

[francislavoie]

That's odd. Was it broken on v2.6.2 as well?

Would you be able to set up a minimally reproducible example? i.e. a simple PHP script that exhibits the issue, plus a Caddyfile that only has the bits that are relevant to the breakage.

[Jimbolino]

nope, v2.6.2 ran on production just fine

Im having trouble reproducing it locally (or on our staging environment)

Maybe it's got something to do with the AWS Network Load Balancer, or maybe bad bots that send malformed headers (wrong Content-Length etc)

[francislavoie]

v2.6.4 should be functionally equivalent to v2.6.2 in terms of the proxy buffering functionality. I don't understand what's going on here.

[mholt]

Can you try enabling access logs and maybe see if we can pin down which requests exactly are hanging?

[Jimbolino]

We have cloudwatch enabled for our access logs
I think the default timeout is 3 seconds, because we see the following entries when searching for { $.duration > 1 }

{
    "level": "error",
    "ts": 1678042875.2110817,
    "logger": "http.log.error",
    "msg": "dialing backend: dial tcp 172.18.0.3:9000: i/o timeout",
    "request": {
        "remote_ip": "172.31.10.238",
        "remote_port": "26109",
        "proto": "HTTP/1.1",
        "method": "GET",
        "host": "172.31.10.238:443",
        "uri": "/health.php",
        "headers": {
            "User-Agent": [
                "ELB-HealthChecker/2.0"
            ],
            "Connection": [
                "close"
            ],
            "Accept": [
                "*/*"
            ],
            "Accept-Encoding": [
                "*"
            ]
        }
    },
    "duration": 3.001065249,
    "status": 502,
    "err_id": "qd6cryvhi",
    "err_trace": "reverseproxy.statusError (reverseproxy.go:1299)"
}

From this ts (2023-03-05T20:01:15.211+01:00) I went back in the logs to see what was happening.
The previous 5-6 mins are only calls to health.php, and before that there is some normal traffic.

[trea]

Is your health.php making any external calls that might not be returned to PHP before Caddy gives up on the request?

I worked on a project where we had reverse proxying to PHP on Docker and couldn't figure out why we would repeatedly get 5xx errors and no running PHP.

It turned out that we were making requests with Curl to a flaky service and someone had inadvertently set CURLOPT_TIMEOUT to 0. Any request to that flaky service that wasn't handled before the reverse proxy gave up and returned to the client left open a PHP worker sitting around waiting for the flaky service to respond until there weren't any workers left.

[Jimbolino]

nope:

<?php
const MAX_LOAD = 25;
$load = sys_getloadavg();
if ($load[0] > MAX_LOAD) {
    http_response_code(503);
    exit('503');
}
if (!isset($_SERVER['APP_ENV'])) {
    $root = __DIR__.'/..';
    if (!file_exists($root.'/.env')) {
        http_response_code(500);
        exit('unknown environment');
    }
    require_once $root.'/vendor/autoload.php';
    Dotenv\Dotenv::createImmutable($root)->load();
}
exit('ok');

and if i understand strace correctly, it's php who is trying to read on the incoming connection from caddy that is stuck
so maybe caddy did not close the connection or send a EOF or something?

[trea]

Thanks, the health.php file you provided looks fine.

I stand by my theory though that you have something else that's causing PHP to not return quickly enough for your call to /health.php. I did create a reproduction using Docker Compose and put it in this repo: https://github.com/trea/php-fpm-issue

If you follow the README (and you may have to run the healthcheck a few times), you end up with requests that take too long. The healthcheck fails and then autoheal restarts it and Caddy can't connect to PHP anymore until it's finished restarting:

"error": "dialing backend: dial tcp 192.168.48.6:9000: connect: connection refused"

Log Output

php-fpm-exit-test-caddy-1     | {
  "level": "debug",
  "ts": 1678475769.7431428,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "php:9000",
  "duration": 0.000587583,
  "request": {
    "remote_ip": "192.168.48.4",
    "remote_port": "54200",
    "proto": "HTTP/1.1",
    "method": "GET",
    "host": "caddy",
    "uri": "/slow.php",
    "headers": {
      "X-Forwarded-Proto": [
        "http"
      ],
      "X-Forwarded-Host": [
        "caddy"
      ],
      "User-Agent": [
        "fortio.org/fortio-1.53.1"
      ],
      "X-Forwarded-For": [
        "192.168.48.4"
      ]
    }
  },
  "error": "dialing backend: dial tcp 192.168.48.6:9000: connect: connection refused"
}

I would recommend setting up a slowlog for FPM and ensuring that the ptrace capability is available, that way you should be able to get a better idea of what is causing FPM to hang.

In this test case the output points to curl_exec:

php-fpm-exit-test-php-1       | [10-Mar-2023 19:33:48] WARNING: [pool www] child 8, script '/var/www/html/slow.php' (request: "GET /slow.php") executing too slow (2.210546 sec), logging
php-fpm-exit-test-php-1       | [10-Mar-2023 19:33:48] WARNING: [pool www] child 7, script '/var/www/html/slow.php' (request: "GET /slow.php") executing too slow (2.220195 sec), logging
php-fpm-exit-test-php-1       | [10-Mar-2023 19:33:48] NOTICE: child 8 stopped for tracing
php-fpm-exit-test-php-1       | [10-Mar-2023 19:33:48] NOTICE: about to trace 8
php-fpm-exit-test-php-1       |
php-fpm-exit-test-php-1       | [10-Mar-2023 19:33:48]  [pool www] pid 8
php-fpm-exit-test-php-1       | script_filename = /var/www/html/slow.php
php-fpm-exit-test-php-1       | [0x0000ffff9f2130c0] curl_exec() /var/www/html/slow.php:6

[Jimbolino]

There are indeed some calls that incidentally take too long.
It still doesnt explain why previous versions of caddy dont cause the same issue.

Maybe #5431 is related

[trea]

Actually, after looking into this more, I think you were right when you suggested #5367 was related, and I do think #5431 is related as well. I think they specifically go back to this change:

https://github.com/caddyserver/caddy/pull/5367/files#diff-a248c9a1ec018edea8b377d155bc1df1a642bf79d00ababb5cdacc6b86c5733dL627

The FastCGI specification states that Responders read up to the total of CONTENT_LENGTH, but as a result of 5367, that is now empty for requests with Transfer-Encoding: chunked.

I have updated my repo to include both versions of Caddy and two more services in the Docker Compose file chunked and chunked264. When I run docker-compose chunked264 PHP actually dies and is respawned immediately. You can call docker-compose run chunked all you want and it works fine.

I understand the reverting of the buffer settings, but I think Caddy should guarantee that CONTENT_LENGTH is set to an int (0 is fine and even desirable) at least as far as the FastCGI transport is concerned. I'd be happy to submit a PR if that'd be welcome.

I think changing this to guard against empty strings and send a 0 instead of an empty string for CONTENT_LENGTH would do it:
https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go#L299

In fact, it's done for the FastCGI protocol elsewhere 🤔 :
https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/reverseproxy/fastcgi/fastcgi.go#L186

[francislavoie]

Ah, interesting. That does make sense @trea. PR is definitely welcome :)