Edit report at https://bugs.php.net/bug.php?id=60961&edit=1
ID: 60961 User updated by: phpbugs at oops dot mooo dot com Reported by: phpbugs at oops dot mooo dot com Summary: Graceful Restart (USR2) isn't very graceful Status: Assigned Type: Bug Package: FPM related Operating System: Debian Squeeze PHP Version: 5.3.9 Assigned To: fat Block user comment: N Private report: N New Comment: Try setting process_control_timeout to something higher than 0. Previous Comments: ------------------------------------------------------------------------ [2013-02-13 09:47:32] php-bugs at puzzled dot xs4all dot nl CentOS 6.3 with php-5.3.3 and the FPM code from 5.3.20 still has the same issue. FWIW this makes it challenging to use nginx with php-fpm because it results in a 502 Bad Gateway. I'm more than happy to help testing a patch. ------------------------------------------------------------------------ [2012-07-17 06:40:44] megazubr at gmail dot com Centos 5.8, php 5.4.4 compiled from source with --enable-fpm When doing USR2 on master pid of php-fpm daemon 1. kill child(502 Bad gatway on long_loop.php in same time) 2. restart daemon with another master pid As i see, it's not a graceful reload. master pid - 12788 child(long_loop.php) - 12795 strace -f -s 8000 -p 12788 [pid 12795] munmap(0x2b017edd1000, 1168) = 0 [pid 12795] munmap(0x2b017edd2000, 1168) = 0 [pid 12795] munmap(0x2b017edd3000, 1168) = 0 [pid 12795] munmap(0x2b017edb5000, 112) = 0 [pid 12795] time(NULL) = 1342505962 [pid 12795] dup2(1, 2) = 2 [pid 12795] close(4) = 0 [pid 12795] dup2(13, 0) = 0 [pid 12795] geteuid() = 0 [pid 12795] setgid(500) = 0 [pid 12795] open("/proc/sys/kernel/ngroups_max", O_RDONLY) = 4 [pid 12795] read(4, "65536\n", 31) = 6 [pid 12795] close(4) = 0 [pid 12795] open("/etc/group", O_RDONLY) = 4 [pid 12795] fcntl(4, F_GETFD) = 0 [pid 12795] fcntl(4, F_SETFD, FD_CLOEXEC) = 0 [pid 12795] fstat(4, {st_mode=S_IFREG|0644, st_size=693, ...}) = 0 [pid 12795] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b017b3ce000 [pid 12795] lseek(4, 0, SEEK_CUR) = 0 [pid 12795] read(4, "root:x:0:root\nbin:x:1:root,bin,daemon\ndaemon:x:2:root,bin,daemon\nsys:x:3:roo t,bin,adm\nadm:x:4:root,adm,daemon\ntty:x:5:\ndisk:x:6:root\nlp:x:7:daemon,lp\nm em:x:8:\nkmem:x:9:\nwheel:x:10:root\nmail:x:12:mail,exim\nnews:x:13:news\nuucp:x :14:uucp\nman:x:15:\ngames:x:20:\ngopher:x:30:\ndip:x:40:\nftp:x:50:\nlock:x:54: \nnobody:x:99:\nusers:x:100:\nnscd:x:28:\nfloppy:x:19:\nvcsa:x:69:\npcap:x:77:\n utmp:x:22:\nutempter:x:35:\nslocate:x:21:\naudio:x:63:\nrpc:x:32:\nmailnull:x:47 :\nsmmsp:x:51:\necryptfs:x:101:\nsshd:x:74:\ndbus:x:81:\navahi:x:70:\nrpcuser:x: 29:\nnfsnobody:x:65534:\nhaldaemon:x:68:\navahi- autoipd:x:102:\nmysql:x:27:\nftpgroup:x:107:\nexim:x:93:\nscreen:x:84:\nfwh:x:50 0:\nqwqwqw:x:501:\n1q2w3e:x:502:\n1q:x:503:\n2w:x:504:\n", 4096) = 693 [pid 12795] read(4, "", 4096) = 0 [pid 12795] close(4) = 0 [pid 12795] munmap(0x2b017b3ce000, 4096) = 0 [pid 12795] setgroups(1, [500]) = 0 [pid 12795] setuid(500) = 0 [pid 12795] prctl(0x4, 0x1, 0, 0, 0) = 0 [pid 12795] clock_gettime(CLOCK_MONOTONIC, {1029872, 690313456}) = 0 [pid 12795] close(6) = 0 [pid 12795] close(8) = 0 [pid 12795] rt_sigaction(SIGTERM, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, NULL, 8) = 0 [pid 12795] rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, NULL, 8) = 0 [pid 12795] rt_sigaction(SIGUSR1, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, NULL, 8) = 0 [pid 12795] rt_sigaction(SIGUSR2, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, NULL, 8) = 0 [pid 12795] rt_sigaction(SIGCHLD, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, NULL, 8) = 0 [pid 12795] rt_sigaction(SIGQUIT, {0x7c33f0, [], SA_RESTORER|SA_RESTART, 0x322c6302f0}, NULL, 8) = 0 [pid 12795] close(9) = 0 [pid 12795] close(10) = 0 [pid 12795] close(11) = 0 [pid 12795] close(12) = 0 [pid 12795] close(13) = 0 [pid 12795] clock_gettime(CLOCK_MONOTONIC, {1029872, 692338456}) = 0 [pid 12795] accept(0, {sa_family=AF_INET, sin_port=htons(60781), sin_addr=inet_addr("127.0.0.1")}, [16]) = 4 [pid 12795] clock_gettime(CLOCK_MONOTONIC, {1029872, 692611456}) = 0 [pid 12795] time(NULL) = 1342505962 [pid 12795] times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1821051559 [pid 12795] poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}]) [pid 12795] read(4, "\1\1\0\1\0\10\0\0", 8) = 8 [pid 12795] read(4, "\0\1\0\0\0\0\0\0", 8) = 8 [pid 12795] read(4, "\1\4\0\1\4\313\5\0", 8) = 8 [pid 12795] read(4, "\17'SCRIPT_FILENAME/home/_htdocs/public_html/long_loop.php\f\0QUERY_STRING\16\3 REQUEST_METHODGET\f\0CONTENT_TYPE\16\0CONTENT_LENGTH\v\16SCRIPT_NAME/long_loop.p hp\v\16REQUEST_URI/long_loop.php\f\16DOCUMENT_URI/long_loop.php\r\31DOCUMENT_ROO T/home/_htdocs/public_html\17\10SERVER_PROTOCOLHTTP/1.1\21\7GATEWAY_INTERFACECGI /1.1\17\vSERVER_SOFTWAREnginx/1.2.2\v\16REMOTE_ADDR89.221.202.206\v\5REMOTE_PORT 58343\v\16SERVER_ADDR174.142.69.107\v\2SERVER_PORT80\v\20SERVER_NAMEfwh.webasyst .com\t\20HTTP_HOSTfwh.webasyst.com\17\nHTTP_CONNECTIONkeep- alive\22\tHTTP_CACHE_CONTROLmax-age=0\17\200\0\0\215HTTP_USER_AGENTMozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Ubuntu/11.10 Chromium/18.0.1025.168 Chrome/18.0.1025.168 Safari/535.19\v? HTTP_ACCEPTtext/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\24\21 HTTP_ACCEPT_ENCODINGgzip,deflate,sdch\24#HTTP_ACCEPT_LANGUAGEru-RU,ru;q=0.8,en- US;q=0.6,en;q=0.4\23 HTTP_ACCEPT_CHARSETwindows-1251,utf- 8;q=0.7,*;q=0.3\v\200\0\0012HTTP_COOKIE__utma=144069043.2077055053.1307503204.13 42164095.1342166094.132; __utmc=144069043; __utmz=144069043.1341978575.128.65.utmcsr=feedburner|utmccn=Feed:%20webasystcom/ ru%20(Webasyst)|utmcmd=feed; PHPSESSID=uvg77mtbskgn2i0avlmmtaola4; _csrf=5003fbcba78297.60899625; last_page=1%5E%5E%5E%2Fwebasyst%2Fhosting%2F\0\0\0\0\0", 1232) = 1232 [pid 12795] read(4, "\1\4\0\1\0\0\0\0", 8) = 8 [pid 12795] clock_gettime(CLOCK_MONOTONIC, {1029872, 694032456}) = 0 [pid 12795] gettimeofday({1342505962, 584135}, NULL) = 0 [pid 12795] stat("/home/_htdocs/public_html/.user.ini", 0x7fffba4db660) = -1 ENOENT (No such file or directory) [pid 12795] setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0 [pid 12795] rt_sigaction(SIGPROF, {0x7078d0, [PROF], SA_RESTORER|SA_RESTART, 0x322c6302f0}, {SIG_DFL, [], 0}, 8) = 0 [pid 12795] rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0 [pid 12795] lstat("/home/_htdocs/public_html/long_loop.php", {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 [pid 12795] lstat("/home/_htdocs/public_html", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0 [pid 12795] lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs/public_html/long_loop.php", {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 [pid 12795] lstat("/home/_htdocs/public_html", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0 [pid 12795] lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs/public_html/long_loop.php", {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 [pid 12795] lstat("/home/_htdocs/public_html", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0 [pid 12795] lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs/public_html/long_loop.php", {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 [pid 12795] lstat("/home/_htdocs/public_html", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0 [pid 12795] lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] lstat("/home/_htdocs", {st_mode=S_IFDIR|0711, st_size=4096, ...}) = 0 [pid 12795] lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 [pid 12795] open("/home/_htdocs/public_html/long_loop.php", O_RDONLY) = 6 [pid 12795] fstat(6, {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 [pid 12795] fstat(6, {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 [pid 12795] fstat(6, {st_mode=S_IFREG|0644, st_size=76, ...}) = 0 [pid 12795] mmap(NULL, 76, PROT_READ, MAP_SHARED, 6, 0) = 0x2b017b3ce000 [pid 12795] clock_gettime(CLOCK_MONOTONIC, {1029872, 698631456}) = 0 [pid 12795] getcwd("/usr/local/nginx/logs"..., 4095) = 22 [pid 12795] chdir("/home/_htdocs/public_html") = 0 [pid 12795] setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0 [pid 12795] munmap(0x2b017b3ce000, 76) = 0 [pid 12795] close(6) = 0 [pid 12795] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 [pid 12795] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, 8) = 0 [pid 12795] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 [pid 12795] nanosleep({1, 0}, <unfinished ...> [pid 12788] <... epoll_wait resumed> {}, 1, 737) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029873, 411240456}) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029873, 411340456}) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029873, 411447456}) = 0 [pid 12788] epoll_wait(16, <unfinished ...> [pid 12795] <... nanosleep resumed> {1, 0}) = 0 [pid 12795] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 [pid 12795] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, 8) = 0 [pid 12795] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 [pid 12795] nanosleep({1, 0}, <unfinished ...> [pid 12788] <... epoll_wait resumed> {}, 1, 1000) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029874, 411323456}) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029874, 411442456}) = 0 [pid 12788] getsockopt(13, SOL_TCP, TCP_INFO, "\n\0\0\0\0\0\0\0\300\306- \0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\240\23]=\0\0 \0\0\240\23]=\240\23]=\0\0\0\0\0\0\0\0\0\0\0\0\260q\v\0\377\377\377\177\2\0\0\0\ 0\0\0\0\3\0\0\0", [92]) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029874, 411797456}) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029874, 411921456}) = 0 [pid 12788] epoll_wait(16, <unfinished ...> [pid 12795] <... nanosleep resumed> {1, 0}) = 0 [pid 12795] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 [pid 12795] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], SA_RESTORER, 0x322c6302f0}, 8) = 0 [pid 12795] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 [pid 12795] nanosleep({1, 0}, <unfinished ...> [pid 12788] <... epoll_wait resumed> 13bda920, 1, 1000) = -1 EINTR (Interrupted system call) [pid 12788] --- SIGUSR2 (User defined signal 2) @ 0 (0) --- [pid 12788] write(8, "2", 1) = 1 [pid 12788] rt_sigreturn(0x8) = -1 EINTR (Interrupted system call) [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029875, 99361456}) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029875, 99472456}) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, {1029875, 99580456}) = 0 [pid 12788] epoll_wait(16, {{EPOLLIN, {u32=15680416, u64=15680416}}}, 1, 312) = 1 [pid 12788] read(6, "2", 1) = 1 [pid 12788] gettimeofday({1342505964, 989857}, NULL) = 0 [pid 12788] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3477, ...}) = 0 [pid 12788] write(4, "[17-Jul-2012 02:19:24] NOTICE: Reloading in progress ...\n", 57) = 57 [pid 12788] kill(12795, SIGQUIT <unfinished ...> [pid 12795] <... nanosleep resumed> 0x7fffba4d94a0) = ? ERESTART_RESTARTBLOCK (To be restarted) [pid 12788] <... kill resumed> ) = 0 [pid 12795] --- SIGQUIT (Quit) @ 0 (0) --- [pid 12788] clock_gettime(CLOCK_MONOTONIC, <unfinished ...> [pid 12795] close(0 <unfinished ...> [pid 12788] <... clock_gettime resumed> {1029875, 100807456}) = 0 [pid 12795] <... close resumed> ) = 0 [pid 12788] read(6, <unfinished ...> [pid 12795] socket(PF_FILE, SOCK_STREAM, 0 <unfinished ...> [pid 12788] <... read resumed> 0x7fffba4db8b7, 1) = -1 EAGAIN (Resource temporarily unavailable) [pid 12795] <... socket resumed> ) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, <unfinished ...> [pid 12795] rt_sigreturn(0x1 <unfinished ...> [pid 12788] <... clock_gettime resumed> {1029875, 101356456}) = 0 [pid 12795] <... rt_sigreturn resumed> ) = -1 EINTR (Interrupted system call) [pid 12788] kill(12795, SIGTERM <unfinished ...> [pid 12795] rt_sigprocmask(SIG_BLOCK, [CHLD], <unfinished ...> [pid 12788] <... kill resumed> ) = 0 [pid 12795] <... rt_sigprocmask resumed> [], 8) = 0 [pid 12788] clock_gettime(CLOCK_MONOTONIC, <unfinished ...> [pid 12795] --- SIGTERM (Terminated) @ 0 (0) --- Process 12795 detached <... clock_gettime resumed> {1029875, 101834456}) = 0 clock_gettime(CLOCK_MONOTONIC, {1029875, 103461456}) = 0 clock_gettime(CLOCK_MONOTONIC, {1029875, 103566456}) = 0 clock_gettime(CLOCK_MONOTONIC, {1029875, 103843456}) = 0 --- SIGCHLD (Child exited) @ 0 (0) --- write(8, "C", 1) = 1 rt_sigreturn(0x8) = 0 epoll_wait(16, {{EPOLLIN, {u32=15680416, u64=15680416}}}, 1, 308) = 1 read(6, "C", 1) = 1 wait4(-1, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGTERM}], WNOHANG|WSTOPPED, NULL) = 12795 clock_gettime(CLOCK_MONOTONIC, {1029875, 104400456}) = 0 gettimeofday({1342505964, 994394}, NULL) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3477, ...}) = 0 write(4, "[17-Jul-2012 02:19:24] NOTICE: reloading: execvp(\"/usr/sbin/php- fpm\", {\"/usr/sbin/php-fpm\", \"--fpm-config\", \"/etc/php-fpm.conf\"})\n", 130) = 130 munmap(0x2b017b3cf000, 1168) = 0 munmap(0x2b017b3d0000, 1168) = 0 munmap(0x2b017b3d1000, 1168) = 0 munmap(0x2b017b3d2000, 1168) = 0 munmap(0x2b017b3d3000, 1168) = 0 munmap(0x2b017b3d4000, 1168) = 0 munmap(0x2b017b3d5000, 1168) = 0 munmap(0x2b017b3d6000, 1168) = 0 munmap(0x2b017b3d7000, 1168) = 0 munmap(0x2b017eb57000, 1168) = 0 munmap(0x2b017eb58000, 1168) = 0 munmap(0x2b017eb59000, 1168) = 0 munmap(0x2b017ed65000, 1168) = 0 ------------------------------------------------------------------------ The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at https://bugs.php.net/bug.php?id=60961 -- Edit this bug report at https://bugs.php.net/bug.php?id=60961&edit=1