PHP script executes twice when longer than 60 seconds

Question

Alright, so I've been wracking my brain about this for the past 3 hours now and been googling like crazy with no resolution to the problem. So, I wrote an example script that reproduces this since my original script is around 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 just being used to re-create the time of execution of the page and is not used in the original 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)

heres 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 have tried everything i can think of. it appears to be a server setting either with Apache or PHP, because when i run this same script on my localhost, it executes successfully like it should without the double load. and before its asked, yes every time I make an INI change or apache config change I have been restarting apache.

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

*.*.*.* - - [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 *.*.*.*

There is definitely something doing this once 60 seconds has been reached in execution time because when i change the execution time to say, 55 seconds, it runs once just 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 will be much appreciated!

Answer 1

Could something such as a missing favicon be causing your script to get called twice. See http://www.webdeveloper.com/forum/showthread.php?245809-Script-Running-Twice. It can also.happen if you have the non www redirected to www or vice versa. See PHP executes twice on page load when redirecting from non-www to www

Answer 2

Just to rule it out, have you tried testing this in another browser? I only mention it because i stumbled on this recently:

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