アクセスログ分析の簡易化①

アクセスログの分析とグラフの作成をエクセルで行ったのですが、数時間分のアクセスログはかなり重く、エクセルが落ちることもしばしばでした。

そこでbashで下処理を行い、必要な項目だけを抜き出すことで、エクセルの動作を軽くすると同時に手作業を減らすことを目指しました。

具体的には、シェル（awk）を使って必要なカラムを抜き出します。
続編では、Pythonで1分あたりの平均リクエスト数などを計算し、PowerPointへ書き出す処理を紹介しする予定です。

アクセスログとは

HTTPサーバーへどのようなアクセスがあったのかを記録したものです。例えば、アクセス元のIPアドレスや接続日時、ステータスコード¹などが保存されています。²

こういった情報を保存しておくことによって、アクセスが多い時間帯を特定したり、障害時に問題の切り分けをしたりする際に参照することができます。

この記事では特にApache³ HTTPサーバーのアクセスログを扱います。

アクセスログの書式設定

httpd.conf ファイル内の LogFormat ディレクティブに設定を記述します。

基本的な書式は以下の通りです。

Logformat (フォーマットの指定) (フォーマットの名前)

LogFormat "%h %l %u %t \"%r\" %>s %b" common

もし、↑ のような指定⁴を行った場合、

リモートホスト（%h）、リモートログ名（%l）、リモートユーザ（%u）、受付時刻（%t）、リクエストの最初の行（つまりHTTPメソッドやアクセスされたファイル）（"%r"）、ステータス（%>s）、バイト数（%b）をスペース区切りで順に出力する、commonという名前のログフォーマットを作成できます。⁵⁶

awkを用いるアクセスログの切り出し方

今回分析対象のサーバーでは、以下の形式でアクセスログを出力しています。

'10.x.x.x - - [25/Jan/2024:17:10:41 +0900] "GET /xxx.html HTTP/xxx" 200 60763 "https://xxx/xxx" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/x.x.x.x Safari/537.36 Edg/x.x.x.x" "10.x.x.x" "xxx" (-) [0] [51064] servera 17236380

このログからawkを使って分析対象の時間帯のみを指定して抜き出します。

今回分析のために必要な情報は、
・ホスト名（第1フィールド）
・リクエスト時間（第4フィールド）
・処理時間（第29フィールド）
の3つなので、それ以外のフィールドを除外します。
また、ステータスがエラーのアクセスについても分析対象から除外します。

この処理を行うために、以下のワンライナーを用います。

awk -v OFS=, '$9 == "200" && $4 ~ /2024:11:(3[2-9]|4[0-9]|5[0-7])/ {print substr($1, 2), substr($4, 14), substr($29, 2, length($29)-2)}'

各部分について簡単に解説します。

-v OFS=,
awkはデフォルトではスペース区切りですが、今回はエクセルでの扱いやすさや見やすさを考慮してカンマ区切りでの出力を行います。
ここでは -v (variables) オプションで OFS (Output Field Separator) を「,」に設定しています。

\$9 == 200
\$9＝9番目のフィールドが200の正常完了の行のみを取り出し、エラーが発生した行⁷については除外する処理を行っています。

&&
AND演算子。

\$4 ~ /2024:11:(3[2-9]|4[0-9]|5[0-7])/
正規表現を用いて時間帯の絞り込みを行っています。この例では11:32~11:57までを対象時間として切り出しています。（～分の処理が煩雑になってしまいます、間違いやすいので注意が必要です……）

{print substr(\$1, 2), substr(\$4, 14), substr(\$29, 2, length($29)-2)}
出力するフィールドを絞り込んでいます。また余分な文字列を消去するため、substrを使っています。

awkを使ったシェルワンライナーの実行

'10.x.x.x - - [11/Mar/2024:11:31:57 +0900] "GET /xxx HTTP/1.1" 200 456 "https://xxx" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/xx.xx (KHTML, like Gecko) Chrome/xx.0.0.71 Safari/xx.36 Edg/97.xx.xx.xx" "10.xx.xx.xx" "xxx" (-) [0] [7515] servera 25297334
'10.x.x.x - - [25/Jan/2024:11:32:41 +0900] "GET /xxx.html HTTP/xxx" 200 60763 "https://xxx/xxx" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/x.x.x.x Safari/537.36 Edg/x.x.x.x" "10.x.x.x" "xxx" (-) [0] [51064] servera 17236380
'10.x.x.x - - [25/Jan/2024:11:46:42 +0900] "GET /xxx.html HTTP/xxx" 200 60763 "https://xxx/xxx" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/x.x.x.x Safari/537.36 Edg/x.x.x.x" "10.x.x.x" "xxx" (-) [0] [132198] servera 17236380
'10.x.x.x - - [25/Jan/2024:11:53:43 +0900] "GET /xxx.html HTTP/xxx" 401 60763 "https://xxx/xxx" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/x.x.x.x Safari/537.36 Edg/x.x.x.x" "10.x.x.x" "xxx" (-) [0] [39601] servera 15373341

煩雑なアクセスログ（testファイルに格納）ですが、上記のワンライナーを通すと……

cat test_qiita | awk '$9 == "200" && $4 ~ /2024:11:(3[2-9]|4[0-9]|5[0-7])/ {print substr($1, 2), substr($4, 14), substr($29, 2, length($29)-2)}'
10.x.x.x 11:32:41 51064
10.x.x.x 11:46:42 132198

必要な情報だけを抜き出すことができました。

1. ステータスコードは、HTTPアクセスの結果（成功、エラーなど）を表すコードです。 ↩

2. ステータスコードの詳細については以下を参照。https://developer.mozilla.org/ja/docs/Web/HTTP/Status ↩

3. Apache以外にも、同じくOSSのNginxやMicrosoftのIISが有名。https://www.rworks.jp/system/system-column/sys-entry/16296/ ↩

4. httpd.confにデフォルトである記述です。 ↩

5. ステータスの「>」は最終ステータスのログを取得することを示しています。 ↩

6. ログフォーマットを指定する書式の詳細については以下を参照。https://httpd.apache.org/docs/2.4/mod/mod_log_config.html#formats ↩

7. 200ぴったり以外の200番台のコードも成功を表すレスポンスです。今回扱うログでは成功ステータスは200番のみのため、200番を単独で指定しています。 ↩