Error and shutdown handlers triggered on object destroy

Bug #76224	Error and shutdown handlers triggered on object destroy
Submitted:	2018-04-15 13:25 UTC	Modified:	2021-11-30 21:20 UTC
From:	we at mokraemer dot de	Assigned:	bukka (profile)
Status:	Re-Opened	Package:	FPM related
PHP Version:	7.3.6	OS:	Linux Mageia 7
Private report:	No	CVE-ID:	None

[2018-04-15 13:25 UTC] we at mokraemer dot de

Description:
------------
I get errors like
"Maximum execution time of 30 seconds exceeded" hours after the real request was successfully served.
Together with errors from a registered shutdown handler which is triggered.

My assumption is, the object stays in RAM for reuse and on cleanup the shutdown handler is triggered.

_Server[REQUEST_TIME_FLOAT] => 1523715452.2153

Time of the triggered error 1523742703

Which is 27251 seconds after the request and ~7.5 hours later.

- PHP 5.6.35 (cli) (built: Mar 31 2018 15:35:22)
- Extensions: Core,date,ereg,libxml,pcre,Reflection,SPL,SimpleXML,hash,bz2,ctype,curl,dom,session,openssl,zlib,gd,gettext,iconv,standard,intl,mbstring,mcrypt,fileinfo,mysqlnd,mysqli,pcntl,posix,exif,soap,imap,sysvmsg,sysvsem,sysvshm,tokenizer,xml,xmlreader,xmlwriter,bcmath,PDO,pdo_mysql,filter,json,zip,Phar,timezonedb,memcached,wbxml,xdebug


Is there any more information I can provide? I don't know how to track this down.

Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports

[2018-04-15 13:28 UTC] spam2 at rhsoft dot net

can you reproduce that with any supported version?

breaking news: php5 is dead, PHP 7.0 is EOL
7.1/7.2 are active supported

anything below only for critical security issues

[2018-06-24 04:25 UTC] php-bugs at lists dot php dot net

No feedback was provided. The bug is being suspended because
we assume that you are no longer experiencing the problem.
If this is not the case and you are able to provide the
information that was requested earlier, please do so and
change the status of the bug back to "Re-Opened". Thank you.

[2018-11-23 09:27 UTC] php at mokraemer dot de

Just updated to php 7.2.11. Still the same error. This happens if php opcache is enabled.

[2018-11-23 09:31 UTC] requinix@php.net

-Status: No Feedback +Status: Re-Opened -PHP Version: 5.6.35 +PHP Version: 7.2

[2018-11-23 10:57 UTC] php at mokraemer dot de

I'll do a test without opcache. Since this is production environment, I have to schedule it.

Reloading config with SIGUSR2 does not work. If you do, the running php-fpm instance is not functional any more.

[2018-11-26 21:53 UTC] we at mokraemer dot de

After 1 day I received 4 aborts of type "Maximum execution time of 30 seconds exceeded". I've tested with module opcache NOT loaded, so my guess was wrong.

# [REQUEST_TIME_FLOAT] Errorhandler_Trigger_Time DIFF
1 1543204413.981       1543250453                46040
2 1543223900.9792      1543255939                32039
3 1543223900.9832      1543266606                42706
4 1543223900.9814      1543267932                44032


Compilation-Flags:

