PHP :: Bug #76601 :: Partially working php-fpm ater incomplete reload
php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #76601 Partially working php-fpm ater incomplete reload
Submitted: 2018-07-10 02:28 UTC Modified: -
From: mnikulin at plesk dot com Assigned:
Status: Open Package: FPM related
PHP Version: 7.0.30 OS: Linux, Ubuntu-16.04
Private report: No CVE-ID: None
View Add Comment Developer Edit
Welcome! If you don't have a Git account, you can't do anything here.
You can add a comment by following this link or if you reported this bug, you can edit this bug over here.
(description)
Block user comment
Status: Assign to:
Package:
Bug Type:
Summary:
From: mnikulin at plesk dot com
New email:
PHP Version: OS:

 

 [2018-07-10 02:28 UTC] 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.

Patches

php-76601_kill-not-rescheduled_2018-07-11.patch (last revision 2018-07-11 08:09 UTC) by mnikulin at plesk dot com)

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2018-07-10 10:53 UTC] mnikulin at plesk dot com
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
 [2018-07-11 08:24 UTC] mnikulin at plesk dot com
I have traced down a part of the problem. SIGKILL is not sent to FPM workers at all.

The open question is why SIGQUIT and SIGTERM are not enough sometimes.
Maybe kill() of a child is interrupted by SIGUSR2 received by the master
process and check for EINTR is required after the kill() call.

Missed SIGQUIT and SIGTERM are hardly can be desirable, but ensuring
SIGKILL delivery allows to avoid process stuck in some intermediate
semi-functional state.

The problem is that SIGTERM and SIGKILL share the same fpm_event_s structure
and scheduled through the same event queue. The handler is invoked
synchronously and it is unable to reschedule itself

fpm_process_ctl.c:202 static void fpm_pctl_action_next()
        fpm_pctl_timeout_set(timeout);

due to

fpm_events.c:156 static int fpm_event_queue_add()
        if (fpm_event_queue_isset(*queue, ev)) {
                return 0;
        }

The timer is removed from the queue *after* completion of the handler

fpm_events.c:440 void fpm_event_loop()
                                        } else { /* delete the event */

Possible solution is to mark the event as persistent (see the patch).
It helps even in the case when some signals from previous iteration
are not delivered, the cost is another second before reexec.

With the patch from https://bugs.php.net/bug.php?id=74083
PHP-FPM becomes immune to SIGUSR2 flood.
 [2018-07-12 03:11 UTC] mnikulin at plesk dot com
SIGQUIT and SIGTERM may be missed by children just after reload due to

fpm_signals.c:169 static void sig_handler()
	if (fpm_globals.parent_pid != getpid()) {
		/* prevent a signal race condition when child process
			have not set up it's own signal handler yet */
		return;
	}

Looks like this measure is not a solution for all cases. sigprocmask() SIG_BLOCK/SIG_UNBLOCK may be added around the fork() call to

fpm_children.c:400 int fpm_children_make()
		pid = fork();
 
PHP Copyright © 2001-2018 The PHP Group
All rights reserved.
Last updated: Sat Aug 18 12:01:26 2018 UTC