問題

ウェブアプリケーションで処理に時間がかかることがあり、その調査を行っている。
その時、アクセスログをもとに原因を特定しているのだが、利用しているミドルウェアによってアクセスログに記録されている時刻が異なっていて混乱したので、その内容を示す。

利用しているアーキテクチャ

今回のアーキテクチャは CloudFront -> nginx -> Apache の構成になっていて、それぞれでアクセスログを出力している。

違いをまとめると以下の通り。 Apache は「受信時刻」だが、CloudFront/Nginx は「レスポンス完了時刻」を示すことが大きく違う。

項目	CloudFront	Nginx	Apache
時刻フィールド	`date` + `time`	`$time_local`	`%t`
ログの時刻の意味	レスポンス完了時刻	レスポンス完了時刻	リクエスト受信時刻
ログ出力のタイミング	レスポンス完了後	レスポンス完了後	レスポンス完了後
公式ドキュメント	CloudFront 標準ログ仕様	Nginx $time_local	Apache ログファイル

そのため、例えば

といった条件でログを記録した場合、ログの時刻記録は以下のようになる。

この仕様を知らないと、ログ時刻を誤って読み取って異なる結論を導き出してしまうので注意すること。