php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #80728 PHP built-in web server resets timeout when it can kill the process
Submitted: 2021-02-10 17:34 UTC Modified: -
From: calvin at cmpct dot info Assigned:
Status: Open Package: Built-in web server
PHP Version: 7.4.15 OS: Fedora 33
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: calvin at cmpct dot info
New email:
PHP Version: OS:

 

 [2021-02-10 17:34 UTC] calvin at cmpct dot info
Description:
------------
When the PHP built-in development webserver finishes a request, it resets PHP's timer to defaults. On ITIMER_PROF (most) platforms, this usually isn't a problem because listening causes PHP to block on listen, stopping it from counting in execution time. On ITIMER_REAL platforms (IBM i and Cygwin), the timer will continue to count down and hit the hard timeout, killing an idle PHP development web server. (This may affect other mediums of PHP, but the development web server is the easiest case.)

The attached patch will add debug output for handling the ITIMER cases and let you force ITIMER_REAL on Linux.

The issue is likely reproducible on 7.3 and 8.0.

Test script:
---------------
<?php

set_time_limit(10); // recommend setting to a large value to diagnose ITIMER_REAL

$i = 0;
while(true) {
        sleep(1); // comment if using ITIMER_PROF because it won't count
        echo "$i<br/>\n";
        $i++;
        ob_flush();
        flush();
}


Expected result:
----------------
$ (cd ~/src/long/; /tmp/php7.4/bin/php -S 0.0.0.0:8080; date)
[Wed Feb 10 13:19:30 2021] PHP 7.4.15RC1 Development Server (http://0.0.0.0:8080) started
[Wed Feb 10 13:19:30 2021] 127.0.0.1:45308 Accepted
 ** Setting prof timer for 30.0 seconds ** 
 ** UnSetting prof timer ** 
 ** Setting prof timer for 10.0 seconds ** 
 ** Setting prof timer for 2.0 seconds ** 
[Wed Feb 10 13:19:41 2021] 127.0.0.1:45308 [200]: GET / - Maximum execution time of 10 seconds exceeded in /home/calvin/src/long/index.php on line 11
 ** UnSetting prof timer ** 
 ** UnSetting prof timer ** 
 ** Setting prof timer for 30.0 seconds ** 
[Wed Feb 10 13:19:41 2021] 127.0.0.1:45308 Closing

Actual result:
--------------
$ (cd ~/src/long/; /tmp/php7.4/bin/php -S 0.0.0.0:8080; date)
[Wed Feb 10 13:13:34 2021] PHP 7.4.15RC1 Development Server (http://0.0.0.0:8080) started
[Wed Feb 10 13:13:38 2021] 127.0.0.1:45126 Accepted
 ** Setting real timer for 30.0 seconds ** 
 ** UnSetting real timer ** 
 ** Setting real timer for 10.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Wed Feb 10 13:13:48 2021] 127.0.0.1:45126 [200]: GET / - Maximum execution time of 10 seconds exceeded in /home/calvin/src/long/index.php on line 8
 ** UnSetting real timer ** 
 ** UnSetting real timer ** 
 ** Setting real timer for 30.0 seconds ** 
[Wed Feb 10 13:13:48 2021] 127.0.0.1:45126 Closing
[Wed Feb 10 13:13:48 2021] 127.0.0.1:45128 Accepted
[Wed Feb 10 13:13:48 2021] 127.0.0.1:45128 Closed without sending a request; it was probably just an unused speculative preconnection
[Wed Feb 10 13:13:48 2021] 127.0.0.1:45128 Closing
 ** Setting real timer for 2.0 seconds ** Fatal error: Maximum execution time of 30+2 seconds exceeded (terminated) in Unknown on line 0
Wed 10 Feb 2021 01:14:20 PM AST

Patches

force-problematic-timer.diff (last revision 2021-02-10 17:34 UTC by calvin at cmpct dot info)

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2021-02-11 15:44 UTC] calvin at cmpct dot info
FWIW, this also affects CGI. I also only believe this happens if set_time_limit is used; if it isn't, the timer seems to be unset without being set again.

For example, index.php and index2.php are identical, except for the set_time_limit in index.php:

 ** Setting real timer for 30.0 seconds ** 
 ** UnSetting real timer ** 
 ** Setting real timer for 180.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Thu Feb 11 10:32:42 2021] ip.address:57946 [200]: GET / - Maximum execution time of 180 seconds exceeded in /home/calvin/tmp/long/index.php on line 8
 ** UnSetting real timer ** 
 ** UnSetting real timer ** 
 ** Setting real timer for 30.0 seconds ** 
