What aren't the values of this PHP generated statements written to the log?

Question

I have this code that runs with every page load:

$output = "<"."?php  if ( ! defined('BASEPATH')) exit('No direct script access allowed'); ?".">\n\n";
$output .= print_r($events, 1);
$output .= "\nTotal Doctrine time: " . $time  . "\n";
$output .= "Peak Memory: " . memory_get_peak_usage() . "";

file_put_contents(BASEPATH."/logs/doctrine_profiler.php", $output);

But when I view the log file, I see this:

Array
(
)

Total Doctrine Time: 0
Peak Memory: 4006524

But if I echo $output I get the expected:

Array
(
    [0] => Array
        (
            [type] => execute
            [query] => SELECT t.id AS t__id, t.name AS t__name, t.annual_fee AS t__annual_fee, t.monthly_fee AS t__monthly_fee, t.additional_store_fee AS t__additional_store_fee FROM tier t WHERE (t.id = ?) LIMIT 1
            [time] => 0.000474
            [params] => Array
                (
                    [0] => 3
                )

        )

)

Total Doctrine time: 0.005281925201416
Peak Memory: 6135048

I don't think it matters, but I'm using Doctrine with CodeIgniter.

EDIT: I have gotten this to work using MAMP, with out changing the code, so could it possibly be a php.ini thing?

EDIT2: After digging into this a little further, it appears that for some reason, on my Media Temple server, everything is getting run twice. On -each- pageload, I get the entire log (ci log) written twice. So, the doctrine log is getting over written when no query executes. I'm still not sure why this happens on MediaTemple and not Locally, so I'll dive a little deeper.

EDIT3: This can be closed, as it's no longer a PHP issue. Disabling JavaScript resolved the issue, so I'm looking in the wrong place. Thank you everyone for your great help!

Answer 1

Let's find out whether for some reason your code get's called twice within the same request/process or if two (not-so-) separate requests are handled.

$output = "<"."?php  if ( ! defined('BASEPATH')) exit('No direct script access allowed'); ?".">\n\n";
$output .= print_r($events, 1);
$output .= "\nTotal Doctrine time: " . $time  . "\n";
$output .= "Peak Memory: " . memory_get_peak_usage() . "\n";
function dbgFoo() {
  static $a = 0;
  return ++$a;
}
$output .= 'debug counter: ' . dbgFoo() . "\n";
// edit: forgot the $return parameter for print_r
$output .= 'POST=' . print_r($_POST, 1);
$output .= 'GET=' . print_r($_GET, 1);
$output .= 'callstack: ' . print_r(debug_backtrace(), 1) . "\n\n\n";

file_put_contents(BASEPATH."/logs/doctrine_profiler.php", $output, FILE_APPEND);

If your code is called twice within the same php instance/request the debug counter output should be >1. And maybe the call stack can help you find the point where the application chooses to call your code ...again.
Otherwise the output of _POST and _GET might indicate why there are two http requests. Maybe you have an add-on in your browser that causes a second request? There was e.g. an issue with ajax requests and older firebug versions.