Zenn
🅰️

【awk(mawk)】アクセスログを集計して分単位のアクセス数と特定のHttpStatuCodeの件数とその割合を出力する

2023/06/26に公開
Linux
awk
mawk
tech

業務でタイトルにあるようなことをやろうと思ったのですが、業務中に良い方法が全く思いつかずに大敗北してしまったので休日に調べてリベンジしました。

経緯

会社で取り扱っているサービスで動いているnginxが、あるタイミングからHttpStatusCode 502を返していることが判明しました。
原因や影響を調査するために、アクセスログを解析することにしました。アクセスログを解析するにあたって、下記の観点で集計をしようとしました。

  • 分単位でアクセス数の合計
  • 分単位における、HttpStatusCode 502の合計
  • 分単位における、合計アクセス数に占めるHttpStatusCode 502の割合

uniqやsortとawkを組み合わせればいけるだろうと思ったのですが、その場で良い処理方法を思いつかなかったので、中途半端な集計ワンライナーを手動で何種類も流し、出力結果をエクセルファイルにまとめてなんとかしました🤮

あまりアクセスログの解析をしたことがなかったので、経験不足によるものもありますが、そもそも自分がawkを使いこなせていなかったことが大きな敗因だったと思います。

前提

今回はアクセスログの集計方法に関する記事なのでHttpStatusCode 502がなぜ発生していたのかの原因には触れません。

今回の集計対象のアクセスログのフォーマットには、LTSV形式を採用しています。
LTSV形式とは、Key:ValueをTabで区切ったログフォーマットです。
下記のようなアクセスログ形式になります(実際のアクセスログではなくサンプルです)。

host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:24:56+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)

この形式だとcutやawkを使いやすそうですね。

以降の説明では、解析するアクセスログは上記のフォーマットを解析することを前提とします。お使いのログフォーマットによっては紹介する方法で解析できない場合もあるかもしれませんがあらかじめご了承ください。

今回のゴール

まず、テストデータとして、下記のアクセスログを集計の対象とします。

host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:22:06+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:22:16+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:22:26+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:502	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:22:36+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:22:46+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:22:56+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:23:06+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:502	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:23:16+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:502	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:23:26+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:502	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:23:36+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:502	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:24:06+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:24:16+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:24:26+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:24:36+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:24:46+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)
host:127.0.0.1	ident:-	user:frank	time:2023-06-25T17:24:56+09:00	req:GET /apache_pb.gif	HTTP/1.0	status:200	size:2326	referer:http://www.example.com/start.html	ua:Mozilla/4.08[en](Win98;I;Nav)

上記の内容をもとに、最終的に欲しい出力結果は以下のようなものになります

time:2023-06-25T17:22, total:6, status502:1, rate:16.666667%
time:2023-06-25T17:23, total:4, status502:4, rate:100.000000%
time:2023-06-25T17:24, total:6, status502:0, rate:0.000000%

左から、

  • 時刻(分単位)。アクセスログベースなのでアクセスが1件もない時間帯は集計しない
  • その時間帯の総アクセス数。HttpStatusCode 502も含む
  • その時間帯のHttpStatusCode 502の件数。
  • その時間帯の総アクセス数に占めるHttpStatusCode 502の割合(%)

この出力が得られることをゴールとして、集計コマンドを考えます

最終的に出来上がったコマンド

解説や過程はさておき、まずは出来上がったコマンドを紹介します。

awk '{time = match($4, /time:[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T[0-9][0-9]:[0-9][0-9]/);trimmed_t = substr($4,RSTART,RLENGTH);total[trimmed_t]++;if($8 == "status:502")status502[trimmed_t]++}END{for (t in total){if(!(t in status502))status502[t] = 0;rate[t] = status502[t] / total[t] * 100;printf("%s, total:%d, status502:%d, rate:%f%%\n", t, total[t], status502[t], rate[t])}}'

