[php-src] Issue #24046: FPM: worker stdio pipe fd closed twice when a child process outlives the worker, breaking a later worker's stderr (EPIPE)

Issue: https://github.com/php/php-src/issues/24046 Author: ipc-zpg ### Description With catch_workers_output = yes, php-fpm (8.1.20 and later, including 8.5) can close the same pipe fd twice when a worker exits while one of its child processes still holds that worker's stdout/stderr pipe open. If a new worker has been forked in the meantime and its pipe was given the same fd number, the second close() closes **the new worker's** pipe read end. From then on, every write that worker makes to stderr fails with EPIPE, until it exits (pm.max_requests, idle timeout). Holding the pipe open is easy to do from userland: fopen('php://stderr') under fpm is a dup() of fd 2 without close-on-exec. Any process started afterwards inherits it, even one started as exec('cmd > /dev/null 2>&1 &'). So a worker that writes to stderr and then starts a short background job is enough. That's common with logging libraries that write to php://stderr, like Monolog's StreamHandler (which throws on a failed write, so every request the broken worker serves fails). #### Reproduce www.conf: ```ini [global] error_log = /proc/self/fd/2 [www] user = www-data group = www-data listen = 9000 pm = ondemand pm.max_children = 8 pm.process_idle_timeout = 10s pm.max_requests = 20 catch_workers_output = yes decorate_workers_output = no ``` index.php: ```php <?php $stderr = fopen('php://stderr', 'a'); // dup() of the worker's stderr pipe, not close-on-exec if (@fwrite($stderr, "log line\n") === false) { http_response_code(500); exit("write to stderr failed\n"); } if (isset($_GET['bg'])) { exec('sleep 2 > /dev/null 2>&1 &'); // inherits the dup above } echo "ok\n"; ``` nginx.conf: ```nginx server { listen 80; root /www; location / { fastcgi_pass fpm:9000; include fastcgi_params; fastcgi_param SCRIPT_FILENAME /www/index.php; } } ``` ```sh docker network create fpmbug docker run -d --rm --name fpm --network fpmbug --network-alias fpm -v "$PWD:/www:ro" \ -v "$PWD/www.conf:/usr/local/etc/php-fpm.d/zz.conf:ro" php:8.5-fpm php-fpm -F -O -y /usr/local/etc/php-fpm.d/zz.conf docker run -d --rm --name ngx --network fpmbug -v "$PWD/nginx.conf:/etc/nginx/conf.d/default.conf:ro" -p 18080:80 nginx:alpine for i in $(seq 1 600); do q=; [ $((i % 7)) -eq 0 ] && q='?bg=1'; curl -s -o /dev/null -w '%{http_code}\n' "http://127.0.0.1:18080/$q"; done | sort | uniq -c docker logs fpm 2>&1 | grep ERROR | head ``` #### Resulted in 600 requests, with a background sleep on every 7th: | Image | Failed stderr writes (HTTP 500) | epoll: unable to remove fd | |---|---|---| | php:8.1-fpm (8.1.34) | 145 | 16 | | php:8.2-fpm (8.2.34) | 158 | 15 | | php:8.3-fpm (8.3.35) | 177 | 15 | | php:8.4-fpm (8.4.26) | 194 | 15 | | php:8.5-fpm (8.5.11) | 173 | 15 | | php:7.4-fpm (7.4.33) | 0 | 0 | (The 8.1–8.4 rows used the same setup with the stderr write done through Monolog's StreamHandler; the 8.5 and 7.4 rows used the bare script above.) The master logs: ``` ERROR: unable to read what child 39 said into stderr: Bad file descriptor (9) ERROR: epoll: unable to remove fd 12 ``` Control runs on 8.3: without the background exec, 0 and 0. With fclose($stderr) before the exec, also 0 and 0. #### But I expected this output instead No failed writes. A child process that outlives its worker shouldn't affect any other worker's pipe. #### Analysis In sapi/fpm/fpm/fpm_children.c, fpm_child_close() fires the stdio event to drain the pipe. If the pipe isn't at EOF, because a grandchild still holds the write end, fpm_stdio_child_said() gets EAGAIN. It then returns without closing the fd or setting it to -1. fpm_child_close() then calls close(child->fd_stderr) but leaves child->fd_stderr unchanged, and it schedules fpm_postponed_child_free() on a 1000 ms timer. That function sees fd_stderr != -1 and calls fpm_event_del() + close() on the same fd number a second time: - If the number hasn't been reused yet, epoll_ctl(DEL) fails and fpm logs epoll: unable to remove fd N. This is harmless, and it's the visible symptom. - If a newly forked worker's pipe has taken the number, the second close removes that worker's event and closes its read end. That worker then gets EPIPE on every stdio write. This case logs nothing. The postponed free came in with the GH-10461 fix (102953735c, "Postpone FPM child freeing in event loop"; present from 8.1.20 and 8.2.7, absent in 8.1.19 and 8.2.6). 7.4's fpm_child_close() freed the child straight away and never closed the fd again. A likely fix is for fpm_child_close() to call fpm_event_del() and set the fd to -1 itself whenever it closes it, so the postponed free can't act on it a second time. This looks like the underlying cause of DataDog/dd-trace-php#2317, which shows the same two log lines. There, the tracer's sidecar process was what held the inherited stderr open. ### PHP Version PHP 8.1.34, 8.2.34, 8.3.35, 8.4.26, 8.5.11 (official php:*-fpm Docker images). Not reproducible on 7.4.33. ### Operating System Debian (official Docker images), Linux x86_64, events.mechanism = epoll (default)