php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #52796 Sep 08 15:22:32.861368 [WARNING] [pool www0] child 25271 said into stderr: "php
Submitted: 2010-09-08 14:28 UTC Modified: 2010-10-06 02:36 UTC
From: momchil at xaxo dot eu Assigned: fat (profile)
Status: Not a bug Package: FPM related
PHP Version: 5.3SVN-2010-09-08 (SVN) OS: linux
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: momchil at xaxo dot eu
New email:
PHP Version: OS:

 

 [2010-09-08 14:28 UTC] momchil at xaxo dot eu
Description:
------------
the server got high load today, php processes were consuming lots of cpu and most php processes were in the R state, php-fpm.log was full with:

Sep 08 15:22:32.644908 [NOTICE] [pool www0] child 25248 started
Sep 08 15:22:32.743826 [WARNING] [pool www0] child 25248 exited on signal 6 SIGABRT after 0.098934 seconds from start
Sep 08 15:22:32.743890 [WARNING] [pool www0] child 25248 said into stderr: "php-fpm: event.c:261: event_base_free: Assertion `(((&base->eventqueue)->tqh_first) == ((void *)0))' failed."
Sep 08 15:22:32.789892 [NOTICE] [pool www0] child 25262 started
Sep 08 15:22:32.830163 [WARNING] [pool www0] child 25262 exited on signal 6 SIGABRT after 0.040331 seconds from start
Sep 08 15:22:32.830233 [WARNING] [pool www0] child 25262 said into stderr: "php-fpm: event.c:261: event_base_free: Assertion `(((&base->eventqueue)->tqh_first) == ((void *)0))' failed."
Sep 08 15:22:32.861300 [NOTICE] [pool www0] child 25271 started
Sep 08 15:22:32.861346 [WARNING] [pool www0] child 25271 exited on signal 6 SIGABRT after 0.000059 seconds from start
Sep 08 15:22:32.861368 [WARNING] [pool www0] child 25271 said into stderr: "php-fpm: event.c:261: event_base_free: Assertion `(((&base->eventqueue)->tqh_first) == ((void *)0))' failed."


I am using r299968 of php 5.3 on Linux 2.6.24-gentoo-r8 x86_64

Test script:
---------------
don't know how to reproduce


Patches

fpm-nomorelibevent.v5.patch (last revision 2010-09-17 07:48 UTC) by fat@php.net)
fpm-nomorelibevent.v2.patch (last revision 2010-09-14 15:38 UTC) by fat@php.net)

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2010-09-08 14:35 UTC] fat@php.net
-Status: Open +Status: Feedback -Assigned To: +Assigned To: fat
 [2010-09-08 14:35 UTC] fat@php.net
- did you reload FPM ?

- does your PHP scripts forks somehow ?

- does your PHP scripts send mail through the mail() function ? does it work ?
 [2010-09-08 14:53 UTC] momchil at xaxo dot eu
-Status: Feedback +Status: Assigned
 [2010-09-08 14:53 UTC] momchil at xaxo dot eu
the scripts do none of the above and I did not reload fpm
 [2010-09-08 14:56 UTC] fat@php.net
-Status: Assigned +Status: Feedback
 [2010-09-08 14:56 UTC] fat@php.net
can you pastbin the full php-fpm.log and your config please ?
 [2010-09-08 15:11 UTC] momchil at xaxo dot eu
-Status: Feedback +Status: Assigned
 [2010-09-08 15:11 UTC] momchil at xaxo dot eu
http://img01.gepime.com/php-fpm.conf
http://img01.gepime.com/php-fpm.log

