|
php.net | support | documentation | report a bug | advanced search | search howto | statistics | random bug | login |
[2010-11-26 12:57 UTC] php-bugs at thequod dot de
Description:
------------
I have installed php-fpm via yesterday's snapshot.
When starting it, the children appear to constantly exit right away.
This is from the logs:
Nov 26 12:15:12.947902 [NOTICE] pid 13248, fpm_children_make(), line 403: [pool www] child 15605 started
Nov 26 12:15:12.948456 [DEBUG] pid 13248, fpm_got_signal(), line 48: received SIGCHLD
Nov 26 12:15:12.948473 [WARNING] pid 13248, fpm_children_bury(), line 249: [pool www] child 15605 exited with code 1 after 0.000595 seconds from start
Nov 26 12:15:12.948901 [NOTICE] pid 13248, fpm_children_make(), line 403: [pool www] child 15606 started
Nov 26 12:15:12.949390 [DEBUG] pid 13248, fpm_got_signal(), line 48: received SIGCHLD
Nov 26 12:15:12.949406 [WARNING] pid 13248, fpm_children_bury(), line 249: [pool www] child 15606 exited with code 1 after 0.000532 seconds from start
Nov 26 12:15:12.949737 [NOTICE] pid 13248, fpm_children_make(), line 403: [pool www] child 15607 started
Nov 26 12:15:12.950274 [DEBUG] pid 13248, fpm_got_signal(), line 48: received SIGCHLD
Nov 26 12:15:12.950291 [WARNING] pid 13248, fpm_children_bury(), line 249: [pool www] child 15607 exited with code 1 after 0.000572 seconds from start
Nov 26 12:15:12.950646 [NOTICE] pid 13248, fpm_children_make(), line 403: [pool www] child 15608 started
Nov 26 12:15:12.951116 [DEBUG] pid 13248, fpm_got_signal(), line 48: received SIGCHLD
Nov 26 12:15:12.951132 [WARNING] pid 13248, fpm_children_bury(), line 249: [pool www] child 15608 exited with code 1 after 0.000503 seconds from start
I have started it using gdb to get a backtrace (from the master), and this looks like:
Nov 26 12:15:12.952358 [NOTICE] pid 13248, fpm_children_make(), line 403: [pool www] child 15610 started
^Z
Program received signal SIGTSTP, Stopped (user).
0xb7a9612c in epoll_wait () from /lib/libc.so.6
(gdb) bt
#0 0xb7a9612c in epoll_wait () from /lib/libc.so.6
#1 0xb7b21c97 in ?? () from /usr/lib/libevent-1.4.so.2
#2 0xb7b14c5a in event_base_loop () from /usr/lib/libevent-1.4.so.2
#3 0xb7b15095 in event_base_dispatch () from /usr/lib/libevent-1.4.so.2
#4 0x083ab9f6 in fpm_event_loop (base=0x8921ef8) at /build/buildd/php5-5.3.4~snap201011251930/sapi/fpm/fpm/fpm_events.c:112
#5 0x083a7130 in fpm_run (max_requests=0xbfffd580, base=0x8921ef8) at /build/buildd/php5-5.3.4~snap201011251930/sapi/fpm/fpm/fpm.c:76
#6 0x083ad45e in main (argc=3, argv=0xbffff684) at /build/buildd/php5-5.3.4~snap201011251930/sapi/fpm/fpm/fpm_main.c:1787
Maybe not really useful, but still..
Here's a "strace -f" of the process:
write(2, "Nov 26 12:22:46.736565 [WARNING]"..., 151Nov 26 12:22:46.736565 [WARNING] pid 23701, fpm_children_bury(), line 249: [pool www] child 25335 exited with code 1 after 0.001438 seconds from start
) = 151
pipe([10, 11]) = 0
pipe([12, 13]) = 0
fcntl64(10, F_GETFL) = 0 (flags O_RDONLY)
fcntl64(10, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
fcntl64(12, F_GETFL) = 0 (flags O_RDONLY)
fcntl64(12, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7019748) = 25336
clock_gettime(CLOCK_MONOTONIC, {1760242, 289405933}) = 0
close(11) = 0
close(13) = 0
epoll_ctl(7, EPOLL_CTL_ADD, 10, {EPOLLIN, {u32=10, u64=10}}) = 0
epoll_ctl(7, EPOLL_CTL_ADD, 12, {EPOLLIN, {u32=12, u64=12}}) = 0
gettimeofday({1290770566, 737322}, NULL) = 0
write(2, "Nov 26 12:22:46.737322 [NOTICE] "..., 105Nov 26 12:22:46.737322 [NOTICE] pid 23701, fpm_children_make(), line 403: [pool www] child 25336 started
) = 105
waitpid(-1, 0xbfaa8c18, WNOHANG|WSTOPPED) = 0
read(4, 0xbfaa8cef, 1) = -1 EAGAIN (Resource temporarily unavailable)
epoll_wait(7, {{EPOLLHUP, {u32=10, u64=10}}}, 32, 10) = 1
--- SIGCHLD (Child exited) @ 0 (0) ---
write(5, "C", 1) = 1
sigreturn() = ? (mask now [])
clock_gettime(CLOCK_MONOTONIC, {1760242, 290274890}) = 0
read(10, "", 1023) = 0
epoll_ctl(7, EPOLL_CTL_DEL, 10, {EPOLLIN, {u32=10, u64=10}}) = 0
close(10) = 0
epoll_wait(7, {{EPOLLHUP, {u32=12, u64=12}}, {EPOLLIN, {u32=4, u64=4}}}, 32, 9) = 2
clock_gettime(CLOCK_MONOTONIC, {1760242, 290435633}) = 0
read(12, "", 1023) = 0
epoll_ctl(7, EPOLL_CTL_DEL, 12, {EPOLLIN, {u32=12, u64=12}}) = 0
close(12) = 0
read(4, "C", 1) = 1
gettimeofday({1290770566, 738251}, NULL) = 0
write(2, "Nov 26 12:22:46.738251 [DEBUG] p"..., 86Nov 26 12:22:46.738251 [DEBUG] pid 23701, fpm_got_signal(), line 48: received SIGCHLD
) = 86
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG|WSTOPPED) = 25336
clock_gettime(CLOCK_MONOTONIC, {1760242, 290729116}) = 0
gettimeofday({1290770566, 738426}, NULL) = 0
write(2, "Nov 26 12:22:46.738426 [WARNING]"..., 151Nov 26 12:22:46.738426 [WARNING] pid 23701, fpm_children_bury(), line 249: [pool www] child 25336 exited with code 1 after 0.001324 seconds from start
) = 151
Although using "catch_workers_output = yes" I do not see anything in the log related to child exiting.
PatchesPull RequestsHistoryAllCommentsChangesGit/SVN commits
|
|||||||||||||||||||||||||||
Copyright © 2001-2025 The PHP GroupAll rights reserved. |
Last updated: Thu Oct 30 16:00:01 2025 UTC |
Still the same problem, using snap201011261530. I cannot reopen the ticket ("You aren't allowed to change a bug to that state.").Nov 29 13:39:18.967256 [WARNING] [pool www] child 29567 exited with code 1 after 0.001296 seconds from start ^Z Program received signal SIGTSTP, Stopped (user). 0xb7a77f32 in fork () from /lib/libc.so.6 (gdb) bt #0 0xb7a77f32 in fork () from /lib/libc.so.6 #1 0x083a7132 in fpm_children_make (wp=0x8920d08, in_event_loop=1, nb_to_spawn=1, is_debug=0) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c:376 #2 0x083a7707 in fpm_children_bury () at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c:285 #3 0x083abed7 in fpm_got_signal (ev=0x87bba80, which=2, arg=0x0) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_events.c:76 #4 0x083ab528 in fpm_event_fire (ev=0x87bba80) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_events.c:373 #5 0x083abb3d in fpm_event_loop () at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_events.c:317 #6 0x083a6e85 in fpm_run (max_requests=0xbfffd580) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm.c:76 #7 0x083ad78a in main (argc=3, argv=0xbffff684) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_main.c:1786 I guess that it would be more interesting to debug the child, which I did not manage to do. I've tried using "catch fork" to stop on the call to fork, and then both tried "follow-fork-mode=child" and stepping, but this does not allow me to step into the forked process (after the fork the next "n" command will start the endless forking/looping again). Please tell me how to debug this: a catch on "fork" appears to make sense. Should I then use another gdb instance to debug the child? I've tried that, but got "ptrace: Operation not permitted." then. Is this because it's too early to attach?Sorry, there is no backtrace with sigfault as there is no segfault ... Can you patch fpm_children.c like this: Index: fpm_children.c =================================================================== --- fpm_children.c (révision 305775) +++ fpm_children.c (copie de travail) @@ -374,6 +374,7 @@ } pid = fork(); +zlog(ZLOG_DEBUG, "pid after fork=%d", pid); switch (pid) { and test again (daemonize=no; log_level=debug) send here your log file content.Unfortunately this does not work: "exit" is not undefined in my case, and when running the program (using "-y main.conf" it starts looping right away). However, I have something more/new: (gdb) set follow-fork-mode child (gdb) catch fork Catchpoint 1 (fork) (gdb) break exit Breakpoint 2 at 0x806a2f0 (gdb) run -y main.conf Starting program: /usr/sbin/php5-fpm -y main.conf [Thread debugging using libthread_db enabled] [New Thread 0xb7591b70 (LWP 24013)] [Thread 0xb7591b70 (LWP 24013) exited] Nov 30 17:20:22.583597 [DEBUG] pid 24010, fpm_event_init_main(), line 229: 1 fds have been reserved Nov 30 17:20:22.583701 [NOTICE] pid 24010, fpm_init(), line 52: fpm is running, pid 24010 Catchpoint 1 (forked process 24014), 0xb7a77f32 in __libc_fork () at ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c:130 130 ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c: No such file or directory. in ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c (gdb) n [New process 24014] [Thread debugging using libthread_db enabled] Nov 30 17:20:33.356489 [DEBUG] pid 24010, fpm_children_make(), line 377: pid after fork=24014 Nov 30 17:20:33.356517 [DEBUG] pid 24010, fpm_children_make(), line 400: [pool www] child 24014 started Nov 30 17:20:33.356527 [NOTICE] pid 24010, fpm_event_loop(), line 254: ready to handle connections 137 in ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c [...] 216 in ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c fpm_children_make (wp=0x8924b30, in_event_loop=0, nb_to_spawn=0, is_debug=1) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c:377 377 /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c: No such file or directory. in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 376 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 377 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c Nov 30 17:22:45.638098 [DEBUG] pid 24014, fpm_children_make(), line 377: pid after fork=0 379 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 337 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 338 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 59 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 383 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 146 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 383 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 146 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 148 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 149 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 148 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 150 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 148 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 151 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 148 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 152 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 148 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 153 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 148 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c 406 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c fpm_children_create_initial (wp=0x8924b30) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c:412 412 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c fpm_run (max_requests=0xbfffd590) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm.c:70 70 /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm.c: No such file or directory. in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm.c 80 in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm.c Using "next"/"n" the next time causes the infinite loop. I cannot see what is going on there really, because the scrollback buffer is spammed fast and I need to switch to another screen window to "pkill -9 -f php-fpm". Apparently the child/fork I've followed in gdb exits here?! Debugging this further, it looks like the child itselfs calls fork again? (gdb) set follow-fork-mode child (gdb) catch fork Catchpoint 1 (fork) (gdb) break exit Breakpoint 2 at 0x806a2f0 (gdb) break fpm_children_create_initial Breakpoint 3 at 0x83a73b6: file /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c, line 411. (gdb) run -y main.conf Starting program: /usr/sbin/php5-fpm -y main.conf [Thread debugging using libthread_db enabled] [New Thread 0xb7591b70 (LWP 26154)] [Thread 0xb7591b70 (LWP 26154) exited] Nov 30 17:37:05.574273 [DEBUG] pid 26151, fpm_event_init_main(), line 229: 1 fds have been reserved Nov 30 17:37:05.574381 [NOTICE] pid 26151, fpm_init(), line 52: fpm is running, pid 26151 Breakpoint 3, fpm_children_create_initial (wp=0x8924b30) at /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c:411 411 /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c: No such file or directory. in /build/buildd/php5-5.3.4~snap201011290730/sapi/fpm/fpm/fpm_children.c (gdb) n Catchpoint 1 (forked process 26155), 0xb7a77f32 in __libc_fork () at ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c:130 130 ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c: No such file or directory. in ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c (gdb) n [New process 26155] Nov 30 17:37:13.200755 [DEBUG] pid 26151, fpm_children_make(), line 377: pid after fork=26155 Nov 30 17:37:13.200784 [DEBUG] pid 26151, fpm_children_make(), line 400: [pool www] child 26155 started Nov 30 17:37:13.200799 [NOTICE] pid 26151, fpm_event_loop(), line 254: ready to handle connections [Thread debugging using libthread_db enabled] 137 in ../nptl/sysdeps/unix/sysv/linux/i386/../fork.c When coming to the last line (80 in fpm.c), I can do "ni" once, before the second one triggers the loop again. I could setup a remote box for you, if this would help you debugging this. However, my fear grows that this is related to some Debian/Ubuntu patch (and I should check vanilla PHP), but this also means that you could try the Ubuntu build as well as a remote box.