ワンライナーだと長すぎて解読不能なので、ファイルに書いて整形します。

rate.awk
{
	time = match($4, /time:[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T[0-9][0-9]:[0-9][0-9]/);
	trimmed_t = substr($4,RSTART,RLENGTH);
	total[trimmed_t]++;
	if($8 == "status:502")
		status502[trimmed_t]++
}
END	{
		for (t in total)
		{
			if(!(t in status502))
				status502[t] = 0;
			rate[t] = status502[t] / total[t] * 100;
			printf("%s, total:%d, status502:%d, rate:%f%%\n", t, total[t], status502[t], rate[t])
		}
	}

解説

分割しながら解説します。awkには前処理とメイン処理と後処理でブロックを分けることができるのでこれを利用しました。

メインブロック

ここの部分の解説です

{
	time = match($4, /time:[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T[0-9][0-9]:[0-9][0-9]/);
	trimmed_t = substr($4,RSTART,RLENGTH);
	total[trimmed_t]++;
	if($8 == "status:502")
		status502[trimmed_t]++
}

今回の集計では、時刻をKey、アクセス件数をValueとした連想配列を定義して集計を行いました。
一つの連想配列では各時刻の総アクセスだけしか集計できないので、時刻をKey、HttpStatusCode 502のアクセス件数をValueとした連想配列を別途用意し、別々に集計を行うようにしました。

連想配列を作るにあたって、まずはKeyとなる時刻が必要になります。ただ、アクセスログはtime:2023-06-25T17:24:26+09:00という形式になっており、分以降の数値は切り捨てる必要があります。該当のフィールド(awkで$4が該当)から時刻を切り出すために下記の処理を行ってます。

time = match($4, /time:[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T[0-9][0-9]:[0-9][0-9]/);
trimmed_t = substr($4,RSTART,RLENGTH);

match()を使うと、正規表現にマッチした開始位置がRSTART,マッチした文字列の長さがRLENGTHというawkの組み込み変数に代入されます。この情報をもとにsubstr()を使うことで正規表現にマッチした文字列を取り出すことができます。
ここで一つ躓いたのですが、mawkでは正規表現で繰り返し条件{n}がサポートされていないようなのでこのような長い表記になりました。
この処理によってKeyとなる時刻が得られたので、以降の処理でそれぞれの連想配列を作り集計を行っています。

ENDブロック

ここの部分の解説です。

END	{
		for (t in total)
		{
			if(!(t in status502))
				status502[t] = 0;
			rate[t] = status502[t] / total[t] * 100;
			printf("%s, total:%d, status502:%d, rate:%f%%\n", t, total[t], status502[t], rate[t])
		}
	}

ENDブロックなので、全ての集計が終わった後に一度だけ実行されるブロックになります。
ここでは主に集計結果を標準出力への出力を行っています。
集計結果は時刻をKeyにした連想配列なので、for ( key in array)を使ってkeyをベースにループを回しています。
時刻はt、時刻tにおける総アクセス数はtotal[t]、時刻tにおけるHttpStatusCode 502の件数はstatus502[t]に格納されているので、あとは割合を計算してprintf()すれば終わりなのですが、時刻によってはHttpStatusCode 502が一度も集計されていない場合が考えられます。
この場合、status502[t]に該当するValueが存在しないので、割合を計算して出力しようとすると、結果が空になります。これを防ぐために、時刻tにおいてHttpStatusCode 502が一度も集計されていない場合は下記の処理を施して値を0にしています。

if(!(t in status502))
	status502[t] = 0;

これで全ての値が出揃ったので、あとは出力フォーマットを整えてprintf()しているだけです。

まとめ

今までawkは特定の区切り文字を指定して任意の位置のフィールドをprint()する程度にしか使っていなかったのですが、思った以上にawkはパワフルな言語でした。
もっと深刻な障害が発生した場合は、迅速な原因の特定や影響範囲の算出などが求められると思うので、いい勉強になりました。

Discussion