Add custom variables to Apache access log from PHP-FPM

Question

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

Answer 1

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).