Bug #65800 [Com]: FPM won't listen to signals when event ports and catch_workers_output are used

Edit report at https://bugs.php.net/bug.php?id=65800&edit=1 ID: 65800 Comment by: filip at hajny dot net Reported by: filip at hajny dot net Summary: FPM won't listen to signals when event ports and catch_workers_output are used Status: Open Type: Bug Package: FPM related Operating System: SmartOS (possibly SunOS) PHP Version: Irrelevant Block user comment: N Private report: N New Comment: We have been providing patched 5.3/5.4/5.5 packages for 6 months by now to the Joyent Public Cloud customers, and it's what it takes to fix the problem. See the attached patch (patch-sapi_fpm_fpm_events_port.c). Previous Comments: ------------------------------------------------------------------------ [2013-10-01 12:27:56] filip at hajny dot net Description: ------------ When "events.mechanism = port" and "catch_workers_output = yes" are in effect on SmartOS (and possibly Illumos/SunOS in general), FPM won't terminate the process stack on a signal received (includes attempts to shut down the stack with TERM, or reload with USR2). There seems to be no other way to stop the stack except for SIGKILL to the master. Looking at the debug log, we see SIGTERM sent to the children processes, which terminate, but stay as zombies. # ./sapi/fpm/php-fpm -F [01-Oct-2013 11:59:28.382567] DEBUG: pid 96294, fpm_scoreboard_init_main(), line 40: got clock tick '100' [01-Oct-2013 11:59:28.382842] DEBUG: pid 96294, fpm_event_init_main(), line 337: event module is port and 5 fds have been reserved [01-Oct-2013 11:59:28.382863] NOTICE: pid 96294, fpm_init(), line 83: fpm is running, pid 96294 [01-Oct-2013 11:59:28.383274] DEBUG: pid 96294, fpm_children_make(), line 421: [pool www] child 96295 started [01-Oct-2013 11:59:28.383626] DEBUG: pid 96294, fpm_children_make(), line 421: [pool www] child 96296 started [01-Oct-2013 11:59:28.383658] DEBUG: pid 96294, fpm_event_loop(), line 366: 2232 bytes have been reserved in SHM [01-Oct-2013 11:59:28.383665] NOTICE: pid 96294, fpm_event_loop(), line 367: ready to handle connections [01-Oct-2013 11:59:42.417811] DEBUG: pid 96294, fpm_event_loop(), line 419: event module triggered 1 events [01-Oct-2013 11:59:42.417854] DEBUG: pid 96294, fpm_got_signal(), line 85: received SIGTERM [01-Oct-2013 11:59:42.417864] NOTICE: pid 96294, fpm_got_signal(), line 86: Terminating ... [01-Oct-2013 11:59:42.417873] DEBUG: pid 96294, fpm_pctl(), line 231: switching to 'terminating' state [01-Oct-2013 11:59:42.417913] DEBUG: pid 96294, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 96296 [01-Oct-2013 11:59:42.417933] DEBUG: pid 96294, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 96295 [01-Oct-2013 11:59:42.417942] DEBUG: pid 96294, fpm_pctl_kill_all(), line 168: 2 child(ren) still alive [01-Oct-2013 11:59:42.417959] DEBUG: pid 96294, fpm_event_loop(), line 419: event module triggered 1 events [01-Oct-2013 11:59:42.418045] DEBUG: pid 96294, fpm_event_loop(), line 419: event module triggered 2 events [01-Oct-2013 11:59:42.418079] DEBUG: pid 96294, fpm_event_loop(), line 419: event module triggered 2 events [01-Oct-2013 11:59:42.418855] ERROR: pid 96294, fpm_stdio_child_said(), line 120: unable to read what child say: Bad file number (9) [01-Oct-2013 11:59:42.418923] DEBUG: pid 96294, fpm_event_loop(), line 419: event module triggered 1 events Killed DTracing sig_handler, we see one SIGCLD per child received. # dtrace -n 'pid$target::sig_handler:entry{ trace(arg0); }' -p $(pgrep php|sort - n|head -1) dtrace: description 'pid$target::sig_handler:entry' matched 1 probe CPU ID FUNCTION:NAME 2 483 sig_handler:entry 15 2 483 sig_handler:entry 18 2 483 sig_handler:entry 18 Oddly enough, the problem is only manifest as long as at least one child process exists from the flock launched at the start. If we manually terminate all the children processes first and let the master re-spawn them all, the problem goes away entirely. # ./sapi/fpm/php-fpm -F [01-Oct-2013 12:20:01.656647] DEBUG: pid 96910, fpm_scoreboard_init_main(), line 40: got clock tick '100' [01-Oct-2013 12:20:01.656920] DEBUG: pid 96910, fpm_event_init_main(), line 337: event module is port and 5 fds have been reserved [01-Oct-2013 12:20:01.656940] NOTICE: pid 96910, fpm_init(), line 83: fpm is running, pid 96910 [01-Oct-2013 12:20:01.657345] DEBUG: pid 96910, fpm_children_make(), line 421: [pool www] child 96911 started [01-Oct-2013 12:20:01.657696] DEBUG: pid 96910, fpm_children_make(), line 421: [pool www] child 96912 started [01-Oct-2013 12:20:01.657730] DEBUG: pid 96910, fpm_event_loop(), line 366: 2232 bytes have been reserved in SHM [01-Oct-2013 12:20:01.657740] NOTICE: pid 96910, fpm_event_loop(), line 367: ready to handle connections [01-Oct-2013 12:20:12.049038] DEBUG: pid 96910, fpm_event_loop(), line 419: event module triggered 4 events [01-Oct-2013 12:20:12.049745] ERROR: pid 96910, fpm_stdio_child_said(), line 120: unable to read what child say: Bad file number (9) [01-Oct-2013 12:20:12.049811] DEBUG: pid 96910, fpm_event_loop(), line 419: event module triggered 1 events [01-Oct-2013 12:20:12.049844] DEBUG: pid 96910, fpm_got_signal(), line 76: received SIGCHLD [01-Oct-2013 12:20:12.049880] WARNING: pid 96910, fpm_children_bury(), line 252: [pool www] child 96911 exited on signal 15 (SIGTERM) after 10.392237 seconds from start [01-Oct-2013 12:20:12.050366] NOTICE: pid 96910, fpm_children_make(), line 421: [pool www] child 96920 started [01-Oct-2013 12:20:12.050404] WARNING: pid 96910, fpm_children_bury(), line 252: [pool www] child 96912 exited on signal 15 (SIGTERM) after 10.392396 seconds from start [01-Oct-2013 12:20:12.050735] NOTICE: pid 96910, fpm_children_make(), line 421: [pool www] child 96921 started [01-Oct-2013 12:20:12.050770] DEBUG: pid 96910, fpm_got_signal(), line 76: received SIGCHLD [01-Oct-2013 12:20:12.050790] DEBUG: pid 96910, fpm_event_loop(), line 419: event module triggered 1 events ^C[01-Oct-2013 12:20:17.138831] DEBUG: pid 96910, fpm_got_signal(), line 80: received SIGINT [01-Oct-2013 12:20:17.138894] NOTICE: pid 96910, fpm_got_signal(), line 81: Terminating ... [01-Oct-2013 12:20:17.138927] DEBUG: pid 96910, fpm_pctl(), line 231: switching to 'terminating' state [01-Oct-2013 12:20:17.139001] DEBUG: pid 96910, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 96921 [01-Oct-2013 12:20:17.139031] DEBUG: pid 96910, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 96920 [01-Oct-2013 12:20:17.139043] DEBUG: pid 96910, fpm_pctl_kill_all(), line 168: 2 child(ren) still alive [01-Oct-2013 12:20:17.139069] DEBUG: pid 96910, fpm_event_loop(), line 419: event module triggered 1 events [01-Oct-2013 12:20:17.139796] DEBUG: pid 96910, fpm_got_signal(), line 76: received SIGCHLD [01-Oct-2013 12:20:17.139834] DEBUG: pid 96910, fpm_children_bury(), line 252: [pool www] child 96920 exited on signal 2 (SIGINT) after 5.089324 seconds from start [01-Oct-2013 12:20:17.139876] DEBUG: pid 96910, fpm_children_bury(), line 252: [pool www] child 96921 exited on signal 2 (SIGINT) after 5.088997 seconds from start [01-Oct-2013 12:20:17.139906] NOTICE: pid 96910, fpm_pctl_exit(), line 70: exiting, bye-bye! This has been a problem on all FPM-capable PHP branches (including current trunk) for at least a year now. Configure phase seems irrelevant, but for the record: # ./configure --enable-fpm --with-fpm-user=www --with-fpm-group=www --with-config- file-path=/opt/local/etc --with- config-file-scan-dir=/opt/local/etc/php.d --sysconfdir=/opt/local/etc -- localstatedir=/var --disable-all -- prefix=/opt/local ------------------------------------------------------------------------ -- Edit this bug report at https://bugs.php.net/bug.php?id=65800&edit=1