Apacheのアクセスログの見方
目次
概要
RHEL 5.9のインストールメディアに同梱されている Apache HTTP サーバのアクセスログ（/var/log/httpd/access_log）の 見方をまとめます。
Apacheではサーバが受信したHTTPリクエストを1件につき1行のログとして アクセスログに記録します。見方はあまり難しくないのですが、 どの部分が何を表しているのか分かりづらいので整理します。
なお、初期状態ではアクセスログが出力される設定になっていますが、 設定ファイル（httpd.conf）を変更することで、 出力先のファイルを指定することや、出力させないこともできます。
構成
想定環境
Apacheの設定ファイルパス
/etc/httpd/conf/httpd.conf
アクセスログのフルパス
/var/log/httpd/access_log
サーバ構成
OSバージョン
Red Hat Enterprise Linux 5.9 x86_64
ソフトウェア・パッケージ一覧
httpd-2.2.3-74.el5
Apacheのアクセスログの設定確認
設定ファイル
Apacheの設定ファイル（/etc/httpd/conf/httpd.conf）の アクセスログに関連する設定を以下に抜き出します。
下記設定はあくまでRHEL 5.9の初期設定の場合です。 ディストリビューションが異なる場合や、ソースコードからコンパイルして Apacheをインストールした場合などは異なる設定となっていますので 適宜読み替えてください。
※以下、関連する行のみ抜粋※
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
LogFormat "%h %l %u %t \"%r\" %>s %b" common
LogFormat "%{Referer}i -> %U" referer
LogFormat "%{User-agent}i" agent
CustomLog logs/access_log combined
ログフォーマットが4種類 LogFormat ディレクティブで定義されていて、 アクセスログはそのうち combined というフォーマットを選択しています。 ログのパスは ServerRoot ディレクティブで定義されたパス （RHEL5.9のApacheでは初期状態で /etc/httpd が設定されている） からの相対パスで指定されています。 つまりアクセスログのパスは /etc/httpd/logs/access_log となります。
ただし、/etc/httpd/logs/ ディレクトリは /var/log/httpd/ ディレクトリへの シンボリックリンクとなっています。したがってアクセスログの実体パスは /var/log/httpd/access_log となります。
ログフォーマットの見方
アクセスログに設定されている combined フォーマットのログ形式は 以下のように設定されています。
%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"
項目を一つずつ見ていきます。
| %h | リモートホスト。つまりApacheにアクセスしてきたクライアントPCのIPアドレスとなります。 |
|---|---|
| %l | リモートログ名。mod_identモジュールがロードされており、IdentityCheckディレクティブがOnになっている場合のみ表示されます。それ以外の場合は『-』と表示されます。 |
| %u | リモートユーザ。 |
| %t | リクエストを受信した時刻。 |
| %r | リクエストの最初の行。 |
| %>s | %sはステータスコード。内部でリダイレクトされた場合でも元々のステータスコードを出力。%>sはリダイレクトされた場合最後のステータスコードを出力。 |
| %b | HTTPヘッダを除くレスポンスのバイト数。0バイトの場合は『-』と表示されます。 |
| %{Referer}i | サーバが受信したリクエストヘッダのReferer。 |
| %{User-Agent}i | サーバが受信したリクエストヘッダのUser-Agent。 |
アクセスログの見方
ブラウザを利用してApacheにアクセスした際に出力されたログを1件例として表示します。
1件のログが長いため表示の都合上2行に分けて表示していますが、 実際には1行のログです。
192.168.0.101 - - [12/May/2014:20:41:48 +0900] "GET /index.html HTTP/1.1" 200 114 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0"
上記ログの各項目を以下に説明します。
| %h | 192.168.0.101 ⇒ApacheにアクセスしてきたPCのIPアドレス。 |
|---|---|
| %l | - |
| %u | - |
| %t | [12/May/2014:20:41:48 +0900] ⇒HTTPリクエストを受信した時刻。 |
| %r | GET /index.html HTTP/1.1 ⇒クライアントはHTTPプロトコルバージョン1.1を利用して http://ドメイン名/index.html にGETメソッドでアクセスしてきたことを表します。 |
| %>s | 200 ⇒HTTPステータスコード。200はレスポンスを返すことに成功したことを表します。 |
| %b | 114 ⇒HTTPレスポンスのサイズ（バイト数）。ただしHTTPヘッダは除きます。 |
| %{Referer}i | - ⇒当ページへアクセスするに当たり、リンクをたどってきたのではなく、直接アクセスしてきたことを表します。 |
| %{User-Agent}i | Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0 ⇒クライアントのOSはWindows NT 6.1（プロダクト名はWindows 7）で、ブラウザにFirefox 29.0を利用してアクセスしてきたことが分かります。 |
アクセスログの出力タイミング
アクセスログに書かれている時刻はApacheがHTTPリクエストを受信した時刻ですが、 ログメッセージがログファイルに書かれるのはApacheがレスポンスを返すときです。
アクセスログの表示項目を見ていれば分かりますが、HTTPレスポンスのサイズや、 今回は紹介していませんが、レスポンスを返すまでのサーバでの処理時間をログに 記載することができます。これら情報はApacheがリクエストを受け取った時点では まだ分からないので、レスポンスを返す時点で必要な情報が揃ってからまとめて ログファイルに書き出します。
そのため、先にサーバでの処理時間が長いリクエストを受け取って、その後 処理時間が短いリクエストを受け取った場合、ログファイルを表示すると 時刻が逆転しているように見えます。 記録された時刻が間違っているわけではないのでご注意ください。
(アクセス2)192.168.0.101 - - [12/May/2014:21:14:56 +0900] "GET /index.html HTTP/1.1" 304 - "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0" (アクセス3)192.168.0.101 - - [12/May/2014:21:14:59 +0900] "GET /test.html HTTP/1.1" 304 - "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0" (アクセス1)192.168.0.101 - - [12/May/2014:21:14:51 +0900] "GET /sleep.php HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0"
アクセスした順はログに記載されている時刻の通りアクセス1→2→3の順ですが、 ログファイルにログメッセージが書かれるのはレスポンスを返した順なので、 アクセス2→3→1の順となっています。