【Apache】アクセスログの順番がおかしい？

Tweet

Category apache 2012/09/12

問題

Apacheのアクセスログを見ていたら、順番がおかしいのを見つけました。

なんでこんな風になるの？

1.1.1.1 - - [22/Jul/2012:18:02:17 +0900] "GET /hoge/ HTTP/1.1"
1.1.1.1 - - [22/Jul/2012:18:02:18 +0900] "GET /hoge/ HTTP/1.1"
1.1.1.1 - - [22/Jul/2012:18:02:12 +0900] "GET /hoge/ HTTP/1.1" ★ここ時間が変
1.1.1.1 - - [22/Jul/2012:18:02:19 +0900] "GET /hoge/ HTTP/1.1"

答え

アクセスログの時間はアクセスのあった時間、アクセスログに書き込まれるのはレスポンスが終わってから。なので、レスポンスに時間がかかると、ログに書き込まれる時間は前後する。

単純にWebサーバー側の処理で時間がかかっている場合もある。

SYN floodアタックっぽい状況で、クライアントがパケットを受け取ったと応答してくれなくて、長引いている場合もある。

似た状況で、ネットワークに問題があって、レスポンスがなかなか完了しない場合も考えられる。

検索エンジンのクローラーのログなどでもよく見かける。

大量のリクエストを発行しているので、レスポンスを受け取ったという応答が遅いのかもしれない。