0

In mod_php you can use the apache_note() function to log variables in the Apache Access Log:

<?php
apache_note('SCRIPT_TIME', '1234');
?>

With the Apache config:

LogFormat "%h %l %u %t [%D/%{SCRIPT_TIME}n] \"%r\" %>s %b" inc_info
...
CustomLog /path/to/access_log inc_info

But the apache_note() function is not available in PHP-FPM.

Likewise, you can't use apache_setenv() or setenv() to set environment variables (to be logged via %{SCRIPT_TIME}e).

One possibility is to set a header that Apache can log with "%{SCRIPT_TIME}i", but you need to be careful to not let sensitive information be sent to the client (e.g. knowing accurate processing time for a login script can be a security issue). But more importantly, it does not work if content has already been sent to the client, as you can no longer send headers (as per the full example below).

Or, PHP could write it's own log file, but this would be duplicating a lot of what the Apache log already does, has the potential to miss log entries (e.g. if the script has an error), and will be created under the Apache user permissions (rather than being written to as root).


Just for more detail, this is the code I use to log the script processing time:

<?php

define('SCRIPT_START', microtime(true));

function log_shutdown() {
    if (!defined('SCRIPT_END')) {
        define('SCRIPT_END', number_format(round((microtime(true) - SCRIPT_START), 4), 4));
    }
    if (function_exists('apache_note')) {
        apache_note('SCRIPT_TIME', SCRIPT_END);
    }
}

register_shutdown_function('log_shutdown');

?>

And from a timing point of view, while Apache does provide "%D", to log "the time taken to serve the request", this is heavily dependent on the users internet connection.


This relates to me trying to enable HTTP/2 on my server, with the config:

Protocols h2 http/1.1

<FilesMatch \.php$>
    CGIPassAuth on
    SetEnvIf Authorization "(.*)" HTTP_AUTHORIZATION=$1
    SetHandler "proxy:fcgi://127.0.0.1:9001"
</FilesMatch>

Also related is the Nginx version

2
  • nginx can log the upstream processing time, but apache cannot. As a general rule, though, your application should be doing its own logging. Apr 8, 2019 at 13:16
  • @MichaelHampton, thanks for pointing me towards the $upstream_response_time variable in nginx, that might work for my specific case (even though it will then include the time it takes to start processing the PHP script, and the delay between PHP-FPM and nginx)... and I while I do have a separate logs for my application, they don't cover every request being made to the web server, as that's already done though the Apache Access Logs, so it wouldn't be useful duplicating it. Apr 8, 2019 at 15:28

1 Answer 1

0

If you're only recording the processing time and using nginx, the suggestion from @MichaelHampton could work, by logging the $upstream_response_time variable.

But I want to keep using Apache, and store extra details (user-id, time processing certain tasks, etc)...

My solution is to create a separate log file, that PHP can write to at any time (even after the headers have been sent), where I'll create a unique(ish) reference code for each request (so the two logs can be joined).

First, get your PHP script to generate a reference code, and send that as a header:

<?php 

// A more compact uniqid - which uses hex encoding, and a full UNIX timestamp

$start = microtime(true);
$sec = floor($start);
$usec = round(($start - $sec) * 1000000); // Only accurate to 6 decimal places.

$sec -= strtotime('-' . date('w', $sec) . ' days, 00:00:00', $sec); // Time since Sunday 00:00, max value = 604800 (60*60*24*7)

$code = '';
foreach([$sec, $usec, rand(100000, 999999)] as $code_part) {
    $a = dechex($code_part); // decbin returns a string
    $a = hex2bin(((strlen($a) % 2) == 0 ? '' : '0') . $a);
    $a = base64_encode_rfc4648($a);
    $code .= str_pad($a, 4, '.', STR_PAD_LEFT); // 4 characters max = 999999 -> "0f423f" (hex) -> "D0I/" (base64)
}

define('REQUEST_START', $start);
define('REQUEST_CODE', $code);

header('X-Request-Code: ' . $code); // For Apache

?>

Apache can log that reference code (more info):

Header always note "X-Request-Code" "Request-Code"
Header always unset "X-Request-Code"

LogFormat "%h %l %u [%{%Y-%m-%d %H:%M:%S}t] [%{Request-Code}n] \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" inc_ref

CustomLog /path/to/access_log inc_ref

Then you could add a register_shutdown_function() that does something like:

<?php 

$log_values = [
        date('Y-m-d H:i:s'),
        REQUEST_CODE,
        $user_id,
        $_SERVER['REMOTE_ADDR'],
        $_SERVER['REQUEST_METHOD'],
        $_SERVER['REQUEST_URI'],
        http_response_code(),
        round((microtime(true) - REQUEST_START), 4),
    ];

if (($fp = fopen($log_file, 'a')) !== false) {
    fputcsv($fp, $log_values);
    fclose($fp);
}

?>

I'm repeating information that's also in the access log for laziness reasons (e.g. to grep a single log file).

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.