PHP script is executed twice when more than 60 seconds

Question

Okay, so I cheated on my brain about this for the last 3 hours and looked like crazy without solving the problem. So, I wrote an example script that reproduces this, since my original script is about 800 lines.

<?php set_time_limit(0); ini_set('max_input_time', '-1'); ini_set('max_execution_time', '0'); error_log("executing script... "); $time = time(); for ($t = 0; $t <= 15; $t++) { error_log("Logging: $t (".(time()-$time)." seconds)"); sleep(5); } error_log("execution done (".(time()-$time)." seconds)"); ?> 

Now the sleep function is used only to recreate page runtime and is not used in the source code. This will produce the following result in the error_log file

 [Tue Nov 06 16:24:14 2012] executing script... [Tue Nov 06 16:24:14 2012] Logging: 0 (0 seconds) [Tue Nov 06 16:24:19 2012] Logging: 1 (5 seconds) [Tue Nov 06 16:24:24 2012] Logging: 2 (10 seconds) [Tue Nov 06 16:24:29 2012] Logging: 3 (15 seconds) [Tue Nov 06 16:24:34 2012] Logging: 4 (20 seconds) [Tue Nov 06 16:24:39 2012] Logging: 5 (25 seconds) [Tue Nov 06 16:24:44 2012] Logging: 6 (30 seconds) [Tue Nov 06 16:24:49 2012] Logging: 7 (35 seconds) [Tue Nov 06 16:24:54 2012] Logging: 8 (40 seconds) [Tue Nov 06 16:24:59 2012] Logging: 9 (45 seconds) [Tue Nov 06 16:25:04 2012] Logging: 10 (50 seconds) [Tue Nov 06 16:25:09 2012] Logging: 11 (55 seconds) [Tue Nov 06 16:25:14 2012] executing script... [Tue Nov 06 16:25:14 2012] Logging: 0 (0 seconds) [Tue Nov 06 16:25:14 2012] Logging: 12 (60 seconds) [Tue Nov 06 16:25:19 2012] Logging: 1 (5 seconds) [Tue Nov 06 16:25:19 2012] Logging: 13 (65 seconds) [Tue Nov 06 16:25:24 2012] Logging: 2 (10 seconds) [Tue Nov 06 16:25:24 2012] Logging: 14 (70 seconds) [Tue Nov 06 16:25:29 2012] Logging: 3 (15 seconds) [Tue Nov 06 16:25:29 2012] Logging: 15 (75 seconds) [Tue Nov 06 16:25:34 2012] Logging: 4 (20 seconds) [Tue Nov 06 16:25:34 2012] execution done (80 seconds) [Tue Nov 06 16:25:39 2012] Logging: 5 (25 seconds) [Tue Nov 06 16:25:44 2012] Logging: 6 (30 seconds) [Tue Nov 06 16:25:49 2012] Logging: 7 (35 seconds) [Tue Nov 06 16:25:54 2012] Logging: 8 (40 seconds) [Tue Nov 06 16:25:59 2012] Logging: 9 (45 seconds) [Tue Nov 06 16:26:04 2012] Logging: 10 (50 seconds) [Tue Nov 06 16:26:09 2012] Logging: 11 (55 seconds) [Tue Nov 06 16:26:14 2012] Logging: 12 (60 seconds) [Tue Nov 06 16:26:19 2012] Logging: 13 (65 seconds) [Tue Nov 06 16:26:24 2012] Logging: 14 (70 seconds) [Tue Nov 06 16:26:29 2012] Logging: 15 (75 seconds) [Tue Nov 06 16:26:34 2012] execution done (80 seconds) 

there are some settings from phpinfo that are relevant

 === apache2handler === Max Requests: Per Child: 1000 - Keep Alive: on - Max Per Connection: 200 Timeouts: Connection: 300 - Keep-Alive: 2 === PHP Version 5.4.5 Core Settings === max_execution_time Local: 0 Master: 30 max_input_time Local: -1 Master: -1 

I tried everything I could think of. it seems to be setting up a server with Apache or PHP, because when I run the same script on my local host, it works successfully, like it, without double load. and before asking it, yes, every time I make an INI change or apache configuration change, I restart apache.

also, here are the access_log entries for the above example.

 *.*.*.* - - [06/Nov/2012:16:43:56 -0700] "GET /test.php HTTP/1.1" 200 20 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:16.0) Gecko/20100101 Firefox/16.0" *.*.*.* *********.com 80 55050278 1012 321 *.*.*.* *.*.*.* - - [06/Nov/2012:16:44:56 -0700] "GET /test.php HTTP/1.1" 200 20 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:16.0) Gecko/20100101 Firefox/16.0" *.*.*.* *********.com 80 60054985 1012 321 *.*.*.* 

Definitely, something does this when 60 seconds is reached at runtime, because when I change the runtime, say 55 seconds, it works as soon as it should.

 [Tue Nov 06 16:46:00 2012] executing script... [Tue Nov 06 16:46:00 2012] Logging: 0 (0 seconds) [Tue Nov 06 16:46:05 2012] Logging: 1 (5 seconds) [Tue Nov 06 16:46:10 2012] Logging: 2 (10 seconds) [Tue Nov 06 16:46:15 2012] Logging: 3 (15 seconds) [Tue Nov 06 16:46:20 2012] Logging: 4 (20 seconds) [Tue Nov 06 16:46:25 2012] Logging: 5 (25 seconds) [Tue Nov 06 16:46:30 2012] Logging: 6 (30 seconds) [Tue Nov 06 16:46:35 2012] Logging: 7 (35 seconds) [Tue Nov 06 16:46:40 2012] Logging: 8 (40 seconds) [Tue Nov 06 16:46:45 2012] Logging: 9 (45 seconds) [Tue Nov 06 16:46:50 2012] Logging: 10 (50 seconds) [Tue Nov 06 16:46:55 2012] execution done (55 seconds) 

Any help with this would be much appreciated!

Answer 1

Perhaps something like a missing icon will trigger a script call twice. See http://www.webdeveloper.com/forum/showthread.php?245809-Script-Running-Twice . This can also happen if you do not have a www redirected to www or vice versa. See PHP executes twice when loading a page when redirecting from non-www to www

Answer 2

Just to rule it out, have you tried checking this in another browser? I only mention this because I recently came across this:

https://support.mozilla.org/en-US/questions/922783

Answer 3

As a workaround, perhaps you can split the execution into two pages; when you are done with the first, just download the second. It may also work around certain resource limitations, such as the low RAM budget in your PHP configuration.