本記事でやりたいこと

会社で障害対応や顧客からの問い合わせを受けた際に、apacheのアクセスログを調査する機会があります。
その中で、「〇〇したはずが反映されていない」などの問い合わせの際にアクセスログに出力された時間と関連処理でDBに登録されたレコードを比較することがあります。

ミリ秒単位の差で結果が変わってくる場合は出力されている時間はレスポンスを受けたときなのか、完了したときなのかでさえも調査結果が変わる為、頭の中を整理する為の記事です。

最初に結論

・出力される【時間】はアクセスされた時間
・出力される【順番】はリクエストが終わりレスポンスを返したとき

検証

このようなファイルを作成します。

nontest.php

<?php
// アクセス時刻をログに記録する（デバッグや確認用）
error_log("Accessed: " . date("Y-m-d H:i:s"));

// 30秒間待機
sleep(30);

// レスポンスを表示（適宜変更可能）
echo "30秒が経過しました。";
?>

出力結果は以下のようになりました。

テスト用に作成したファイルにアクセス→その後にphpinfoを二回開く、ということをやりました。

[Sat Jan 25 15:18:03.782944 2025] Accessed: 2025-01-25 07:18:03

::1 - - [25/Jan/2025:15:18:06 +0900] "GET /dashboard/phpinfo.php
::1 - - [25/Jan/2025:15:18:20 +0900] "GET /dashboard/phpinfo.php
::1 - - [25/Jan/2025:15:18:03 +0900] "GET /dashboard/nontest.php

結論の通りになりました。

##途中でバッファを吐いたらどうなるか
以下のように途中でバッファを吐いてみる

<?php
// アクセス時刻をログに記録する（デバッグや確認用）
error_log("Accessed: " . date("Y-m-d H:i:s"));

// 30秒間待機
sleep(5);

// レスポンスを表示（適宜変更可能）
echo "5秒経過";
ob_flush();
flush();

sleep(30);

echo "5+30秒が経過しました。";
?>

[Mon Feb 17 15:15:39.776441 2025] Accessed: 2025-02-17 07:15:39

::1 - - [17/Feb/2025:15:15:41 +0900] "GET /dashboard/phpinfo.php
::1 - - [17/Feb/2025:15:15:43 +0900] "GET /dashboard/phpinfo.php
::1 - - [17/Feb/2025:15:15:39 +0900] "GET /dashboard/nontest.php

結論は変わらない、画面にはバッファが吐かれたときに反映するが、アクセスログの出力順には影響しｎ