'./configure' '--with-apxs2=/usr/bin/apxs' '--build=x86_64-mageia-linux-gnu' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--localstatedir=/var/lib' '--mandir=/usr/share/man' '--enable-shared=yes' '--enable-static=no' '--with-libdir=lib64' '--with-config-file-path=/etc' '--with-config-file-scan-dir=/etc/php.d' '--disable-debug' '--enable-inline-optimization' '--with-pcre-regex=/usr' '--with-zlib=/usr' '--with-pdo-odbc=unixODBC' '--with-zlib=shared,/usr' '--with-openssl=shared,/usr' '--with-openssl-dir=/usr' '--enable-libxml=/usr' '--enable-mod_charset' '--without-pear' '--enable-bcmath=shared' '--with-bz2=shared,/usr' '--enable-calendar=shared' '--enable-ctype=shared' '--with-curl=shared,/usr' '--without-curlwrappers' '--enable-dba=shared' '--with-gdbm' '--with-db4' '--with-cdb' '--enable-dom=shared,/usr' '--with-enchant=shared,/usr' '--enable-exif=shared' '--enable-fileinfo=shared' '--enable-filter=shared' '--with-pcre-dir=/usr' '--enable-intl=shared' '--with-icu-dir=/usr' '--enable-json=shared' '--with-libjson' '--enable-ftp=shared' '--with-gd=shared,/usr' '--with-jpeg-dir=/usr' '--with-webp-dir=/usr' '--with-png-dir=/usr' '--with-zlib-dir=/usr' '--with-xpm-dir=/usr/X11R6' '--with-freetype-dir=/usr' '--enable-gd-native-ttf' '--with-gettext=shared,/usr' '--with-gmp=shared,/usr' '--enable-hash=shared,/usr' '--with-iconv=shared' '--with-imap=shared,/usr' '--with-imap-ssl=/usr' '--with-ldap=shared,/usr' '--with-ldap-sasl=/usr' '--enable-mbstring=shared,/usr' '--enable-mbregex' '--with-libmbfl=/usr' '--with-onig=/usr' '--with-mysqli=shared,mysqlnd' '--with-mysql-sock=/var/lib/mysql/mysql.sock' '--enable-mysqlnd=shared,/usr/bin/mysql_config' '--with-unixODBC=shared,/usr' '--enable-opcache=shared' '--enable-pcntl=shared' '--enable-pdo=shared,/usr' '--with-pdo-dblib=shared,/usr' '--with-pdo-mysql=shared,mysqlnd' '--with-pdo-odbc=shared,unixODBC,/usr' '--with-pdo-pgsql=shared,/usr' '--with-pdo-sqlite=shared,/usr' '--with-pgsql=shared,/usr' '--enable-phar=shared' '--enable-posix=shared' '--with-readline=shared,/usr' '--with-recode=shared,/usr' '--enable-session=shared,/usr' '--enable-shmop=shared,/usr' '--enable-simplexml' '--with-snmp=shared,/usr' '--enable-soap=shared,/usr' '--enable-sockets=shared,/usr' '--with-sqlite3=shared,/usr' '--enable-sysvmsg=shared,/usr' '--enable-sysvsem=shared,/usr' '--enable-sysvshm=shared,/usr' '--with-tidy=shared,/usr' '--enable-tokenizer=shared,/usr' '--enable-xml=shared,/usr' '--enable-xmlreader=shared,/usr' '--with-xmlrpc=shared,/usr' '--enable-xmlwriter=shared,/usr' '--with-xsl=shared,/usr' '--enable-wddx=shared' '--with-libxml-dir=/usr' '--enable-zip=shared' '--with-libzip=/usr' '--with-interbase=shared,/usr/lib64/firebird' '--with-pdo-firebird=shared,/usr/lib64/firebird' '--enable-phpdbg' '--enable-phpdbg-webhelper' 'build_alias=x86_64-mageia-linux-gnu'


Anything else you need?

[2019-07-22 10:36 UTC] we at mokraemer dot de

-Operating System: Linux Mageia 6 +Operating System: Linux Mageia 7 -PHP Version: 7.2 +PHP Version: 7.3.6

[2019-07-22 10:36 UTC] we at mokraemer dot de

The same problem exists for the current release 7.3.x:
Maximum execution time of 30 seconds exceeded

[REQUEST_TIME] => 1563669631 (21.07.2019 00:37:40)
Log-Time: 2019-07-21 13:06:01

Is it possible this has sth. to do with persistent database connections using mysqli class?

[2019-07-28 09:48 UTC] php at mokraemer dot de

I can see some processes do not get renewed:
apache     546  0.0  0.1 341852 19904 ?        S    02:38   0:32 php-fpm: pool www
apache     566  0.0  0.1 341852 19796 ?        S    02:39   0:32 php-fpm: pool www
apache     627  0.0  0.1 341848 19960 ?        S    02:41   0:32 php-fpm: pool www
apache   12982  0.1  0.2 343384 39324 ?        S    11:09   0:02 php-fpm: pool www
apache   14048  0.0  0.1 342252 25292 ?        S    11:39   0:00 php-fpm: pool www
apache   14049  0.0  0.1 342252 29304 ?        S    11:39   0:00 php-fpm: pool www
apache   14050  0.0  0.1 342316 29636 ?        S    11:39   0:00 php-fpm: pool www
root     30813  0.0  0.2 341472 32788 ?        Ss   01:12   0:01 php-fpm: master process (/etc/php-fpm.conf)


As you can see the processes 546, 566, 627 have already run longer than the maximum execution time (30) and have surely fullfilled enough requests so they should get renewed.

Logfile says:
[28-Jul-2019 02:53:06] WARNING: [pool www] server reached max_children setting (120), consider raising it

Is there a case if the limit is hit?

[2021-11-30 21:20 UTC] bukka@php.net

-Assigned To: +Assigned To: bukka

[2021-11-30 21:20 UTC] bukka@php.net

I realize that this is quite old but is this still happening on any of the supported version (at least 7.4, ideally check on 8.0)? If so, would you be able to configure slowlog as it might show some clues.