PHP-FPM requests are stuck and childs are killed after elapsing of the timeout

[WoZ]

Description

php-fpm child processes periodically stuck. No matter what scripts are executing... Script may stuck and the same script with the same params will execute ok right after this. My application has logs and writes them to stdout/stderr, but during the mentioned "stucks" no logs are present at all, so the logger didn't initialize, and initialization is the first step, even before any external connections to databases/queues/caches. Looks like a bug.

I use a base docker image 8.1.15-fpm. nginx is used as a webserver with FastCGI support and nginx routes via upstream requests to the same host machine (different container) via TCP.

Configuration:

[global]
error_log = /proc/self/fd/2
log_level = debug
log_limit = 8192
daemonize = no

[www]
access.log = /proc/self/fd/2
slowlog = /proc/self/fd/2
request_slowlog_timeout = 60s
clear_env = no
catch_workers_output = yes
decorate_workers_output = no
pm = dynamic
pm.max_children = 50
pm.start_servers = 2
pm.min_spare_servers = 2
pm.max_spare_servers = 5
pm.status_path = /status
request_terminate_timeout = 60s
listen = 9000

Additional info and logs during such a stuck.

1. nginx forwards a request to the upstream (php-fpm) on the same machine, but in a different container.
2. php-fpm logs nothing related to this request and this child. Only the very first message from the master process regarding

[02-May-2024 12:27:00.660632] DEBUG: pid 7, fpm_children_make(), line 435: [pool www] child 215893 started.

4. I write every second an output of the status page to the log and may see this request.

{
  "pool": "www",
  "process manager": "dynamic",
  "start time": 1714984262,
  "start since": 14215,
  "accepted conn": 71133,
  "listen queue": 0,
  "max listen queue": 1,
  "listen queue len": 511,
  "idle processes": 3,
  "active processes": 3,
  "total processes": 6,
  "max active processes": 16,
  "max children reached": 0,
  "slow requests": 0,
  "processes": [
    {
      "pid": 215893,
      "state": "Running",
      "start time": 1714998420,
      "start since": 57,
      "requests": 15,
      "request duration": 35713306,
      "request method": "POST",
      "request uri": "/index.php?access-token=secret_key_1&match_id=1111823&period_id=&event_code=",
      "content length": 95,
      "user": "-",
      "script": "/api/public/index.php",
      "last request cpu": 0,
      "last request memory": 0
    },
    {
      "pid": 215774,
      "state": "Idle",
      "start time": 1714998270,
      "start since": 207,
      "requests": 188,
      "request duration": 77764,
      "request method": "-",
      "request uri": "-",
      "content length": 0,
      "user": "-",
      "script": "-",
      "last request cpu": 51.44,
      "last request memory": 8388608
    },
    {
      "pid": 215799,
      "state": "Idle",
      "start time": 1714998303,
      "start since": 174,
      "requests": 164,
      "request duration": 5309,
      "request method": "-",
      "request uri": "-",
      "content length": 0,
      "user": "-",
      "script": "-",
      "last request cpu": 0,
      "last request memory": 16777216
    },
    {
      "pid": 215766,
      "state": "Idle",
      "start time": 1714998267,
      "start since": 210,
      "requests": 194,
      "request duration": 66407,
      "request method": "-",
      "request uri": "-",
      "content length": 0,
      "user": "-",
      "script": "-",
      "last request cpu": 30.12,
      "last request memory": 8388608
    },
    {
      "pid": 209262,
      "state": "Finishing",
      "start time": 1714990534,
      "start since": 7943,
      "requests": 7,
      "request duration": 7939544520,
      "request method": "POST",
      "request uri": "/index.php?access-token=secret_key_1&match_id=1112831&period_id=&event_code=",
      "content length": 92,
      "user": "-",
      "script": "/api/public/index.php",
      "last request cpu": 0,
      "last request memory": 0
    },
    {
      "pid": 215484,
      "state": "Running",
      "start time": 1714997843,
      "start since": 634,
      "requests": 605,
      "request duration": 4025,
      "request method": "GET",
      "request uri": "/status?full&json",
      "content length": 0,
      "user": "-",
      "script": "-",
      "last request cpu": 0,
      "last request memory": 0
    }
  ]
}

5. After some time php-fpm kills this child with the message in the log file

[02-May-2024 12:28:23.221826] WARNING: pid 7, fpm_request_check_timed_out(), line 272: [pool www] child 215893, script '/api/public/index.php' (request: "POST /index.php?access-token=secret_key_1&match_id=1111823&period_id=&event_code=") execution timed out (61.052097 sec), terminating


[02-May-2024 12:28:23.228318] WARNING: pid 7, fpm_children_bury(), line 258: [pool www] child 215893 exited on signal 15 (SIGTERM) after 82.568327 seconds from start

6. The application didn't send anything to nginx, because in nginx logs I see

172.0.1.10 - - [06/May/2024:12:27:58 +0000] "POST /action?access-token=secret_key_1&match_id=1111823&period_id=&event_code= HTTP/1.0" 499 0 "https://origdomain.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36" "XXX.XXX.XXX.XXX, XXX.XXX.XXX.XXX, XXX.XXX.XXX.XXX" rt="36.043" uct="0.000" uht="-" urt="36.044" conn="1286328" conn_reqs="1" upstream_addr="172.0.1.6:9000" upstream_status="-" upstream_response_time="36.044" upstream_header_time="-" upstream_connect_time="0.000" upstream_cache_status="-" upstream_bytes_sent="1888" upstream_bytes_received="0"

