apacheのログに出る時刻はバージョン1.3.xと2.xとで違う

知っている人は知っているけど知らない人は知らない、ささいなTIPSではありますが。

たとえばApacheのアクセスログに
192.168.10.20 - - [31/Aug/2006:22:24:26 +0900] "GET /hoge.html HTTP/1.1" 200 1215
というログがあったとして、このログに記載されている時刻は「ブラウザからのリクエストをApacheが受け取った時刻」なのか？それとも「Apacheがブラウザにレスポンスを返した時刻」なのか？

正解は次のとおり。

Apache1.3系統の場合：「全ての処理を終えてログを出力する時点の時刻≒Apacheがブラウザにレスポンスを返した時刻」
Apache2以降の場合：「ブラウザからのリクエストをApacheが受け取った時刻」

注：ログまわりの設定や実装になんか小細工している場合は除く

これはApacheのリリースノートなど見ていても不思議と書いていない。しかしマニュアルを見比べるとなんとなくわかる。

1.3のマニュアル	[10/Oct/2000:13:55:36 -0700] (%t) The time that the server finished processing the request （訳：サーバーがリクエストの処理を終了した時刻）
2.0のマニュアル	%...t Time the request was received (standard english format) （訳：リクエストを受けた時刻）

apacheのバージョンに関わらず、ログがファイルに書き込まれるタイミングは常に「そのリクエストに対するレスポンス処理を全て終了した時点」である。なぜなら、全てのレスポンス処理を終えなければわからない情報をログに出力する場合もあるから。ここで問題なのはログに記録されている時刻だ。静的なファイルの内容を返すだけならともかくWebアプリの場合には何か問題が発生したときその時刻が重要になるのだが、重い処理をするWebアプリだとリクエストを受けた時刻とレスポンスを返した時刻にはズレが発生してしまい、ログに記録されているのはそのどちらなのかを正確に把握しておかないと問題の原因や所在を見誤ってしまうことがあるので注意が必要である。

昔のapache-usersメーリングリストの投稿でもっと詳しい人が解説を残してくれている。

Apache 1.3.xのmod_log_configモジュールでは「ログを出力する時点の時刻」を出力していますが、Apache 2.0.xのmod_log_configモジュールは「リクエストを受け取った時点の時刻」を出力しています。このためApache 2.0.xの場合は大きなファイルのダウンロードや処理時間が長いプログラムを実行した場合など、リクエスト～レスポンス完了までの時間が長い場合にログの前後関係が崩れやすくなっています。

この変更の理由はトランザクションの処理中に何度もシステムコールを発行するオーバーヘッドを嫌うためなのか、「ログを出力した時刻」よりも「リクエストされた時刻」の方がアクセスログとして価値があるからかは知りません。
（http://mm.apache.jp/pipermail/apache-users/2004-April/004080.html より抜粋）

ついでなので小山氏執筆の書籍など。