UECジャーナル

開眼☆シェルスクリプト ログを自在に加工する(2) ― ログの整形と集計

ログを自在に加工する(1) ― awkとsedの使い方で紹介したように、CentOSやApache HTTPd Serverが出力するログはプログラムで処理するためには最適化されていない。こうしたログファイルを処理しやすい形式に整形して保存し、保存した整形済みファイルに対してターミナルでコマンドを実行し有用なデータを抽出する方法を紹介する。

大切なのはデータを整理すること

ログを整形する処理はシェルスクリプトとしてファイルに保存しておく。整形後のファイルからデータを抽出する処理は、ターミナルでコマンドを実行することで終わらせる。 整理されたログファイルに対してはsort(1)やuniq(1)、それにawk(1)/sed(1)をちょっと組み合わせてやるだけで大抵のことができる。このような一時的な処理は逆にシェルスクリプトとしてファイルに残しておくと後で面倒なことになる。繰り返し実行するならインタラクティブシェルのエイリアスでも設定しておけばよいだろう。

"Notes on Programming in C"※1から次の言葉を引用しよう注2。

Data dominates. If you've chosen the right data structures and organized things well, the algorithms will almost always be self­evident. Data structures, not algorithms, are central to programmin. (See Brooks p 102.) [Pike1989]

「データがきれいだとコードが短く簡単になる」ということが説明されている。シェルスクリプトであればawk(1)などで扱いやすい形式にして、どこか適切な場所に整形済みデータを置くことが目標となる。

今回のお題：ログをさばく(後半)

CentOS 6のsecureログファイルおよびApache HTTPd Serverのaccess_logログファイルを題材にしてテキストを処理する方法を紹介する。ログファイルは/home/ueda/LOG/ディレクトリに保存してあるとする。

$ ls | column -c 50
access_log	secure-20111016
access_log.1	secure-20111023
access_log.2	secure-20111030
access_log.3	secure-20111204
access_log.4	secure-20111211
secure		secure-20111218
secure-20111012	secure-20111225
$

それぞれログ形式がどのようになっているかは次のように確認できる。

$ head -n 1 secure access_log
==> secure <==
Nov 20 09:23:44 cent sshd[20019]: Did not receive identification string from 123.232.118.231

==> access_<og <==
114.80.93.71 - - [20/Nov/2011:06:47:54 +0900] "GET / HTTP/1.1" 200 1429 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)"
$

人間が読むにはこの形式のままでもよいが、プログラムで処理しようとした場合、次のような点が問題になる。

このログをターミナルからコマンドを実行してすぐにデータを抽出できるレベルまで整形していく。

secureログ整形シェルスクリプト

secureログには西暦年が記述されていないが、先に示したようにここではsecureログのローテート先のファイル名に年月日を付与してある。この年月日を西暦年を追加するという整形処理に利用するものとする。処理の本質部分だけをシェルスクリプトにまとめると次のようになる。ここではSECURE_NORMALIZEというファイル名で作成してある。

#!/bin/sh

dir=/home/ueda/
tmp=/tmp/$$
today=$(date +%Y%m%d)

cd $dir/LOG
cat secure > $tmp-$today

awk '{print FILENAME,$0}' secure-* $tmp-$today	|
#1:ファイル名 2:ログの内容
#過去のログファイル名から年月日だけ取り出す
sed 's/^[^-]*-//'				|
#1:ファイル年月日 2:ログの内容
#年と月日を分ける
sed 's/^..../& /'
#1:ファイル年 2:ファイル月日 3:ログの内容

awk(1)でログデータに日付を追加するといった内容だ。実行すると次のようになる。

