php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #74093 Maximum execution time of n+2 seconds exceed not written in error_log
Submitted: 2017-02-13 14:48 UTC Modified: 2017-02-15 04:34 UTC
Votes:1
Avg. Score:3.0 ± 0.0
Reproduced:0 of 0 (0.0%)
From: rainer-phpbugs at 7val dot com Assigned: laruence (profile)
Status: Closed Package: FPM related
PHP Version: 7.1.1 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: rainer-phpbugs at 7val dot com
New email:
PHP Version: OS:

 

 [2017-02-13 14:48 UTC] rainer-phpbugs at 7val dot com
Description:
------------
If a Library call does not return within 2s after the max_execution_time has been exceeded, zend_timeout_handler() in Zend/zend_execute_API.c approx. Line 1201 emits the error message to STDERR instead of writing it into the error_log and then kills the child. As a result, the following message, without any further explanation, is logged in error_log:

child 23444 exited with code 1 after 360.705768 seconds from start

If catch_workers_output is enabled, the "Maximum execution [...] exceeded" message is logged in error_log, prefixed with "said into stderr".

This is a regression from PHP 7.0. (tested with 7.0.15, which logs a message in error_log, while 7.1.1 does not with the default configuration).

Test script:
---------------
<?php
/* generate an image with lots of colors using imagemagick:
convert -size 4096x4096 -define gradient:direction=east gradient:red-green PNG48:hor_gradient.png
convert hor_gradient.png -rotate 90 gradient_h.png
convert -size 4096x4096 gradient: PNG48:linear_gradient.png
composite linear_gradient.png -compose Multiply gradient_h.png grad.png

or download from http://can avan.de/lots_of_colors.png
*/

$i = new imagick();
$i->readimage('grad.png');
print($i->getImageColors()."\n");


Expected result:
----------------
"Fatal error: Maximum execution time of 30+2 seconds" should be logged in the configured error_log, just like the "Fatal error: Maximum execution time of 30 seconds" message. 

This should be independent of the catch_workers_output setting.

Actual result:
--------------
Only "child 1903 exited with code 1 after 68.983009 seconds from start" is logged.

Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2017-02-14 08:06 UTC] laruence@php.net
-Status: Open +Status: Feedback
 [2017-02-14 08:06 UTC] laruence@php.net
this is an expected behavior, since 7.1 we have new safe timeout handling system, and you example must trigger hard_timeout, in that case, no php function can be called for safety, so we only can call fprintf(stderr instead..

thanks
 [2017-02-14 10:28 UTC] rainer-phpbugs at 7val dot com
-Status: Feedback +Status: Open
 [2017-02-14 10:28 UTC] rainer-phpbugs at 7val dot com
That is unfortunate. Is _php_error_log_ex() or php_log_err_with_severity() really considered unsafe in this context? If so, is there any chance this could be changed?

If that is not possible, can unique exit codes be used to signify the reason the php-fpm child was killed?

Chainging the default value of catch_workers_output to "yes" may work for me, but I suspect that it may not be a good solution for everybody.
 [2017-02-15 04:33 UTC] laruence@php.net
Automatic comment on behalf of laruence@gmail.com
Revision: http://git.php.net/?p=php-src.git;a=commit;h=1242f53ddb018cdba93a9ffe4f56554a6471901f
Log: Workaround to fix bug #74093 (Maximum execution time of n+2 seconds exceed not written in error_log)
 [2017-02-15 04:33 UTC] laruence@php.net
-Status: Open +Status: Closed
 [2017-02-15 04:34 UTC] laruence@php.net
-Assigned To: +Assigned To: laruence
 [2017-02-15 04:34 UTC] laruence@php.net
right, I change the exit code from 1 to 124, 124 is also used by linux timeout 

https://github.com/php/php-src/commit/1242f53ddb018cdba93a9ffe4f56554a6471901f
 [2018-04-05 12:57 UTC] arekm at maven dot pl
There is a problem though.

Error is written to error log now but it lacks virtual host name in apache if error log uses it (%v) like:

ErrorLogFormat "%v [%t] [%l] [pid %P] [client %a] %M %m"

Normal timeouts have %v (vhost name) logged properly. Hard timeouts have no host name logged in error_log.
 [2018-04-05 12:58 UTC] arekm at maven dot pl
But I guess new bug report is needed since this is about FPM only and mine is apache related.
 
PHP Copyright © 2001-2018 The PHP Group
All rights reserved.
Last updated: Thu Sep 20 09:01:25 2018 UTC