btw the log is 334MB (it's a busy server)
 [2010-09-09 23:38 UTC] momchil at xaxo dot eu
umf... got it on another server with another website running r301234

Sep 10 00:08:15.534321 [WARNING] [pool www0] child 25119, script '/www/grabo.bg/www/root/index.php' execution timed out (30.126267 sec), terminating
Sep 10 00:08:15.537840 [WARNING] [pool www0] child 25119 exited on signal 15 SIGTERM after 124.330987 seconds from start
Sep 10 00:08:15.538251 [NOTICE] [pool www0] child 27012 started
Sep 10 00:08:15.539222 [WARNING] [pool www0] child 27012 exited on signal 11 SIGSEGV after 0.000991 seconds from start
Sep 10 00:08:15.539538 [NOTICE] [pool www0] child 27013 started
Sep 10 00:08:15.544915 [WARNING] [pool www0] child 27013 exited on signal 11 SIGSEGV after 0.005390 seconds from start
Sep 10 00:08:15.545278 [NOTICE] [pool www0] child 27015 started
Sep 10 00:08:15.554279 [WARNING] [pool www0] child 27015 exited on signal 11 SIGSEGV after 0.009020 seconds from start
Sep 10 00:08:15.554629 [NOTICE] [pool www0] child 27016 started
Sep 10 00:08:15.555623 [WARNING] [pool www0] child 27016 exited on signal 11 SIGSEGV after 0.001011 seconds from start
Sep 10 00:08:15.555929 [NOTICE] [pool www0] child 27017 started
Sep 10 00:08:15.556648 [WARNING] [pool www0] child 27017 exited on signal 11 SIGSEGV after 0.000739 seconds from start
Sep 10 00:08:15.556904 [NOTICE] [pool www0] child 27018 started
Sep 10 00:08:15.557602 [WARNING] [pool www0] child 27018 exited on signal 11 SIGSEGV after 0.000720 seconds from start
Sep 10 00:08:15.557848 [NOTICE] [pool www0] child 27019 started
Sep 10 00:08:15.558532 [WARNING] [pool www0] child 27019 exited on signal 11 SIGSEGV after 0.000705 seconds from start
Sep 10 00:08:15.558774 [NOTICE] [pool www0] child 27020 started
Sep 10 00:08:15.559492 [WARNING] [pool www0] child 27020 exited on signal 11 SIGSEGV after 0.000738 seconds from start
Sep 10 00:08:15.559747 [NOTICE] [pool www0] child 27021 started
Sep 10 00:08:15.560549 [WARNING] [pool www0] child 27021 exited on signal 11 SIGSEGV after 0.000822 seconds from start
Sep 10 00:08:15.560911 [NOTICE] [pool www0] child 27022 started
Sep 10 00:08:15.561798 [WARNING] [pool www0] child 27022 exited on signal 11 SIGSEGV after 0.000905 seconds from start
Sep 10 00:08:15.561850 [WARNING] failed processes threshold (10 in 60 sec) is reached, initiating reload
Sep 10 00:08:15.650499 [NOTICE] reloading: execvp("/usr/local/php/sbin/php-fpm", {"/usr/local/php/sbin/php-fpm"})
php-fpm: event.c:261: event_base_free: Assertion `(((&base->eventqueue)->tqh_first) == ((void *)0))' failed.
 [2010-09-09 23:43 UTC] momchil at xaxo dot eu
fpm.conf of the above one:
[global]
pid                         = /var/run/php-fpm.pid
error_log                   = /var/log/php/php-fpm.log
log_level                   = notice
emergency_restart_threshold = 10
emergency_restart_interval  = 1m
process_control_timeout     = 5s
daemonize                   = yes

[www0]
listen                      = 127.0.0.1:9910
listen.backlog              = -1
listen.allowed_clients      = 127.0.0.1
user                        = php
group                       = php
pm                          = dynamic
pm.max_children             = 100
pm.start_servers            = 10
pm.min_spare_servers        = 5
pm.max_spare_servers        = 20
pm.max_requests             = 500
pm.status_path              = /status
ping.path                   = /ping
ping.response               = pong
request_terminate_timeout   = 30s
request_slowlog_timeout     = 15s
slowlog                     = /var/log/php/php-fpm-0.log.slow
rlimit_files                = 20000
rlimit_core                 = 0
catch_workers_output        = yes
 
 env[HOSTNAME]               = $HOSTNAME
 env[PATH]                   = /usr/local/bin:/usr/bin:/bin
 env[TMP]                    = /tmp
 env[TMPDIR]                 = /tmp
 env[TEMP]                   = /tmp
 [2010-09-09 23:47 UTC] fat@php.net
-Status: Assigned +Status: Feedback
 [2010-09-09 23:47 UTC] fat@php.net
You have a lots of error in your LOG file:

1- Sep 08 14:10:10.251071 [WARNING] [pool www0] child 13097 said into stderr: "Connection from 
disallowed IP address '10.13.20.24' is dropped."

you should allow those IP address

2- you have a lots of PHP errors which are written to stdout. Search for "said into stderr" in 
you LOG file.

3- You have calls from external command (rm, convert). when run, php forks for running those 
command. The problem seem to be similar to bug http://bugs.php.net/52501

4- you have a lot of requests which are executing too slow after 15s and which are ptraced to 
slowlog.

5- you have a lot of requests which are timeouted after 30s.

6- you have a lot of warning saying your server "seems busy". you should review your 
configuration file to increase min/max_spare_server.

4- I asked if you did reload FPM. You said no and your LOG file says you had:

Sep 08 03:10:07.634996 [NOTICE] using inherited socket fd=6, "10.13.20.26:9910"

5- I asked if your PHP scripts forks somehow. It appears so


finaly, the problem occurs when:

- some PHP scripts are forking some process (via system() or mail())
- FPM is reloading via emergency_restart_threshold

It's a bug related to libevent and forking. I'm on it. You should try disabling 
emergency_restart_threshold temporarily.
 [2010-09-09 23:57 UTC] momchil at xaxo dot eu
-Status: Feedback +Status: Assigned
 [2010-09-09 23:57 UTC] momchil at xaxo dot eu
1,2,4,5 are known.

about forking: I thought you mean forking inside php code and did not thought about system(), there is some code using the system() function.
reloading: I did not reload fpm at the moment when the crash happened, we are reloading it on fpm.conf/php.ini changes

about what I wrote just before on 2010-09-09 21:38 UTC: I was told that the mail() function has been used about 1500 times in a script for sending newsletter, which might be related as you pointed out.

I will try without the emergency restart as you suggest, thank you for the pointers and your time investigating this :)
 [2010-09-10 00:00 UTC] fat@php.net
you should not use FPM reloading since this bug has not been corrected. Please use 
restart instead.
 [2010-09-10 00:03 UTC] momchil at xaxo dot eu
ok, can you please point me to the bug report about reloading so that I can follow it and know when it gets fixed?
 [2010-09-10 00:08 UTC] fat@php.net
just follow the current bug and the following http://bugs.php.net/52501
 [2010-09-14 17:38 UTC] fat@php.net
The following patch has been added/updated:

Patch Name: fpm-nomorelibevent.v2.patch
Revision:   1284478708
URL:        http://bugs.php.net/patch-display.php?bug=52796&patch=fpm-nomorelibevent.v2.patch&revision=1284478708
 [2010-09-14 17:38 UTC] fat@php.net
-Status: Assigned +Status: Feedback
 [2010-09-14 17:38 UTC] fat@php.net
Can you please test the following patch ?

This patch removes libevent from FPM. A simple select base event mechanism has 
been made instead. It should prevent the forking problem when using libevent.
 [2010-09-17 09:48 UTC] fat@php.net
The following patch has been added/updated:

Patch Name: fpm-nomorelibevent.v5.patch
Revision:   1284709736
URL:        http://bugs.php.net/patch-display.php?bug=52796&patch=fpm-nomorelibevent.v5.patch&revision=1284709736
 [2010-09-17 09:49 UTC] fat@php.net
can you please test the new patch (v5) ?
 [2010-09-17 10:28 UTC] momchil at xaxo dot eu
-Status: Feedback +Status: Assigned
 [2010-09-17 10:28 UTC] momchil at xaxo dot eu
yes, I will test it next week, thank you
 [2010-10-06 02:36 UTC] fat@php.net
-Status: Assigned +Status: Bogus
 [2010-10-06 02:36 UTC] fat@php.net
Please do not submit the same bug more than once. An existing
bug report already describes this very problem. Even if you feel
that your issue is somewhat different, the resolution is likely
to be the same. 

Thank you for your interest in PHP.

See http://bugs.php.net/52501.
 
PHP Copyright © 2001-2017 The PHP Group
All rights reserved.
Last updated: Sun Nov 19 01:31:42 2017 UTC