$ ./SECURE_NORMALIZE | head -n 2 | cut -c 1-51
2011 1012 Sep 11 19:15:23 localhost runuser: pam_un
2011 1012 Sep 11 19:15:23 localhost runuser: pam_un
$ ./SECURE_NORMALIZE | tail -n 2 | cut -c 1-51
2011 1230 Dec 30 13:40:03 cent sshd[31763]: Connect
2011 1230 Dec 30 13:40:06 cent su: pam_unix(su-l:se
$

日付を正規化する処理を追加すると次のようになる。一見すると複雑なように見えるが、実際にはほとんどがコメントで、パイプの部分はawk(1)が5回、sed(1)が4回使われているだけだ。

#!/bin/sh -vx

dir=/home/ueda/
tmp=/tmp/$$
today=$(date +%Y%m%d)

cd $dir/LOG
cat secure > $tmp-$today

awk '{print FILENAME,$0}' secure-* $tmp-$today	|
sed 's/^[^-]*-//'				|
sed 's/^..../& /'				|
#1:ファイル年 2:ファイル月日 3:ログの内容
#出力例：2011 1230 Dec 30 13:40:06 cent su: pam_u
#月だけ頭に出して英語表記を数字表記に変える
awk '{print $3,$0}'				|
#1:ログ月 2:ファイル年 3:ファイル月日 4:ログの内容
#前編で登場した月の英語表記を数字に変換するsedスクリプト
sed -f $dir/SYS/MONTH -				|
#ログから日付を持ってきてログ月にくっつける
#一桁の日付を二桁に（既出のgsubを使うが普通はsprintf）
awk '{gsub(/^.$/,"0&",$5);$1=$1$5;print}'	|
#1:ログ月日 2:ファイル年 3:ファイル月日 4:ログの内容
#ログの月日がファイルの月日より後なら昨年のデータ
awk '{if($1>$3){$2--};print}'		|
#1:ログ月日 2:ログ年 3:ファイル月日 4:ログの内容
#出力例：0911 2011 1012 Sep 11 19:17:44 localhost
awk '{$1=$2$1;$2="";$3="";$4="";$5="";print}'	|
#日付の後に無駄なスペースがたくさん入るので消す
sed 's/  */ /' > $dir/LOG/SECURE

rm -f $tmp-*
exit 0

実行すると次のようになる。

$ tail -n 3 ../LOG/SECURE | tail -n 3 | cut -c 1-47
20111230 13:39:16 cent su: pam_unix(su-l:sessio
20111230 13:40:03 cent sshd[31763]: Connection
20111230 13:40:06 cent su: pam_unix(su-l:sessio
$

access_logログ整形シェルスクリプト

access_logはデフォルトの設定であれば次の項目で左から順に9項目のデータが記述されている。

  1. クライアントのIP
  2. クライアントアイデンティティ
  3. ユーザ名
  4. アクセス日時
  5. クライアントからの要求
  6. ステータスコード
  7. 転送バイト数
  8. 参照元サイト
  9. クライアントの情報

ここではログをフィールド形式に変換したいため、次の規則で変換を実施するものとする。

空白区切りにするところまでのシェルスクリプトを次に示す。ここではHTTPD_ACCESS_NORMALIZEというファイル名で作成してある。区切り文字として一旦"デリミタ"という文字列を当てているが、ファイル中に存在する可能性がほぼゼロの文字列であれば何でもよい。日本語が含まれないログファイルの場合、日本語を割り当てて変換に利用するというのはひとつのテクニックである。

#!/bin/sh

export LANG=ja_JP.UTF-8
dir=/home/ueda/

cat $dir/LOG/httpd/access_log.*		    $dir/LOG/httpd/access_log		|
#「デリミタ」という文字を区切り文字にデータを分ける。
sed 's/^\(..*\) \(..*\) \(..*\) \[\(..*\)\] "\(..*\)" \(..*\) \(..*\) "\(..*\)" "\(..*\)"$/\1デリミタ\2デリミタ\3デリミタ\4デリミタ\5デリミタ\6デリミタ\7デリミタ\8デリミタ\9/'	|
#_を\_に
sed 's/_/\\_/g'				|
#空白を_に
sed 's/ /_/g'				|
#デリミタを空白に
sed 's/デリミタ/ /g'

出力はたとえば次のようになる。

$ ./HTTPD_ACCESS_NORMALIZE 2> /dev/null | head -n 1
180.76.5.49 - - 13/Nov/2011:05:55:20_+0900 GET_/ueda/profile.htm_HTTP/1.1 200 1841 - Mozilla/5.0_(compatible;_Baiduspider/2.0;_+http://www.baidu.com/search/spider.html)
$

フィールドが9つになっているかどうかは、次のようにawk(1)を使えば調べることができる。

$ ./HTTPD_ACCESS_NORMALIZE 2> /dev/null | awk '{print NF}' | uniq
9
$

sed(1)の使い方がわかりにくいという場合、次のようにawk(1)を使って同様のことをすることもできる※3。

#!/bin/sh

dir=/home/ueda/
tmp=/tmp/$$

cat $dir/LOG/access_log.*		    $dir/LOG/access_log			> $tmp-data

awk -F" '{print  $1}' $tmp-data	|
awk '{print sprintf("%010s",NR),$0}'	|
awk '{print $1,1,$2;print $1,2,$3;      print $1,3,$4;print $1,4,$5,$6}'	> $tmp-1-4

awk -F" '{print $2}' $tmp-data		|
awk '{print sprintf("%010s",NR),5,$0}'	> $tmp-5

awk -F" '{print $3}' $tmp-data		|
awk '{print sprintf("%010s",NR),$0}'	|
awk '{print $1,6,$2;print $1,7,$3}'	> $tmp-6-7

awk -F" '{print $4}' $tmp-data		|
awk '{print sprintf("%010s",NR),8,$0}'	> $tmp-8

awk -F" '{print $6}' $tmp-data		|
awk '{print sprintf("%010s",NR),9,$0}'	> $tmp-9

sort -m -k1,2 -s $tmp-{1-4,5,6-7,8,9}

実行すると次のようになる。

$ ./HTTPD_ACCESS_NORMALIZE.awk | head -n 9 | cut -c 1-53
0000000001 1 180.76.5.49
0000000001 2 -
0000000001 3 -
0000000001 4 [13/Nov/2011:05:55:20 +0900]
0000000001 5 GET /ueda/profile.htm HTTP/1.1
0000000001 6 200
0000000001 7 1841
0000000001 8 -
0000000001 9 Mozilla/5.0 (compatible; Baiduspider/2.0
$

sed(1)で実装したものに、さらに日付処理などを加えて整理すると次のようになる。

#!/bin/sh -vx

export LANG=ja_JP.UTF-8
dir=/home/ueda

dlmt=デリミタ
reg='^\(..*\) \(..*\) \(..*\) \[\(..*\)\] "\(..*\)" \(..*\) \(..*\) "\(..*\)" "\(..*\)"$'
str="\1$dlmt\2$dlmt\3$dlmt\4$dlmt\5$dlmt\6$dlmt\7$dlmt\8$dlmt\9"

#"や[ ]、空白を目印にレコードを9分割する。
sed "s;$reg;$str;" $dir/LOG/httpd/access_log.*		                   $dir/LOG/httpd/access_log		|
#_を\_に
sed 's/_/\\_/g'						|
#空白を_に
sed 's/ /_/g'						|
#デリミタを空白に戻す
sed "s/$dlmt/ /g"					|
#出力例：119.147.75.140 - - 23/Nov/2011:15:14:13_+0900 ...
#日時を先頭に
awk '{a=$4;$4="";print a,$0}'				|
#出力例：23/Nov/2011:15:14:13_+0900 119.147.75.140 - - ...
sed 's;^\(..\)/\(...\)/\(....\):\(..\):\(..\):\(..\)_[^ ]*;\2 \1 \3 \4\5\6;'	|
#出力例：Nov 23 2011 151413 119.147.75.140 - - ...
sed -f $dir/SYS/MONTH					|
#出力例：11 23 2011 151413 119.147.75.140 - - ...
awk '{d=$3$1$2;$1="";$2="";$3="";print d,$0}'		|
#1:日付 2:時刻 3-10:あとの項目
#間延びした区切りの空白を戻す。
sed 's/  */ /g' > $dir/LOG/ACCESS_LOG

exit 0

実行すると次のようになる。

$ head -n 3 ../LOG/ACCESS_LOG | cut -c 1-60
20111030 062140 66.249.67.163 - - GET_/robots.txt_HTTP/1.1 4
20111030 062140 209.85.238.184 - - GET_/paper/ARAIBO_Techni
20111030 072937 123.125.71.72 - - HEAD_/paper/ARAIBO_Techni
$

整形したデータの活用

整形したデータを活用してみよう。まず、secureログから不正ユーザアクセスを仕掛けてきたIPv4アドレスを抽出してみる。

$ awk '$4~/^sshd/' SECURE | awk '$5=="Invalid"' |
awk '$6=="user"' | head -n 3
20110912 00:57:32 cent sshd[2942]: Invalid user http from 211.233.62.118
20110912 04:05:35 cent sshd[3386]: Invalid user oracle from 203.236.203.2
20110912 04:05:37 cent sshd[3388]: Invalid user oracle from 203.236.203.2
$

IPv4アドレスだけ表示させるなら次のようにすればよい。

$ awk '$4~/^sshd/' SECURE | awk '$5=="Invalid"' |
awk '$6=="user"' | awk '{print $NF}' | sort | uniq > tmp
$ head -n 3 tmp
110.234.96.196
111.92.236.251
112.65.165.131
$

不正アクセスに使われたユーザ名とその回数を抽出するには次のようにコマンドを実行する。

$ awk '$4~/^sshd/' SECURE | awk '$5=="Invalid"' |
awk '$6=="user"{print $7}' | uniq | sort | uniq -c |
sort -k1,1nr | head -n 3 | awk '{print $1,$2}'
362 test
275 oracle
234 admin
$

Apache HTTPd Serverに対して1日あたり何個のIPv4アドレスからアクセスがあったのかを調べるには次のようにコマンドを実行する。

$ awk '{print $1,$3}' ACCESS_LOG | sort | uniq |
awk '{print $1}' | uniq -c > tmp
$ cat tmp | head -n 4 | awk '{print $1,$2}'
28 20111009
24 20111010
28 20111011
44 20111012
$

最後に、Webページのアクセス一覧を作成してみる。まず、ステータスコードが200(OK)のものを取り出し、パスを整理する。

$ awk '$7==200&&$6~/^GET/{print $6}' ACCESS_LOG |
sed 's/^GET_\(..*\)_[^_]*$/\1/' | sed 's/?..*//' > tmp
$ head tmp
/ueda/profile.htm
/paper/ARAIBO_TechnicalReport2005.pdf
/
/araibo.css
/updates.html
/ueda/activity_j.cgi
/ueda/award.cgi
/ueda/current.htm
/ueda/dp.php
/ueda/index.htm
$

ランキング対象を絞り込み、整理して表示させると次のようになる。

$ cat tmp | awk -F. '$NF~//$|^htm|^cgi|^php/' |
sort | uniq -c | sort -k1,1nr | sed 's;\\_;_;g' |
head -n 10 | awk '{print $1,$2}'
152 /
78 /haribote/index.php
78 /updates.html
71 /ueda/dp.php
50 /ueda/prob_robotics_j.cgi
49 /ueda/publication_j.cgi
44 /ueda/index_j.htm
42 /ueda/index_j_right.html
40 /ueda/index_j_left.htm
28 /ueda/current_j.html
$

おわりに

ログを整形するシェルスクリプトとターミナルでのログ集計の例を紹介した。ターミナルでのログ集計は実務でも利用する操作なので、何度も操作して指に慣れさせてしまいたいところだ。

取り上げたシェルスクリプトではfor構文やwhile構文は一回も使用していない。if構文はawk(1)の内部で一度だけ使っている。制御構文であるwhileやforをなるべく使用しないようにする方法は制御構文whileやforを避ける方法を参照のこと。

※1 Rob Pike, "Notes on Programming in C", http://www.lysator.liu.se/c/pikestyle.html, 1989.

※2 邦訳: データがすべてに優先する。適切なデータ構造を選んで物事をちゃんと整理すれば、アルゴリズムはほとんどの場合に自明となる。アルゴリズムではなく、データ構造がプログラミングの中心である(Brooksの102ページを参照のこと)。

※3 日本GNU AWKユーザー会 (JGAUC) 斉藤氏ご指導による。

Software Design 2012年3月号 上田隆一著、「テキストデータならお手のもの"開眼☆シェルスクリプト" : 【3】ログを自在に加工する(2) ― ログの整形と集計」より加筆修正後転載。

Last modified: 2014-01-13 00:00:00