Edit report at https://bugs.php.net/bug.php?id=65800&edit=1
ID: 65800
Updated by: laruence@php.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:
I don't understand why fpm_event_add is added here.
anyway, could you please make a PR at github https://github.com/php/php-src?
we may need more eyes on this.
thanks
Previous Comments:
------------------------------------------------------------------------
[2015-09-20 08:33:18] rainer dot jung at kippdata dot de
We observed the problem on Solaris too.
I added another patch that contains the following three parts:
- switch variables "nget" and "i" to unsigned. The Solaris event ports API uses
unsigned nget and this change silences compiler warnings. This part is unrelated to the rest and the
leats important.
- Check events returned when EINTR was caught. We observed crashed during testing for PHP 7 when
starting fpm and then stopping without any requests being handled. The crashes were due to event
ports returning nget=1 if EINTR occurred, but in fact nget simply wasn't changed from what had
been put into the port_getn call. The crash then happened, because portev_user didn't point to
the address of the event callback function but instead to some other (invalid) memory address. To
check whether actually an event is available, the patch sets portev_user to a magic value and checks
it after port_getn returns. This fixes the crash. The fix is taken from the Apache APR library,
which in turn took it likely form libev. See also the old Solaris discussion at http://marc.info/?l=opensolaris-networking-discuss&m=125071205204540.
This problem e.g. also hit Apache 2.4 on Solaris when it was new.
- I mostly copoied the third part from the previous patch here, namely re-associating the evevtn
with the port after port_getn. Without this e.g. Stopping directly after starting doesn't work.
The children send their SIGCHLD, the signal is received and the "C" character is send to
the pipe, but the receiving event never happens, so the children remain as zombies and the master
process never stopps. I only changed the previous patch from doing the port_associate as a copy of
the code in fpm_event_port_add() to directlxy call fpm_event_port_add(). Note that any error form
fpm_event_port_add() is not being handled, but it isn't handled in other places calling
fpm_event_port_add(), so at least it is consistent. Even without handling errors from
fpm_event_port_add() the code is more correct than without calling it at all.
The patch applies to PHP 5.4, 5.5, 5.6 and 7.0. The problems have only been observed by us for 7.0
but that was likely just luck.
Other open PHP bugs that likely will also be fixed by this path:
- https://bugs.php.net/bug.php?id=66694
- https://bugs.php.net/bug.php?id=67181
- https://bugs.php.net/bug.php?id=68349
I'll add a reference to the new patch there, mybe we can get some more testing from those other
users.
------------------------------------------------------------------------
[2014-07-08 14:47:04] d dot v dot taylor at leedsmet dot ac dot uk
Related To: Bug #67181
------------------------------------------------------------------------
[2014-06-13 13:02:31] filip at hajny dot net
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).
------------------------------------------------------------------------
[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