HTTP status code is 499, because nginx closed the connection due to max wait time. upstream_connect_time="0.000", upstream_bytes_sent="1888" upstream_bytes_received="0".

There is no pattern present. Simple health checks fail as well as more complicated logic. The only thing in common is that "requests" for the affected child are always low, and the child starts <60s before the stuck.

Any ideas?

Paid help for investigation and resolution is welcomed too.

PHP Version

8.1.15

Operating System

Ubuntu 20.04 in docker

[dstogov]

Please, try to identify the stucking worker, attach debgger (gdb -p PID), and print the backtrace (bt).

[bukka]

If getting backtrace is problematic for you (e.g. when running in container), please consider configuring the slowlog which should give you more info and also dump the backtrace to the logs. It means set slowlog to for example /dev/stderr (if using container) and request_slowlog_timeout to the time that will catch just those slow requests - see docs for format: https://www.php.net/manual/en/install.fpm.configuration.php#request_slowlog_timeout . You can also consider increasing request_slowlog_trace_depth if the trace is incomplete.

[WoZ]

At the moment I may share identified and gathered results.

strace was launched: strace -t -T -f -p8 (attach to pid = 8, master php-fpm process and attach to any child). php-fpm was reloaded to force forks and to start waiting. The next stuck happened with the child process with pid = 6385.

9788173:[pid  6385] 13:41:35 write(11, "{\"@timestamp\":\"2024-05-07T13:41:"..., 407) = 407 <0.000034>
9788174:[pid  6385] 13:41:35 sendto(20, "p\0\0\0\3INSERT INTO `event_timer` ("..., 116, MSG_DONTWAIT, NULL, 0) = 116 <0.000048>
9788175:[pid  6385] 13:41:35 poll([{fd=20, events=POLLIN|POLLERR|POLLHUP}], 1, 86400000) = 1 ([{fd=20, revents=POLLIN}]) <0.005579>
9788176:[pid  6385] 13:41:35 recvfrom(20, "\17\0\0\1\0\1\376_*\321\1\0\0\0\0\2\0\0\0", 32768, MSG_DONTWAIT, NULL, NULL) = 19 <0.000094>
9788177:[pid  6385] 13:41:35 write(11, "{\"@timestamp\":\"2024-05-07T13:41:"..., 600) = 600 <0.000080>
9788178:[pid  6385] 13:41:35 write(11, "{\"@timestamp\":\"2024-05-07T13:41:"..., 3796 <unfinished ...>
9899446:[pid  6385] 13:42:35 <... write resumed>) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) <60.241445>
9899448:[pid  6385] 13:42:35 --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=8, si_uid=1002} ---
9899450:[pid  6385] 13:42:35 rt_sigaction(SIGTERM, NULL,  <unfinished ...>
9899452:[pid  6385] 13:42:35 <... rt_sigaction resumed>{sa_handler=0x556ca67ad9e0, sa_mask=~[ILL TRAP ABRT BUS FPE KILL SEGV CONT STOP TSTP TTIN TTOU SYS RTMIN RT_1], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f74588bbd60}, 8) = 0 <0.000040>
9899454:[pid  6385] 13:42:35 rt_sigaction(SIGTERM, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f74588bbd60},  <unfinished ...>
9899456:[pid  6385] 13:42:35 <... rt_sigaction resumed>NULL, 8) = 0 <0.000265>
9899458:[pid  6385] 13:42:35 rt_sigprocmask(SIG_UNBLOCK, [TERM], NULL, 8) = 0 <0.000460>
9899460:[pid  6385] 13:42:35 getpid()           = 6385 <0.000106>
9899461:[pid  6385] 13:42:35 kill(6385, SIGTERM) = 0 <0.000028>
9899462:[pid  6385] 13:42:35 --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=6385, si_uid=1002} ---
9899480:[pid  6385] 13:42:35 +++ killed by SIGTERM +++

What's fd=11?

9764603:[pid  6385] 13:41:22 dup(2)             = 11 <0.000023>

To remind you, config is the next

[global]
error_log = /proc/self/fd/2
log_level = debug
log_limit = 8192
daemonize = no

[www]
access.log = /proc/self/fd/2
slowlog = /proc/self/fd/2
catch_workers_output = yes
decorate_workers_output = no

After that, manipulations with fd=2 were checked (decided to confirm that catch_workers_output = yes creates pipe in the master process - fpm_stdio_prepare_pipes).

9759038:[pid  6385] 13:41:15 dup2(18, 1 <unfinished ...>
9759042:[pid  6385] 13:41:15 <... dup2 resumed>) = 1 <0.000439>
9759048:[pid  6385] 13:41:15 dup2(25, 2 <unfinished ...>
9759052:[pid  6385] 13:41:15 <... dup2 resumed>) = 2 <0.000053>
9759058:[pid  6385] 13:41:15 close(15 <unfinished ...>
9759062:[pid  6385] 13:41:15 <... close resumed>) = 0 <0.000189>
9759067:[pid  6385] 13:41:15 close(18 <unfinished ...>
9759083:[pid  6385] 13:41:15 <... close resumed>) = 0 <0.001107>