[Thu Feb 11 10:32:42 2021] ip.address:57946 Closing
[Thu Feb 11 10:32:46 2021] ip.address:58018 Accepted
 ** Setting real timer for 30.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Thu Feb 11 10:33:17 2021] ip.address:58018 [200]: GET /index2.php - Maximum execution time of 30 seconds exceeded in /home/calvin/tmp/long/index2.php on line 8
 ** UnSetting real timer ** 
[Thu Feb 11 10:33:17 2021] ip.address:58018 Closing
[Thu Feb 11 10:35:09 2021] ip.address:58092 Accepted
 ** Setting real timer for 30.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Thu Feb 11 10:35:39 2021] ip.address:58092 [200]: GET /index2.php - Maximum execution time of 30 seconds exceeded in /home/calvin/tmp/long/index2.php on line 8
 ** UnSetting real timer ** 
[Thu Feb 11 10:35:39 2021] ip.address:58092 Closing
[Thu Feb 11 10:36:50 2021] ip.address:58134 Accepted
 ** Setting real timer for 30.0 seconds ** 
 ** UnSetting real timer ** 
 ** Setting real timer for 180.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Thu Feb 11 10:39:50 2021] ip.address:58134 [200]: GET / - Maximum execution time of 180 seconds exceeded in /home/calvin/tmp/long/index.php on line 8
 ** UnSetting real timer ** 
 ** UnSetting real timer ** 
 ** Setting real timer for 30.0 seconds ** 
[Thu Feb 11 10:39:50 2021] ip.address:58134 Closing
[Thu Feb 11 10:40:01 2021] ip.address:58218 Accepted
 ** Setting real timer for 30.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Thu Feb 11 10:40:32 2021] ip.address:58218 [200]: GET /index2.php - Maximum execution time of 30 seconds exceeded in /home/calvin/tmp/long/index2.php on line 8
 ** UnSetting real timer ** 
[Thu Feb 11 10:40:32 2021] ip.address:58218 Closing
 [2021-02-11 21:52 UTC] calvin at cmpct dot info
I think the problem is for the max_execution_time handler (OnUpdateTimeout) - that seems to reset it even when there's no script running if it was changed.

Diff:

```
diff --git a/main/main.c b/main/main.c
index 1cb50ce1dd..eedce27f8f 100644
--- a/main/main.c
+++ b/main/main.c
@@ -467,6 +467,7 @@ static PHP_INI_MH(OnUpdateTimeout)
        }
        zend_unset_timeout();
        ZEND_ATOL(EG(timeout_seconds), ZSTR_VAL(new_value));
+fprintf(stderr, " ** Updating timeout to %d ** \n", EG(timeout_seconds));
        zend_set_timeout(EG(timeout_seconds), 0);
        return SUCCESS;
 }

```

Output:

```
 ** Setting real timer for 30.0 seconds ** 
 ** UnSetting real timer ** 
 ** Updating timeout to 45 ** 
 ** Setting real timer for 45.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Thu Feb 11 16:23:02 2021] ip.address:40006 [200]: GET / - Maximum execution time of 45 seconds exceeded in /home/calvin/tmp/long/index.php on line 8
 ** UnSetting real timer ** 
 ** UnSetting real timer ** 
 ** Updating timeout to 30 ** 
 ** Setting real timer for 30.0 seconds ** 
[Thu Feb 11 16:23:02 2021] ip.address:40006 Closing
[Thu Feb 11 16:23:04 2021] ip.address:40022 Accepted
 ** Setting real timer for 30.0 seconds ** 
 ** Setting real timer for 2.0 seconds ** 
[Thu Feb 11 16:23:34 2021] ip.address:40022 [200]: GET /index2.php - Maximum execution time of 30 seconds exceeded in /home/calvin/tmp/long/index2.php on line 8
 ** UnSetting real timer ** 
[Thu Feb 11 16:23:34 2021] ip.address:40022 Closing
```
 [2021-02-12 18:34 UTC] calvin at cmpct dot info
GH-6683 is my suggested patch for this issue. LMK if it's not ideal/a better way is possible.
 
PHP Copyright © 2001-2021 The PHP Group
All rights reserved.
Last updated: Mon Apr 19 12:01:23 2021 UTC