Edit report at https://bugs.php.net/bug.php?id=76601&edit=1
ID: 76601
Comment by: mnikulin at plesk dot com
Reported by: mnikulin at plesk dot com
Summary: Partially working php-fpm ater incomplete reload
Status: Open
Type: Bug
Package: FPM related
Operating System: Linux, Ubuntu-16.04
PHP Version: 7.0.30
Block user comment: N
Private report: N
New Comment:
Debug logs from a similar incident
[10-Jul-2018 17:17:29.169525] NOTICE: pid 32007, fpm_sockets_init_main(), line 349: using inherited
socket fd=37, "/run/php/php7.0-fpm.sock"
[10-Jul-2018 17:17:29.169525] NOTICE: pid 32007, fpm_sockets_init_main(), line 349: using inherited
socket fd=37, "/run/php/php7.0-fpm.sock"
[10-Jul-2018 17:17:29.171013] DEBUG: pid 32007, fpm_event_init_main(), line 342: event module is
epoll and 301 fds have been reserved
[10-Jul-2018 17:17:29.171170] NOTICE: pid 32007, fpm_init(), line 85: fpm is running, pid 32007
[10-Jul-2018 17:17:29.171538] DEBUG: pid 32007, fpm_children_make(), line 421: [pool www] child
32047 started
[10-Jul-2018 17:17:29.171768] DEBUG: pid 32007, fpm_children_make(), line 421: [pool www] child
32048 started
[10-Jul-2018 17:17:29.171831] DEBUG: pid 32007, fpm_event_loop(), line 371: 186000 bytes have been
reserved in SHM
[10-Jul-2018 17:17:29.171871] NOTICE: pid 32007, fpm_event_loop(), line 372: ready to handle
connections
[10-Jul-2018 17:17:29.174339] DEBUG: pid 32007, fpm_systemd_heartbeat(), line 68: have notify start
to systemd
[10-Jul-2018 17:17:29.174535] NOTICE: pid 32007, fpm_systemd_heartbeat(), line 75: systemd monitor
interval set to 10000ms
[10-Jul-2018 17:17:29.174628] DEBUG: pid 32007, fpm_got_signal(), line 112: received SIGUSR2
[10-Jul-2018 17:17:29.174681] NOTICE: pid 32007, fpm_got_signal(), line 113: Reloading in progress
...
[10-Jul-2018 17:17:29.174732] DEBUG: pid 32007, fpm_pctl(), line 234: switching to
'reloading' state
[10-Jul-2018 17:17:29.174790] DEBUG: pid 32007, fpm_pctl_kill_all(), line 162: [pool www] sending
signal 3 SIGQUIT to child 32048
[10-Jul-2018 17:17:29.174840] DEBUG: pid 32007, fpm_pctl_kill_all(), line 162: [pool www] sending
signal 3 SIGQUIT to child 32047
[10-Jul-2018 17:17:29.174887] DEBUG: pid 32007, fpm_pctl_kill_all(), line 171: 2 child(ren) still
alive
[10-Jul-2018 17:17:29.174935] DEBUG: pid 32007, fpm_got_signal(), line 112: received SIGUSR2
[10-Jul-2018 17:17:29.174980] NOTICE: pid 32007, fpm_got_signal(), line 113: Reloading in progress
...
[10-Jul-2018 17:17:29.175025] DEBUG: pid 32007, fpm_event_loop(), line 424: event module triggered 1
events
[10-Jul-2018 17:17:29.176463] DEBUG: pid 32007, fpm_pctl_kill_all(), line 162: [pool www] sending
signal 15 SIGTERM to child 32048
[10-Jul-2018 17:17:29.176504] DEBUG: pid 32007, fpm_pctl_kill_all(), line 162: [pool www] sending
signal 15 SIGTERM to child 32047
[10-Jul-2018 17:17:29.176510] DEBUG: pid 32007, fpm_pctl_kill_all(), line 171: 2 child(ren) still
alive
[10-Jul-2018 17:17:29.186320] DEBUG: pid 32007, fpm_got_signal(), line 112: received SIGUSR2
[10-Jul-2018 17:17:29.186506] NOTICE: pid 32007, fpm_got_signal(), line 113: Reloading in progress
...
[10-Jul-2018 17:17:29.186601] DEBUG: pid 32007, fpm_event_loop(), line 424: event module triggered 1
events
[10-Jul-2018 17:17:29.197708] DEBUG: pid 32007, fpm_got_signal(), line 112: received SIGUSR2
[10-Jul-2018 17:17:29.197735] NOTICE: pid 32007, fpm_got_signal(), line 113: Reloading in progress
...
[10-Jul-2018 17:17:29.197741] DEBUG: pid 32007, fpm_event_loop(), line 424: event module triggered 1
events
Previous Comments:
------------------------------------------------------------------------
[2018-07-10 02:28:04] mnikulin at plesk dot com
Description:
------------
I caught php-fpm in a weird state while I was trying to look closer at another issue (#74083
"master PHP-fpm is stopped on multiple reloads"). The aim is to check stability when
several requests for reload (kill -USR2) arrive in parallel. In my case PHP-FPM process failed into
partially working state.
Likely it is hard to reproduce the same state. In my opinion even completely died process is not so
terrible due to killed service is easier to notice.
php-fpm: Installed: 1:7.0+35ubuntu6.1
configuration:
ubuntu default "www" dynamic pool with pm.start_servers = 2
~30 other on-demand pools
Test script:
---------------
for i in {1..10} ; do ( systemctl reload php7.0-fpm ; echo "$i status $?" ; ) & done
Expected result:
----------------
Signals (SIGUSR1, SIGUSR2, SIGQUIT, SIGTERM) are properly masked while critical operations at
initialization and shutdown stages are performed. So daemon is running after reload request
(SIGUSR2), it reloads configuration and is responsive to requests on all configured sockets.
Actual result:
--------------
- PHP-FPM daemon is running.
- Requests handled by most of the pools fail with 502 code.
- Previously configured sockets are open.
- "www" pool is working, however no new children are spawn in response to increased load.
- The only result of more attempts to reload are additional "[06-Jul-2018 12:06:34] NOTICE:
Reloading in progress ..." log entries.
- Changes in configuration files are ignored (e.g. no new sockets become open).
ps xauwf
root 15007 0.0 3.2 368532 32976 ? Ss Jul05 0:05 php-fpm: master process
(/etc/php/7.0/fpm/php-fpm.conf)
www-data 7535 0.0 0.6 368292 6668 ? S 11:17 0:00 \_ php-fpm: pool www
www-data 7539 0.0 0.6 368292 6668 ? S 11:17 0:00 \_ php-fpm: pool www
systemd is regularly notified
strace:
epoll_wait(39, [], 301, 553) = 0
clock_gettime(CLOCK_MONOTONIC, {89876, 465329966}) = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 40
getsockopt(40, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(40, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0
sendmsg(40, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"},
msg_iov(1)=[{"READY=1\nSTATUS=Processes active:"..., 84}], msg_controllen=0, msg_flags=0},
MSG_NOSIGNAL) = 84
close(40) = 0
clock_gettime(CLOCK_MONOTONIC, {89876, 467799731}) = 0
Attempt to reload once more:
strace
12:01:53.155389 clock_gettime(CLOCK_MONOTONIC, {90970, 718593604}) = 0
12:01:53.155618 epoll_wait(39, 0x562314725f70, 301, 338) = -1 EINTR (Interrupted system call)
12:01:53.290441 --- SIGUSR2 {si_signo=SIGUSR2, si_code=SI_USER, si_pid=8841, si_uid=0} ---
12:01:53.290519 write(7, "2", 1) = 1
12:01:53.290626 rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system call)
12:01:53.290762 clock_gettime(CLOCK_MONOTONIC, {90970, 853986574}) = 0
12:01:53.291297 clock_gettime(CLOCK_MONOTONIC, {90970, 854429547}) = 0
12:01:53.291401 clock_gettime(CLOCK_MONOTONIC, {90970, 854526970}) = 0
12:01:53.291499 epoll_wait(39, [{EPOLLIN, {u32=331364736, u64=94708655208832}}], 301, 203) = 1
12:01:53.291600 read(6, "2", 1) = 1
12:01:53.291712 gettimeofday({1530856913, 291798}, NULL) = 0
12:01:53.291867 write(5, "[06-Jul-2018 12:01:53] NOTICE: R"..., 57) = 57
12:01:53.292071 read(6, 0x7ffee5c6fd77, 1) = -1 EAGAIN (Resource temporarily unavailable)
12:01:53.292511 clock_gettime(CLOCK_MONOTONIC, {90970, 855637928}) = 0
12:01:53.292618 clock_gettime(CLOCK_MONOTONIC, {90970, 855745156}) = 0
12:01:53.291297 clock_gettime(CLOCK_MONOTONIC, {90970, 854429547}) = 0
12:01:53.291401 clock_gettime(CLOCK_MONOTONIC, {90970, 854526970}) = 0
12:01:53.291499 epoll_wait(39, [{EPOLLIN, {u32=331364736, u64=94708655208832}}], 301, 203) = 1
12:01:53.291600 read(6, "2", 1) = 1
12:01:53.291712 gettimeofday({1530856913, 291798}, NULL) = 0
12:01:53.291867 write(5, "[06-Jul-2018 12:01:53] NOTICE: R"..., 57) = 57
12:01:53.292071 read(6, 0x7ffee5c6fd77, 1) = -1 EAGAIN (Resource temporarily unavailable)
12:01:53.292511 clock_gettime(CLOCK_MONOTONIC, {90970, 855637928}) = 0
Internally it is in the reload state
(gdb) p fpm_state
$1 = 2
# FPM_PCTL_STATE_RELOADING
There was an attempt to send SIGTERM to all children, but SIGKILL was not sent for some reason:
(gdb) p fpm_signal_sent
$2 = 15
# 15) SIGTERM
www pool is in the list, child count and their PIDs are correct
(gdb) p fpm_globals.running_children
$3 = 2
(gdb) p *$pwww
$37 = {next = 0x0, config = 0x562314721a40, user = 0x5623147247b0 "www-data", home =
0x5623147247d0 "/var/www", listen_address_domain = FPM_AF_UNIX, listening_socket = 38,
set_uid = 33, set_gid = 33, socket_uid = 33, socket_gid = 33,
socket_mode = 432, children = 0x562314727bc0, running_children = 2, idle_spawn_rate = 1,
warn_max_children = 0, scoreboard = 0x7f8587748000, log_fd = -1, limit_extensions = 0x562314721ec0,
ondemand_event = 0x0, socket_event_set = 0}
(gdb) p *$pwww->children
$38 = {prev = 0x0, next = 0x562314727ac0, started = {tv_sec = 88316, tv_usec = 284870}, wp =
0x5623147219b0, ev_stdout = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0,
tv_usec = 0}, callback = 0x0, arg = 0x0,
flags = 0, index = 0, which = 0}, ev_stderr = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0},
frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x0, arg = 0x0, flags = 0, index = 0, which = 0},
shm_slot_i = 0, fd_stdout = -1,
fd_stderr = -1, tracer = 0x0, slow_logged = {tv_sec = 0, tv_usec = 0}, idle_kill = 0, pid = 7539,
scoreboard_i = 1}
(gdb) p *$pwww->children->next
$39 = {prev = 0x562314727bc0, next = 0x0, started = {tv_sec = 88316, tv_usec = 284478}, wp =
0x5623147219b0, ev_stdout = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0,
tv_usec = 0}, callback = 0x0, arg = 0x0,
flags = 0, index = 0, which = 0}, ev_stderr = {fd = 0, timeout = {tv_sec = 0, tv_usec = 0},
frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x0, arg = 0x0, flags = 0, index = 0, which = 0},
shm_slot_i = 0, fd_stdout = -1,
fd_stderr = -1, tracer = 0x0, slow_logged = {tv_sec = 0, tv_usec = 0}, idle_kill = 0, pid = 7535,
scoreboard_i = 0}
pctl_event has some reasonable values of its fields, not trash
$40 = {fd = -1, timeout = {tv_sec = 88317, tv_usec = 284972}, frequency = {tv_sec = 1, tv_usec = 0},
callback = 0x5623138b8580 <fpm_pctl_action>, arg = 0x0, flags = 0, index = -1, which = 1}
However this handler is not in the timer queue
(gdb) p *fpm_event_queue_timer
$43 = {prev = 0x0, next = 0x562314727ce0, ev = 0x562313c03d00 <heartbeat>}
(gdb) p *fpm_event_queue_timer->next
$44 = {prev = 0x562314727d50, next = 0x0, ev = 0x562313c03a80 <heartbeat>}
(gdb) p *fpm_event_queue_timer->ev
$45 = {fd = -1, timeout = {tv_sec = 347438, tv_usec = 829245}, frequency = {tv_sec = 10, tv_usec =
0}, callback = 0x5623138bea40 <fpm_systemd_heartbeat>, arg = 0x0, flags = 4, index = -1, which
= 1}
(gdb) p *fpm_event_queue_timer->next->ev
$46 = {fd = -1, timeout = {tv_sec = 347430, tv_usec = 49454}, frequency = {tv_sec = 1, tv_usec = 0},
callback = 0x5623138b85a0 <fpm_pctl_perform_idle_server_maintenance_heartbeat>, arg = 0x0,
flags = 4, index = -1, which = 1}
I have not found any obvious place where a system call can be interrupted in such way that next
timer is not arranged. I do not see a way to remove an event from the queue without firing the
scheduled handler at first as well. It is quite strange that SIGKILL was not send to the running
children.
It is really terrible that systemd believes that fpm service is a healthy state and it is even
worser that some pools serve incoming request. It is hard to detect such case, looks like all pools
have to be checked otherwise some sites may stop working. Reload does not cure the problem, restart
is required and it has to be diagnosed somehow.
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=76601&edit=1