From: mnikulin at plesk dot com
Operating system: Linux, Ubuntu-16.04
PHP version: 7.0.30
Package: FPM related
Bug Type: Bug
Bug description:Partially working php-fpm ater incomplete reload
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 bug report at https://bugs.php.net/bug.php?id=76601&edit=1
--
Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=76601&r=trysnapshot54
Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=76601&r=trysnapshot55
Try a snapshot (trunk): https://bugs.php.net/fix.php?id=76601&r=trysnapshottrunk
Fixed in SVN: https://bugs.php.net/fix.php?id=76601&r=fixed
Fixed in release: https://bugs.php.net/fix.php?id=76601&r=alreadyfixed
Need backtrace: https://bugs.php.net/fix.php?id=76601&r=needtrace
Need Reproduce Script: https://bugs.php.net/fix.php?id=76601&r=needscript
Try newer version: https://bugs.php.net/fix.php?id=76601&r=oldversion
Not developer issue: https://bugs.php.net/fix.php?id=76601&r=support
Expected behavior: https://bugs.php.net/fix.php?id=76601&r=notwrong
Not enough info: https://bugs.php.net/fix.php?id=76601&r=notenoughinfo
Submitted twice: https://bugs.php.net/fix.php?id=76601&r=submittedtwice
register_globals: https://bugs.php.net/fix.php?id=76601&r=globals
PHP 4 support discontinued: https://bugs.php.net/fix.php?id=76601&r=php4
Daylight Savings: https://bugs.php.net/fix.php?id=76601&r=dst
IIS Stability: https://bugs.php.net/fix.php?id=76601&r=isapi
Install GNU Sed: https://bugs.php.net/fix.php?id=76601&r=gnused
Floating point limitations: https://bugs.php.net/fix.php?id=76601&r=float
No Zend Extensions: https://bugs.php.net/fix.php?id=76601&r=nozend
MySQL Configuration Error: https://bugs.php.net/fix.php?id=76601&r=mysqlcfg