18 and 25 were inherited from the master process, so the next step is to check the master process.

[pid     8] 13:41:15 pipe( <unfinished ...>
[pid     8] 13:41:15 <... pipe resumed>[20, 25]) = 0 <0.000165>
[pid     8] 13:41:15 fcntl(15, F_GETFL <unfinished ...>
[pid     8] 13:41:15 <... fcntl resumed>) = 0 (flags O_RDONLY) <0.000165>
[pid     8] 13:41:15 fcntl(15, F_SETFL, O_RDONLY|O_NONBLOCK <unfinished ...>
[pid     8] 13:41:15 <... fcntl resumed>) = 0 <0.000257>
[pid     8] 13:41:15 fcntl(20, F_GETFL <unfinished ...>
[pid     8] 13:41:15 <... fcntl resumed>) = 0 (flags O_RDONLY) <0.000131>
[pid     8] 13:41:15 fcntl(20, F_SETFL, O_RDONLY|O_NONBLOCK <unfinished ...>
[pid     8] 13:41:15 <... fcntl resumed>) = 0 <0.000108>
[pid     8] 13:41:15 rt_sigprocmask(SIG_BLOCK, [QUIT USR1 USR2 TERM CHLD],  <unfinished ...>
[pid     8] 13:41:15 <... rt_sigprocmask resumed>NULL, 8) = 0 <0.000171>
[pid     8] 13:41:15 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD <unfinished ...>
[pid     8] 13:41:15 <... clone resumed>, child_tidptr=0x7f7455efac50) = 6385 <0.002065>
strace: Process 6385 attached
[pid     8] 13:41:15 rt_sigprocmask(SIG_UNBLOCK, ~[RTMIN RT_1],  <unfinished ...>
[pid     8] 13:41:15 <... rt_sigprocmask resumed>NULL, 8) = 0 <0.000871>
[pid     8] 13:41:15 close(18 <unfinished ...>
[pid     8] 13:41:15 <... close resumed>) = 0 <0.000128>
[pid     8] 13:41:15 close(25 <unfinished ...>
[pid     8] 13:41:15 <... close resumed>) = 0 <0.000360>
[pid     8] 13:41:15 epoll_ctl(11, EPOLL_CTL_ADD, 15, {EPOLLIN, {u32=2820626776, u64=93925165455704}} <unfinished ...>
[pid     8] 13:41:15 <... epoll_ctl resumed>) = 0 <0.000135> [pid     8] 13:41:15 getpid( <unfinished ...>
[pid     8] 13:41:15 <... getpid resumed>) = 8 <0.000164>
[pid     8] 13:41:15 getpid( <unfinished ...>
[pid     8] 13:41:15 <... getpid resumed>) = 8 <0.000067>
[pid     8] 13:41:15 epoll_wait(11,  <unfinished ...>
[pid     8] 13:41:15 <... epoll_wait resumed>[{EPOLLIN, {u32=2820626528, u64=93925165455456}}, {EPOLLIN, {u32=2820629360, u64=93925165458288}}], 101, 989) = 2 <0.000124>
[pid     8] 13:41:15 read(19,  <unfinished ...>
[pid     8] 13:41:15 <... read resumed>"{\"@timestamp\":\"2024-05-07T13:41:"..., 1023) = 761 <0.000377>
[pid     8] 13:41:15 write(2, "{\"@timestamp\":\"2024-05-07T13:41:"..., 761 <unfinished ...>
[pid     8] 13:41:15 <... write resumed>) = 761 <0.000079>

So, it was the call of fpm_stdio_prepare_pipes (link to target tag 8.1.15) and fpm_stdio_parent_use_pipes.
But we see here epoll_ctl for fd=15, but I didn't find epoll_ctl with EPOLL_CTL_ADD and fd=20... So, looks like master process doesn't subscribe to fd=20 and doesn't read fd=20.

So, the code may fail at one of these lines:

fpm_event_set(&child->ev_stderr, child->fd_stderr, FPM_EV_READ, fpm_stdio_child_said, child);
fpm_event_add(&child->ev_stderr, 0);

At the moment there is no answer why only 1 fd was added via epoll_ctl.

[bukka]

I just had a proper look into this and the code around and can't really see why adding stderr event can be omitted. The only conditions that could trigger it is around the queue checks in fpm_event_queue_add but none of those should normally result in early return in this situation. I assume that you would notice malloc error for elt as it has got ZLOG_SYSERROR. If you are able to recompile it yourself, it might be worth to add few log calls (e.g. some zlog warnings) before all returns to see if any of those conditions get triggered for that child.

If you are only able to re-produce it on production, there might be some external factors causing this. It is actually quite similar to #11447 so might be worth to check the application as well.

[WoZ]

@bukka updates.

php-fpm was patched and we relaunched php-fpm. After some time we get the same behavior as before.
The reason that epoll_ctl wasn't called with EPOLL_CTL_ADD and broken fd is a return from fpm_event_queue_isset with non NULL value.

php-src/sapi/fpm/fpm/fpm_events.c

