apacheのアクセスログ
こんばんは、牧野です。
今回はアルゴリズムの話は置いておき、apacheの話題です。
先日、あるサイトのapacheのアクセスログを調べていて気付いたのですが、
リクエストがタイムアウトしてしまい、クライアントがデータを受信できなかった時でも
アクセスログにはリクエストのあった時間のログが残ってしまうんですね。。
ス テータスコード200で。。。
これは、携帯でアクセスできるウェブサーバがあれば簡単に確認することができます。
（携帯の方がタイムアウトするまでの時間が短いので）
次のようなプログラムをサーバに置いて、
<?php
sleep(70);
echo 'Hello!';
?>
あとはアクセスログを見ながらこのプログラムに携帯からアクセスするだけです。
すると、、、
通信開始
↓
70秒経過前 に端末側ではタイムアウトメッセージ
↓
70秒後に、ステータスコードが200で、リクエストが合った時刻のログが書き込まれる
実際にどんなデータがやりとりされているかを見るには、Linuxなら
tcpdump
コマンドが使えます。
/usr/sbin/tcpdump -n 'port 80'
という感じで実行すると80番ポート流れるパケットの概要を見ることができます。
今回はポートだけを指定していますが、もっといろんなマッチング条件を指定することも可能です。
これを実行して改めてアクセスしてみると、
19:25:25.289060 210.136.161.151.44924 > 192.168.1.207.http: S 1392407767:1392407767(0) win 32768 <mss 1460,wscale 0,nop> (DF)
19:25:25.289093 192.168.1.207.http > 210.136.161.151.44924: S 573743362:573743362(0) ack 1392407768 win 5840 <mss 1460,nop,wscale 0> (DF)
19:25:25.292958 210.136.161.151.44924 > 192.168.1.207.http: P 1:123(122) ack 1 win 32768 (DF)
19:25:25.293023 192.168.1.207.http > 210.136.161.151.44924: . ack 123 win 5840 (DF)
19:26:17.095988 210.136.161.151.44924 > 192.168.1.207.http: F 123:123(0) ack 1 win 32768 (DF)
19:26:17.129320 192.168.1.207.http > 210.136.161.151.44924: . ack 124 win 5840 (DF)
19:26:35.290859 192.168.1.207.http > 210.136.161.151.44924: P 1:265(264) ack 124 win 5840 (DF)
19:26:35.290974 192.168.1.207.http > 210.136.161.151.44924: F 265:265(0) ack 124 win 5840 (DF)
19:26:35.294709 210.136.161.151.44924 > 192.168.1.207.http: R 1392407891:1392407909(18) win 0 (DF)
19:26:35.294711 210.136.161.151.44924 > 192.168.1.207.http: R 1392407891:1392407909(18) win 0 (DF)
最初ウェブサーバにパケットが飛んで、
ウェブサーバが返信
クライアント（docomoゲートウェイサーバ）がヘッダー情報送信
ウェブサーバ受け取り
ここでプログラムはsleep()。
クライアント（docomoゲートウェイサーバ）がタイムアウトして、コネクション切断リクエスト
ウェブサーバが返信
でも、ウェブサーバはデータ送信して、
続けてコネクション切断リクエスト送信
docomoゲートウェイサーバが返信
docomoゲートウェイサーバが2回接続終了リクエスト
となって いるようです。（違ってたら教えていただけると助かります。）
やはり、apacheはコネクション切断リクエストを受け取った後でもかまわずレスポンスを返して、ステータスコード200が記録されているってことかな。
ちなみに、tcpdump実行時に -X オプションを追加すると、パケットデータが文字列で表示されるのですが、ネットワークを流れるデータを簡単に覗けることが実感できます。。
話をアクセスログに戻しますが、apacheの設定でログのフォーマットを変えることで、タイムアウトしたアクセスを判別できるようにすることが可能です。
例えば、httpd.confを
LogFormat "%h %l %u %t \"%r\" %>s %b" common
→LogFormat "%h %l %u %t \"%r\" %>s %b %D %X" common
…
CustomLog logs/access_log combined
のように、LogFormatに%Dや%Xを加えておくと、タイムアウトのアクセス判別の参考に使えそうです。
（参考ページ）
http://httpd.apache.org/docs/2.2/ja/mod/mod_log_config.html
%Dはリクエストの処理にかかった時間(マイクロ秒)、%Xは応答が完了したときの接続ステータスを表します。
他にもいろんな出力が可能なので、必要に応じてカスタマイズしてはいかがでしょうか。
