From: florisjan dot gerrits at gmail dot com
Operating system: Ubuntu 18.04 bionic
PHP version: 7.2.10
Package: FPM related
Bug Type: Bug
Bug description:PHP-FPM7.x can't finish reloading after encountering a fatal error
Description:
------------
What you did: Browsed to a website using break/continue outside a loop
and afterwards, I reloaded PHP-FPM.
What I want to happen: I want PHP-FPM to successfully reload
What actually happened: PHP-FPM got stuck in 'Waiting on reload...' and
forced me to either restart or manually send a SIGKILL to the child that
got stuck.
(Force) Moving websites from PHP5.6 to PHP7.x made me to run into this
bug. A lot of old websites use 'break' and 'continue' options in
if-constructions (outside loops). An example:
2018/09/13 11:25:59 [error] 7861#7861: *8603 FastCGI sent in stderr:
"PHP message: PHP Fatal error: 'break' not in the 'loop' or
'switch'
context in /home/florisjantest.nl/public_html/index.php on line 5" while
reading response header from upstream, client: 0.0.0.0, server:
florisjantest.nl, request: "GET / HTTP/1.1", upstream:
"fastcgi://unix:/var/run/php-fpm.florisjantest.nl.socket:", host:
"florisjantest.nl"
This Fatal error triggers the PHP-FPM child to become unresponsive and
ignore any and all signals except for SIGKILL. Trying to reload PHP-FPM
will cause the master to get stuck in 'waiting on reload' status and
will not allow any new connections.
Technical:
What you did: trigger the error and reload PHP-FPM
What I want to happen:
[pid 6324] kill(7893, SIGQUIT) = 0
[pid 6324] getpid() = 6324
[pid 6324] getpid() = 6324
[pid 6324] epoll_wait(8, <unfinished ...>
[pid 7893] <... accept resumed> 0x7ffd46708d70, [112]) = ? ERESTARTSYS
(To be restarted if SA_RESTART is set)
[pid 7893] --- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER, si_pid=6324,
si_uid=0} ---
[pid 7893] close(0) = 0
[pid 7893] socket(AF_UNIX, SOCK_STREAM, 0) = 0
[pid 7893] rt_sigreturn({mask=[]}) = 43
[pid 7893] accept(0, 0x7ffd46708d70, [112]) = -1 EINVAL (Invalid
argument)
[pid 7893] munmap(0x7ffab1d13000, 67108864) = 0
[pid 7893] close(3)
What actually happened:
[pid 22815] kill(8176, SIGQUIT) = 0
[pid 22815] getpid() = 22815
[pid 22815] getpid() = 22815
[pid 22815] epoll_wait(9, <unfinished ...>
[pid 8176] <... accept resumed> 0x7ffd81ca33d0, [112]) = ? ERESTARTSYS
(To be restarted if SA_RESTART is set)
[pid 8176] --- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER,
si_pid=22815, si_uid=0} ---
[pid 8176] rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
[pid 8176] accept(10, <unfinished ...>
[pid 22815] <... epoll_wait resumed> [], 1, 1000) = 0
[pid 22815] getpid() = 22815
Loaded modules:
# php-fpm7.2 -m
[PHP Modules]
bcmath
bz2
calendar
cgi-fcgi
Core
ctype
curl
date
dom
exif
fileinfo
filter
ftp
gd
gettext
hash
iconv
imap
intl
json
ldap
libxml
mbstring
mysqli
mysqlnd
openssl
pcre
PDO
pdo_mysql
pdo_pgsql
pdo_sqlite
pgsql
Phar
posix
readline
Reflection
session
shmop
SimpleXML
soap
sockets
sodium
SPL
sqlite3
standard
sysvmsg
sysvsem
sysvshm
tokenizer
wddx
xml
xmlreader
xmlwriter
xsl
Zend OPcache
zip
zlib
[Zend Modules]
Zend OPcache
Test script:
---------------
<?php
$variabele = 'TEST';
if (!empty($variabele)) {
break;
}
Actual result:
--------------
After requesting the above mentioned script the following situation will
occur:
The master process issues a SIGQUIT every 10 seconds:
epoll_wait(9, [], 1, 1000) = 0
getpid() = 22080
kill(22106, SIGQUIT) = 0
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 1000) = 0
getpid() = 22080
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 992) = 0
getpid() = 22080
socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 10
getsockopt(10, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(10, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0
getuid() = 0
geteuid() = 0
getgid() = 0
getegid() = 0
sendmsg(10, {msg_name={sa_family=AF_UNIX,
sun_path="/run/systemd/notify"}, msg_namelen=21,
msg_iov=[{iov_base="READY=1\nSTATUS=Processes active: 0, idle: 1,
Requests: 1, slow: 0, Traffic: 0req/sec", iov_len=84}], msg_iovlen=1,
msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 84
An strace on the child process shows the following:
accept(10, 0x7fff77012e90, [112]) = ? ERESTARTSYS (To be restarted
if SA_RESTART is set)
--- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER, si_pid=22080, si_uid=0}
---
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
accept(10,
The situation changes when you initiate a reload of PHP-FPM. The reload
will signal SIGUSR2, it sends another SIGQUIT to the child and after 10
seconds it will send a SIGTERM. This is where no further signals are
given to the child. No new SIGQUITs no new SIGTERMs and no SIGKILLs
(although that's probably okay). The broken child is still active and
upholding the master from reloading:
# systemctl reload php7.2-fpm.service
# ps axuf | grep php
root 22697 0.0 0.2 14432 1020 pts/0 S+ 11:40 0:00
\_ grep php
root 22080 0.0 6.1 486688 30532 ? Ss 11:25 0:00
php-fpm: master process (/etc/php/7.2/fpm/php-fpm.conf)
florisja 22106 0.0 3.8 489292 18984 ? S 11:25 0:00 \_
php-fpm: pool florisjantest.nl
Reload in master:
epoll_wait(9, 0x55fbc277db10, 1, 1000) = -1 EINTR (Interrupted system
call)
--- SIGUSR2 {si_signo=SIGUSR2, si_code=SI_USER, si_pid=22692, si_uid=0}
---
getpid() = 22080
write(6, "2", 1) = 1
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
getpid() = 22080
epoll_wait(9, [{EPOLLIN, {u32=3228071840, u64=94539753224096}}], 1, 773)
= 1
read(5, "2", 1) = 1
write(4, "[13-Sep-2018 11:40:35] NOTICE: Reloading in progress ...\n",
57) = 57
kill(22106, SIGQUIT) = 0
read(5, 0x7fff77012e77, 1) = -1 EAGAIN (Resource
temporarily unavailable)
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 772) = 0
getpid() = 22080
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 1000) = 0
getpid() = 22080
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 1000) = 0
getpid() = 22080
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 795) = 0
getpid() = 22080
socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 10
getsockopt(10, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(10, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0
getuid() = 0
geteuid() = 0
getgid() = 0
getegid() = 0
sendmsg(10, {msg_name={sa_family=AF_UNIX,
sun_path="/run/systemd/notify"}, msg_namelen=21,
msg_iov=[{iov_base="READY=1\nSTATUS=Processes active: 0, idle: 2,
Requests: 1, slow: 0, Traffic: 0req/sec", iov_len=84}], msg_iovlen=1,
msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 84
close(10) = 0
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 202) = 0
getpid() = 22080
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 1000) = 0
getpid() = 22080
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 222) = 0
kill(22106, SIGTERM) = 0
getpid() = 22080
getpid() = 22080
epoll_wait(9, [], 1, 777) = 0
Reload in child:
--- SIGQUIT {si_signo=SIGQUIT, si_code=SI_USER, si_pid=22080, si_uid=0}
---
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
accept(10, 0x7fff77012e90, [112]) = ? ERESTARTSYS (To be restarted
if SA_RESTART is set)
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=22080, si_uid=0}
---
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
accept(10,
As mentioned above, no new SIGQUIT signals will follow. The master gets
the status 'Waiting on reload...' and doesn't seem to think the child is
still there.
Initiating a restart of PHP-FPM will show the following:
# systemctl restart php7.2-fpm.service
# ps axuf
root 22815 0.0 6.1 486688 30352 ? Ss 11:47 0:00
php-fpm: master process (/etc/php/7.2/fpm/php-fpm.conf)
Master:
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=1, si_uid=0} ---
getpid() = 22080
write(6, "T", 1) = 1
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
--- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1, si_uid=0} ---
getpid() = 22080
epoll_wait(9, [{EPOLLIN, {u32=3228071840, u64=94539753224096}}], 1, 968)
= 1
read(5, "T", 1) = 1
write(4, "[13-Sep-2018 11:47:54] NOTICE: Terminating ...\n", 47) = 47
kill(22106, SIGTERM) = 0
read(5, 0x7fff77012e77, 1) = -1 EAGAIN (Resource
temporarily unavailable)
......
kill(22106, SIGKILL) = 0
getpid() = 22080
getpid() = 22080
epoll_wait(9, 0x55fbc277db10, 1, 968) = -1 EINTR (Interrupted system
call)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=22106,
si_uid=1003, si_status=SIGKILL, si_utime=0, si_stime=1} ---
getpid() = 22080
write(6, "C", 1) = 1
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
getpid() = 22080
epoll_wait(9, [{EPOLLIN, {u32=3228071840, u64=94539753224096}}], 1, 963)
= 1
read(5, "C", 1) = 1
wait4(-1, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGKILL}],
WNOHANG|WSTOPPED, NULL) = 22106
write(4, "[13-Sep-2018 11:47:59] NOTICE: exiting, bye-bye!\n", 49) = 49
Child:
0x7fff77012e90, [112]) = ? ERESTARTSYS (To be restarted if
SA_RESTART is set)
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=1, si_uid=0} ---
--- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=1, si_uid=0} ---
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
accept(10, 0x7fff77012e90, [112]) = ? ERESTARTSYS (To be restarted
if SA_RESTART is set)
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=22080, si_uid=0}
---
rt_sigreturn({mask=[]}) = -1 EINTR (Interrupted system
call)
accept(10, <unfinished ...>) = ?
+++ killed by SIGKILL +++
--
Edit bug report at https://bugs.php.net/bug.php?id=76895&edit=1
--
Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=76895&r=trysnapshot54
Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=76895&r=trysnapshot55
Try a snapshot (trunk): https://bugs.php.net/fix.php?id=76895&r=trysnapshottrunk
Fixed in SVN: https://bugs.php.net/fix.php?id=76895&r=fixed
Fixed in release: https://bugs.php.net/fix.php?id=76895&r=alreadyfixed
Need backtrace: https://bugs.php.net/fix.php?id=76895&r=needtrace
Need Reproduce Script: https://bugs.php.net/fix.php?id=76895&r=needscript
Try newer version: https://bugs.php.net/fix.php?id=76895&r=oldversion
Not developer issue: https://bugs.php.net/fix.php?id=76895&r=support
Expected behavior: https://bugs.php.net/fix.php?id=76895&r=notwrong
Not enough info: https://bugs.php.net/fix.php?id=76895&r=notenoughinfo
Submitted twice: https://bugs.php.net/fix.php?id=76895&r=submittedtwice
register_globals: https://bugs.php.net/fix.php?id=76895&r=globals
PHP 4 support discontinued: https://bugs.php.net/fix.php?id=76895&r=php4
Daylight Savings: https://bugs.php.net/fix.php?id=76895&r=dst
IIS Stability: https://bugs.php.net/fix.php?id=76895&r=isapi
Install GNU Sed: https://bugs.php.net/fix.php?id=76895&r=gnused
Floating point limitations: https://bugs.php.net/fix.php?id=76895&r=float
No Zend Extensions: https://bugs.php.net/fix.php?id=76895&r=nozend
MySQL Configuration Error: https://bugs.php.net/fix.php?id=76895&r=mysqlcfg