Lines 162 to 180 in 1a3d870

	static int fpm_event_queue_add(struct fpm_event_queue_s **queue, struct fpm_event_s *ev) /* {{{ */
	{
	struct fpm_event_queue_s *elt;
	if (!queue || !ev) {
	return -1;
	}
	if (fpm_event_queue_isset(*queue, ev)) {
	return 0;
	}
	if (!(elt = malloc(sizeof(struct fpm_event_queue_s)))) {
	zlog(ZLOG_SYSERROR, "Unable to add the event to queue: malloc() failed");
	return -1;
	}
	elt->prev = NULL;
	elt->next = NULL;
	elt->ev = ev;

php-src/sapi/fpm/fpm/fpm_events.c

Lines 145 to 160 in 1a3d870

	static struct fpm_event_s *fpm_event_queue_isset(struct fpm_event_queue_s *queue, struct fpm_event_s *ev) /* {{{ */
	{
	if (!ev) {
	return NULL;
	}
	while (queue) {
	if (queue->ev == ev) {
	return ev;
	}
	queue = queue->next;
	}
	return NULL;
	}
	/* }}} */

This happens because the pointer to fpm_event_s structure was found already in fpm_event_queue_fd.

php-src/sapi/fpm/fpm/fpm_events.c

Lines 44 to 47 in 1a3d870

	static struct fpm_event_module_s *module;
	static struct fpm_event_queue_s *fpm_event_queue_timer = NULL;
	static struct fpm_event_queue_s *fpm_event_queue_fd = NULL;
	static struct fpm_event_s children_bury_timer;

After this, we started to track fpm_event_queue_fd before calls of fpm_event_queue_add, fpm_event_queue_del, and fpm_event_queue_destroy. Plus some intermediate logs to identify the caller.

Below you may find logs and comments.

DEBUG: pid 8, fpm_pctl_perform_idle_server_maintenance(), line 398: [pool www] currently 5 active children, 1 spare children, 6 running children. Spawning rate 1
DEBUG: pid 8, fpm_children_make(), line 405: blocking signals before child birth
DEBUG: pid 8, fpm_children_make(), line 429: unblocking signals, child born

NOTICE: pid 8, fpm_stdio_parent_use_pipes(), line 335: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_set for stdout, child->fd_stdout == 14, child->pid == 229698
NOTICE: pid 8, fpm_stdio_parent_use_pipes(), line 337: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_add for stdout
NOTICE: pid 8, fpm_event_add(), line 613: [pid=8] fpm_event_add: going to call fpm_event_queue_add(&fpm_event_queue_fd)
NOTICE: pid 8, fpm_event_queue_isset(), line 201: [pid=8] fpm_event_queue_isset: going to check isset
NOTICE: pid 8, fpm_event_queue_print_debug(), line 152: [pid=8] fpm_event_queue_print_debug: going to print current queue content

Element #0 queue_addr = 0x55d8d1c75960, queue = { prev = 0, next = 0x55d8d1c73080, ev_address = 0x55d8d1c72fd0, ev = { fd = 22, arg = 0x37fbb, flags = 2, index = 22, which = 2 } }
Element #1 queue_addr = 0x55d8d1c73080, queue = { prev = 0x55d8d1c75960, next = 0x55d8d1c731c0, ev_address = 0x55d8d1c72f88, ev = { fd = 12, arg = 0x37fbb, flags = 2, index = 12, which = 2 } }
Element #2 queue_addr = 0x55d8d1c731c0, queue = { prev = 0x55d8d1c73080, next = 0x55d8d1c731a0, ev_address = 0x55d8d1c73110, ev = { fd = 28, arg = 0x37ee9, flags = 2, index = 28, which = 2 } }
Element #3 queue_addr = 0x55d8d1c731a0, queue = { prev = 0x55d8d1c731c0, next = 0x55d8d1c757a0, ev_address = 0x55d8d1c730c8, ev = { fd = 19, arg = 0x37ee9, flags = 2, index = 19, which = 2 } }
Element #4 queue_addr = 0x55d8d1c757a0, queue = { prev = 0x55d8d1c731a0, next = 0x55d8d1c75b60, ev_address = 0x55d8d1c72eb0, ev = { fd = 20, arg = 0x37ee3, flags = 2, index = 20, which = 2 } }
Element #5 queue_addr = 0x55d8d1c75b60, queue = { prev = 0x55d8d1c757a0, next = 0x55d8d1c73670, ev_address = 0x55d8d1c72e68, ev = { fd = 13, arg = 0x37ee3, flags = 2, index = 13, which = 2 } }
Element #6 queue_addr = 0x55d8d1c73670, queue = { prev = 0x55d8d1c75b60, next = 0x55d8d1c73650, ev_address = 0x55d8d1c72db0, ev = { fd = 24, arg = 0x37d55, flags = 2, index = 24, which = 2 } }
Element #7 queue_addr = 0x55d8d1c73650, queue = { prev = 0x55d8d1c73670, next = 0x55d8d1c75b40, ev_address = 0x55d8d1c72d68, ev = { fd = 15, arg = 0x37d55, flags = 2, index = 15, which = 2 } }
Element #8 queue_addr = 0x55d8d1c75b40, queue = { prev = 0x55d8d1c73650, next = 0x55d8d1c75c80, ev_address = 0x55d8d1c75d10, ev = { fd = 25, arg = 0x37d46, flags = 2, index = 25, which = 2 } }
Element #9 queue_addr = 0x55d8d1c75c80, queue = { prev = 0x55d8d1c75b40, next = 0x55d8d1c72f40, ev_address = 0x55d8d1c75cc8, ev = { fd = 17, arg = 0x37d46, flags = 2, index = 17, which = 2 } }
Element #10 queue_addr = 0x55d8d1c72f40, queue = { prev = 0x55d8d1c75c80, next = 0x55d8d1c73060, ev_address = 0x55d8d1c75ab0, ev = { fd = 0, arg = 0, flags = 0, index = 0, which = 0 } }
Element #11 queue_addr = 0x55d8d1c73060, queue = { prev = 0x55d8d1c72f40, next = 0x55d8d1c75980, ev_address = 0x55d8d1c75888, ev = { fd = 16, arg = 0x37b7b, flags = 2, index = 16, which = 2 } }
Element #12 queue_addr = 0x55d8d1c75980, queue = { prev = 0x55d8d1c73060, next = 0x55d8d1c757c0, ev_address = 0x55d8d1c758d0, ev = { fd = 21, arg = 0x37b7b, flags = 2, index = -1, which = 2 } }
Element #13 queue_addr = 0x55d8d1c757c0, queue = { prev = 0x55d8d1c75980, next = 0x55d8d1c72d20, ev_address = 0x55d8d1c75710, ev = { fd = 22, arg = 0x36fe6, flags = 2, index = -1, which = 2 } }
Element #14 queue_addr = 0x55d8d1c72d20, queue = { prev = 0x55d8d1c757c0, next = 0x55d8d1c5d760, ev_address = 0x55d8d1c72c70, ev = { fd = 18, arg = 0x34834, flags = 2, index = 18, which = 2 } }
Element #15 queue_addr = 0x55d8d1c5d760, queue = { prev = 0x55d8d1c72d20, next = 0, ev_address = 0x55d8d0a276a0, ev = { fd = 8, arg = 0, flags = 2, index = 8, which = 2 } }

fpm_event_queue_print_debug: printed 16 elements
fpm_event_queue_isset(), line 204: [pid=8] fpm_event_queue_isset: searching for: ev_address = 0x55d8d1c75a68, ev = { fd = 14, arg = 0x38142, flags = 2, index = -1, which = 2 }
fpm_event_queue_isset(), line 223: [pid=8] fpm_event_queue_isset: match was not found, returning

ev wasn't found in the queue, so it was added as the very first element. But pay attention to this line

Element #10 queue_addr = 0x55d8d1c72f40, queue = { prev = 0x55d8d1c75c80, next = 0x55d8d1c73060, ev_address = 0x55d8d1c75ab0, ev = { fd = 0, arg = 0, flags = 0, index = 0, which = 0 } }

Ok, after adding stdout the second call adds stderr file descriptor.

fpm_stdio_parent_use_pipes(), line 340: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_set for stderr, child->fd_stdout == 23, child->pid == 229698
fpm_stdio_parent_use_pipes(), line 342: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_add for stderr
fpm_event_add(), line 613: [pid=8] fpm_event_add: going to call fpm_event_queue_add(&fpm_event_queue_fd)
fpm_event_queue_isset(), line 201: [pid=8] fpm_event_queue_isset: going to check isset
fpm_event_queue_print_debug(), line 152: [pid=8] fpm_event_queue_print_debug: going to print current queue content

Element #0 queue_addr = 0x55d8d1c72d00, queue = { prev = 0, next = 0x55d8d1c75960, ev_address = 0x55d8d1c75a68, ev = { fd = 14, arg = 0x38142, flags = 2, index = 14, which = 2 } }
Element #1 queue_addr = 0x55d8d1c75960, queue = { prev = 0x55d8d1c72d00, next = 0x55d8d1c73080, ev_address = 0x55d8d1c72fd0, ev = { fd = 22, arg = 0x37fbb, flags = 2, index = 22, which = 2 } }
Element #2 queue_addr = 0x55d8d1c73080, queue = { prev = 0x55d8d1c75960, next = 0x55d8d1c731c0, ev_address = 0x55d8d1c72f88, ev = { fd = 12, arg = 0x37fbb, flags = 2, index = 12, which = 2 } }
Element #3 queue_addr = 0x55d8d1c731c0, queue = { prev = 0x55d8d1c73080, next = 0x55d8d1c731a0, ev_address = 0x55d8d1c73110, ev = { fd = 28, arg = 0x37ee9, flags = 2, index = 28, which = 2 } }
Element #4 queue_addr = 0x55d8d1c731a0, queue = { prev = 0x55d8d1c731c0, next = 0x55d8d1c757a0, ev_address = 0x55d8d1c730c8, ev = { fd = 19, arg = 0x37ee9, flags = 2, index = 19, which = 2 } }
Element #5 queue_addr = 0x55d8d1c757a0, queue = { prev = 0x55d8d1c731a0, next = 0x55d8d1c75b60, ev_address = 0x55d8d1c72eb0, ev = { fd = 20, arg = 0x37ee3, flags = 2, index = 20, which = 2 } }
Element #6 queue_addr = 0x55d8d1c75b60, queue = { prev = 0x55d8d1c757a0, next = 0x55d8d1c73670, ev_address = 0x55d8d1c72e68, ev = { fd = 13, arg = 0x37ee3, flags = 2, index = 13, which = 2 } }
Element #7 queue_addr = 0x55d8d1c73670, queue = { prev = 0x55d8d1c75b60, next = 0x55d8d1c73650, ev_address = 0x55d8d1c72db0, ev = { fd = 24, arg = 0x37d55, flags = 2, index = 24, which = 2 } }
Element #8 queue_addr = 0x55d8d1c73650, queue = { prev = 0x55d8d1c73670, next = 0x55d8d1c75b40, ev_address = 0x55d8d1c72d68, ev = { fd = 15, arg = 0x37d55, flags = 2, index = 15, which = 2 } }
Element #9 queue_addr = 0x55d8d1c75b40, queue = { prev = 0x55d8d1c73650, next = 0x55d8d1c75c80, ev_address = 0x55d8d1c75d10, ev = { fd = 25, arg = 0x37d46, flags = 2, index = 25, which = 2 } }
Element #10 queue_addr = 0x55d8d1c75c80, queue = { prev = 0x55d8d1c75b40, next = 0x55d8d1c72f40, ev_address = 0x55d8d1c75cc8, ev = { fd = 17, arg = 0x37d46, flags = 2, index = 17, which = 2 } }
Element #11 queue_addr = 0x55d8d1c72f40, queue = { prev = 0x55d8d1c75c80, next = 0x55d8d1c73060, ev_address = 0x55d8d1c75ab0, ev = { fd = 23, arg = 0x38142, flags = 2, index = -1, which = 2 } }
Element #12 queue_addr = 0x55d8d1c73060, queue = { prev = 0x55d8d1c72f40, next = 0x55d8d1c75980, ev_address = 0x55d8d1c75888, ev = { fd = 16, arg = 0x37b7b, flags = 2, index = 16, which = 2 } }
Element #13 queue_addr = 0x55d8d1c75980, queue = { prev = 0x55d8d1c73060, next = 0x55d8d1c757c0, ev_address = 0x55d8d1c758d0, ev = { fd = 21, arg = 0x37b7b, flags = 2, index = -1, which = 2 } }
Element #14 queue_addr = 0x55d8d1c757c0, queue = { prev = 0x55d8d1c75980, next = 0x55d8d1c72d20, ev_address = 0x55d8d1c75710, ev = { fd = 22, arg = 0x36fe6, flags = 2, index = -1, which = 2 } }
Element #15 queue_addr = 0x55d8d1c72d20, queue = { prev = 0x55d8d1c757c0, next = 0x55d8d1c5d760, ev_address = 0x55d8d1c72c70, ev = { fd = 18, arg = 0x34834, flags = 2, index = 18, which = 2 } }
Element #16 queue_addr = 0x55d8d1c5d760, queue = { prev = 0x55d8d1c72d20, next = 0, ev_address = 0x55d8d0a276a0, ev = { fd = 8, arg = 0, flags = 2, index = 8, which = 2 } }
fpm_event_queue_print_debug(), line 191: [pid=8] fpm_event_queue_print_debug: printed 17 elements

fpm_event_queue_isset(), line 204: [pid=8] fpm_event_queue_isset: searching for: ev_address = 0x55d8d1c75ab0, ev = { fd = 23, arg = 0x38142, flags = 2, index = -1, which = 2 }
fpm_event_queue_isset(), line 207: [pid=8] fpm_event_queue_isset: match was found: ev_address = 0x55d8d1c75ab0, ev = { fd = 23, arg = 0x38142, flags = 2, index = -1, which = 2 }
fpm_event_queue_add(), line 239: [pid=8] fpm_event_queue_add: fpm_event_queue_isset return 0
fpm_children_make(), line 435: [pool www] child 229698 started

As you may see fpm_event_queue_isset was called with passing pointer to ev with an address 0x55d8d1c75ab0.
This address may be found in the last output

Element #11 queue_addr = 0x55d8d1c72f40, queue = { prev = 0x55d8d1c75c80, next = 0x55d8d1c73060, ev_address = 0x55d8d1c75ab0, ev = { fd = 23, arg = 0x38142, flags = 2, index = -1, which = 2 } }

and in the same line with fd=0 I presented above.

Element #11 queue_addr = 0x55d8d1c72f40, queue = { prev = 0x55d8d1c75c80, next = 0x55d8d1c73060, ev_address = 0x55d8d1c75ab0, ev = { fd = 23, arg = 0x38142, flags = 2, index = -1, which = 2 } }

What next? We checked the code and have found...

fpm_children_make calls child = fpm_resources_prepare(wp);

php-src/sapi/fpm/fpm/fpm_children.c

Lines 440 to 480 in 1a3d870

	while (fpm_pctl_can_spawn_children() && wp->running_children < max && (fpm_global_config.process_max < 1 || fpm_globals.running_children < fpm_global_config.process_max)) {
	warned = 0;
	child = fpm_resources_prepare(wp);
	if (!child) {
	return 2;
	}
	zlog(ZLOG_DEBUG, "blocking signals before child birth");
	if (0 > fpm_signals_child_block()) {
	zlog(ZLOG_WARNING, "child may miss signals");
	}
	pid = fork();
	switch (pid) {
	case 0 :
	fpm_child_resources_use(child);
	fpm_globals.is_child = 1;
	fpm_child_init(wp);
	return 0;
	case -1 :
	zlog(ZLOG_DEBUG, "unblocking signals");
	fpm_signals_unblock();
	zlog(ZLOG_SYSERROR, "fork() failed");
	fpm_resources_discard(child);
	return 2;
	default :
	zlog(ZLOG_DEBUG, "unblocking signals, child born");
	fpm_signals_unblock();
	child->pid = pid;
	fpm_clock_get(&child->started);
	fpm_parent_resources_use(child);
	zlog(is_debug ? ZLOG_DEBUG : ZLOG_NOTICE, "[pool %s] child %d started", wp->config->name, (int) pid);
	}

fpm_resources_prepare(wp) calls fpm_child_alloc

php-src/sapi/fpm/fpm/fpm_children.c

Lines 350 to 377 in 1a3d870

	static struct fpm_child_s *fpm_resources_prepare(struct fpm_worker_pool_s *wp) /* {{{ */
	{
	struct fpm_child_s *c;
	c = fpm_child_alloc();
	if (!c) {
	zlog(ZLOG_ERROR, "[pool %s] unable to malloc new child", wp->config->name);
	return 0;
	}
	c->wp = wp;
	c->fd_stdout = -1; c->fd_stderr = -1;
	if (0 > fpm_stdio_prepare_pipes(c)) {
	fpm_child_free(c);
	return 0;
	}
	if (0 > fpm_scoreboard_proc_alloc(c)) {
	fpm_stdio_discard_pipes(c);
	fpm_child_free(c);
	return 0;
	}
	return c;
	}
	/* }}} */

And fpm_child_alloc calls malloc(sizeof(struct fpm_child_s))

php-src/sapi/fpm/fpm/fpm_children.c

Lines 41 to 54 in 1a3d870

	static struct fpm_child_s *fpm_child_alloc(void)
	{
	struct fpm_child_s *ret;
	ret = malloc(sizeof(struct fpm_child_s));
	if (!ret) {
	return 0;
	}
	memset(ret, 0, sizeof(*ret));
	ret->scoreboard_i = -1;
	return ret;
	}

After this, child is passed to fpm_parent_resources_use(child) and last function calls fpm_stdio_parent_use_pipes.

php-src/sapi/fpm/fpm/fpm_stdio.c

Lines 318 to 335 in 1a3d870

	int fpm_stdio_parent_use_pipes(struct fpm_child_s *child) /* {{{ */
	{
	if (0 == child->wp->config->catch_workers_output) { /* not required */
	return 0;
	}
	close(fd_stdout[1]);
	close(fd_stderr[1]);
	child->fd_stdout = fd_stdout[0];
	child->fd_stderr = fd_stderr[0];
	fpm_event_set(&child->ev_stdout, child->fd_stdout, FPM_EV_READ, fpm_stdio_child_said, child);
	fpm_event_add(&child->ev_stdout, 0);
	fpm_event_set(&child->ev_stderr, child->fd_stderr, FPM_EV_READ, fpm_stdio_child_said, child);
	fpm_event_add(&child->ev_stderr, 0);
	return 0;

php-src/sapi/fpm/fpm/fpm_events.c

Lines 505 to 523 in 1a3d870

	int fpm_event_add(struct fpm_event_s *ev, unsigned long int frequency) /* {{{ */
	{
	struct timeval now;
	struct timeval tmp;
	if (!ev) {
	return -1;
	}
	ev->index = -1;
	/* it's a triggered event on incoming data */
	if (ev->flags & FPM_EV_READ) {
	ev->which = FPM_EV_READ;
	if (fpm_event_queue_add(&fpm_event_queue_fd, ev) != 0) {
	return -1;
	}
	return 0;
	}

So, looks like malloc(sizeof(struct fpm_child_s)) received the same address as was previously used by some other child.

Proofs for this.

When the value of fpm_event_s *ev was created it got ev = { fd = 23, arg = 0x38142, flags = 2, index = -1, which = 2 }. index = -1 may be set only by

php-src/sapi/fpm/fpm/fpm_events.c

Lines 505 to 523 in 1a3d870

	int fpm_event_add(struct fpm_event_s *ev, unsigned long int frequency) /* {{{ */
	{
	struct timeval now;
	struct timeval tmp;
	if (!ev) {
	return -1;
	}
	ev->index = -1;
	/* it's a triggered event on incoming data */
	if (ev->flags & FPM_EV_READ) {
	ev->which = FPM_EV_READ;
	if (fpm_event_queue_add(&fpm_event_queue_fd, ev) != 0) {
	return -1;
	}
	return 0;
	}

Later, in fpm_event_epoll_add it will be set to ev->fd.

php-src/sapi/fpm/fpm/events/epoll.c

Lines 156 to 183 in 1a3d870

	static int fpm_event_epoll_add(struct fpm_event_s *ev) /* {{{ */
	{
	struct epoll_event e;
	/* fill epoll struct */
	#if SIZEOF_SIZE_T == 4
	/* Completely initialize event data to prevent valgrind reports */
	e.data.u64 = 0;
	#endif
	e.events = EPOLLIN;
	e.data.fd = ev->fd;
	e.data.ptr = (void *)ev;
	if (ev->flags & FPM_EV_EDGE) {
	e.events = e.events | EPOLLET;
	}
	/* add the event to epoll internal queue */
	if (epoll_ctl(epollfd, EPOLL_CTL_ADD, ev->fd, &e) == -1) {
	zlog(ZLOG_ERROR, "epoll: unable to add fd %d", ev->fd);
	return -1;
	}
	/* mark the event as registered */
	ev->index = ev->fd;
	return 0;
	}
	/* }}} */

Our current hypothesis states:

1. for some reason struct fpm_event_s in the fpm_event_queue_fd was freed, but not deleted from the queue.
2. memory was reallocated and when php-fpm master process set new struct fpm_event_s the pointer from the fpm_event_queue_fd points to the same memory address.

@bukka do you have any idea why struct fpm_event_s was cleared for specific fd? We need to find this specific call and logic and continue debugging.

[WoZ]

Additionally, we've checked occurrences of the ev address 0x55d8d1c75ab0 in logs.

6 minutes before it was spotted with ev = { fd = 0, arg = 0, flags = 0, index = 0, which = 0 } } it had the following value.

NOTICE: pid 8, fpm_event_queue_print_debug(), line 170: [pid=8] fpm_event_queue_print_debug: Element #10 queue_addr = 0x55d8d1c72f40, queue = { prev = 0x55d8d1c75c80, next = 0x55d8d1c73060, ev_address = 0x55d8d1c75ab0, ev = { fd = 26, arg = 0x37cbd, flags = 2, index = 26, which = 2 } }

Thid fd was created 16 minutes earlier with the creation of child.

DEBUG: pid 8, fpm_pctl_perform_idle_server_maintenance(), line 398: [pool www] currently 5 active children, 1 spare children, 6 running children. Spawning rate 1
DEBUG: pid 8, fpm_scoreboard_proc_alloc(), line 414: [pool www] the proc->free_slot was not free. Let's search
DEBUG: pid 8, fpm_children_make(), line 405: blocking signals before child birth
DEBUG: pid 8, fpm_children_make(), line 429: unblocking signals, child born
NOTICE: pid 8, fpm_stdio_parent_use_pipes(), line 323: [pid=8] fpm_stdio_parent_use_pipes was called
NOTICE: pid 8, fpm_stdio_parent_use_pipes(), line 335: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_set for stdout, child->fd_stdout == 18, child->pid == 228541

NOTICE: pid 8, fpm_stdio_parent_use_pipes(), line 337: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_add for stdout

NOTICE: pid 8, fpm_event_queue_isset(), line 204: [pid=8] fpm_event_queue_isset: searching for: ev_address = 0x55d8d1c75a68, ev = { fd = 18, arg = 0x37cbd, flags = 2, index = -1, which = 2 }
NOTICE: pid 8, fpm_event_queue_isset(), line 223: [pid=8] fpm_event_queue_isset: match was not found, returning
NOTICE: pid 8, fpm_event_queue_add(), line 260: [pid=8] fpm_event_queue_add: module->add(ev)

NOTICE: pid 8, fpm_stdio_parent_use_pipes(), line 340: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_set for stderr, child->fd_stdout == 26, child->pid == 228541
NOTICE: pid 8, fpm_stdio_parent_use_pipes(), line 342: [pid=8] fpm_stdio_parent_use_pipes: calling fpm_event_add for stderr
 
NOTICE: pid 8, fpm_event_queue_isset(), line 204: [pid=8] fpm_event_queue_isset: searching for: ev_address = 0x55d8d1c75ab0, ev = { fd = 26, arg = 0x37cbd, flags = 2, index = -1, which = 2 }
NOTICE: pid 8, fpm_event_queue_isset(), line 223: [pid=8] fpm_event_queue_isset: match was not found, returning
NOTICE: pid 8, fpm_event_queue_add(), line 260: [pid=8] fpm_event_queue_add: module->add(ev)

DEBUG: pid 8, fpm_children_make(), line 435: [pool www] child 228541 started
DEBUG: pid 8, fpm_pctl_perform_idle_server_maintenance(), line 446: [pool www] 1 child(ren) have been created dynamically

Later, we've found

DEBUG: pid 8, fpm_children_bury(), line 260: [pool www] child 228541 has been killed by the process management after 718.381129 seconds from start

Let's check the log

DEBUG: pid 8, fpm_pctl_perform_idle_server_maintenance(), line 398: [pool www] currently 1 active children, 6 spare children, 7 running children. Spawning rate 1
NOTICE: pid 8, fpm_event_queue_del(), line 276: [pid=8] fpm_event_queue_del: going to delete event: ev_address = 0x55d8d1c75a68, ev = { fd = 18, arg = 0x37cbd, flags = 2, index = 18, which = 2 }
 
DEBUG: pid 8, fpm_event_loop(), line 523: event module triggered 1 events
DEBUG: pid 8, fpm_got_signal(), line 82: received SIGCHLD

DEBUG: pid 8, fpm_children_bury(), line 260: [pool www] child 228541 has been killed by the process management after 718.381129 seconds from start

So, fpm_event_queue_del was called only for stdout but not for stderr.
So, the hypothesis is updated.

[bukka]

We had actually an issue with freeing the event too soon which got fixed in 8.1.20: 1029537 . Could you try to update and patch your version to see if it helps by any chance? Ideally it would be great if you could update to latest 8.2 as we cannot really make a fix to 8.1 if it's something else.