上田ブログ

なお、このサイトはbashでできている。

お知らせ: 詳解確率ロボティクス増刷 /  シェルスクリプト高速開発手法入門改訂2版発売中 /  エンジニアHubで記事を書きました / 

開眼シェルスクリプト2012年3月号

Tue Dec 9 21:53:23 JST 2014 (modified: Sun Oct 1 10:50:27 JST 2017)
views: 569, keywords:

  このエントリーをはてなブックマークに追加 
   

出典: 技術評論社SoftwareDesign

3. 開眼シェルスクリプト 第3回

3.1. はじめに

 皆様、花粉症対策、万全でしょうか。筆者の場合は毎年対応をサボり、 3月に入ってから医者通いして強い薬を飲み、 半分寝たまま仕事をするのが恒例行事となっております。 早めに原因を叩いておくことが大事だとは分かっていながら、 症状が出るまではつい後回しにしてしまいます。

 今回の開眼シェルスクリプトはログ捌き後半です。 ログを処理しやすい形式に整形して一旦保存し、 保存した整形済みファイルを使い、端末で有用な情報を抽出します。 前回ちらっと見ましたが、Linuxやapacheが吐き出すログは、 必ずしもプログラムで処理するために最適化されていません。 シェルスクリプトで処理しやすいように整形します。

3.1.1. 花粉症も厄介なデータも早めに叩くのが吉

 お題に入る前に、例によって格言を。今回は、次の言葉を意識します。

  • 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 programming. (See Brooks p. 102.) [Pike1989]

    “データが全てに優先する。もし適切なデータ構造を選んで物事を整理すれば、アルゴリズムはほとんどの場合に自明となる。アルゴリズムではなく、データ構造がプログラミングの中心である。(Brooksの102ページを見よ。)

(脚注:[Pike1989] Rob Pike, “Notes on Programming in C”, http://www.lysator.liu.se/c/pikestyle.html, 1989. 不勉強なため未だ読んでませんが、Brooksの102ページというのは、「人月の神話」の原著の102ページのようです。)

 要は「データがきれいだとコードが短く簡単になる」ということを言っています。 だとしたら、なるべく根元でデータを整形するのが良い習慣と言えるでしょう。 シェルスクリプトの場合は、awkで扱いやすい形式にして、 どこか適切な場所に整形済みデータを置くことが目標となります。 これをサボると、 長いシェルスクリプトを涕泗の如く生産して振り回されることになります。 ・・・花粉症のようになります。

 そういう観点を踏まえ、 今回はデータ整形をシェルスクリプトに残し、雑多な集計を端末で済ませます。 集計なぞ、単に何かの数を数えるくらいの処理だったらsort、 uniqと数個のawk・sedで済んでしまうことが大半で、 定期起動したりCGIスクリプトにしない限りはコードに残すと後で面倒です。 一方、データ整形は複雑なだけでなく、 扱いやすいデータを生成するという意味で価値が高いので、残す価値があります。

3.2. 今回のお題:ログをさばく(後半)

 前回に引き続き、Linuxのsecureログ、apacheのaccess_logを題材にします。 ホーム下に「LOG」というディレクトリを作って、 以下のように放り込んであります。 ファイルの場所は前回と同じなのですが、 secureログが前回執筆時より増えています。

[ LOG]$ ls httpd/access_log secure-20111016 httpd/access_log.1 secure-20111023 httpd/access_log.2 secure-20111030 httpd/access_log.3 secure-20111204 httpd/access_log.4 secure-20111211 secure secure-20111218 secure-20111012 secure-20111225 

 まず、恐れ多くも「きれいか汚いか」という観点でログにケチを付けます。

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

==> httpd/access_log <== 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に西暦年がついていない
  • どちらのログも月の表記が数字でない
  • access_logのデータの区切り方が統一されていない

これらを残しておくと、情報を引き出すときに毎回大変な目に遭います。

 ということで、ログをきれいにします。 実のところ、前回の「他に方法がないことが実験により明らかである場合に限り、 大きいプログラムを書け。」という格言に従えば、 ログの発生元をカスタマイズするのが最良の方法です。 しかし、それでは話が終わってしまうので、 シェルスクリプトで簡潔にします。すんません・・・。

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

 まずsecureログから。このログの最大の問題は、 ログ発生の月日は書いてあっても年が書いてないことです。 長期にわたるログの解析や、年をまたいだログのソートができなくなってしまいます。 前回は、tacを使って年を付加するトリッキーな処理を書きましたが、 今回はもう少し簡単な方法を使います。 幸い私のCentOS6の環境ではデフォルトの状態で過去のログのファイル名に 年月日が付いているので、これを使って

  • ある日のログファイルに、その日以降のログがあったらそれは前の年のログ

と決めつけて日付に年をつけます。

 さっそく格言どおり、データ側の都合でアルゴリズムを考える必要が出てきました。 最初からログに年情報があればこんなことはしなくてよいのです。 そういう意味では、過去のログに年月日が付いているので、少し負担は減りました。 その代わりに、ポータビリティーは犠牲になります。

 ログファイルの日付をログに付加する処理をリスト1に示します。 8行目で最新のsecureファイルに今日の日付をつけて/tmpにコピーします。 理由は後で説明します。下手な排他ではありません。 10行目のawk中の「FILENAME」は、ファイル名が入った変数です。 10行目の処理で、各ログの先頭にファイル名が入ります。 13行目のsedで、ファイル名から日付以外の文字を除去します。 正規表現 ^[^-]*- は、 「行頭からハイフンでない文字が続いた後にハイフン」という意味です。

 結局、8行目のコピーはsecureファイルのファイル名に日付を入れて、 過去のログ(secure-日付)と同じ処理ができるようにするだけのために行ったものでした。 ファイル名もデータの一部なので、 やはり正規化しておいた方がアルゴリズムが簡単になります。 速度にこだわる人はシンボリックリンクを使う手もあります。

▼リスト1: ログにログファイルの日付をつける

 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17
#!/bin/bash

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

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

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

リスト1のスクリプトを実行すると、出力は次のようになります。

[ SYS]$ ./SECURE_NORMALIZE | head -n 2 2011 1012 Sep 11 19:15:23 localhost runuser: pam_un 2011 1012 Sep 11 19:15:23 localhost runuser: pam_un [ SYS]$ ./SECURE_NORMALIZE | tail -n 2 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 

 次にログ自体の日付を正規化していきます。 リスト2のスクリプトで、日付を数字にして正規化できます。 コメントが多いので一見すると雑然としていますが、 パイプの部分はawk5個、sed4個で済んでいます。

▼リスト2: secureログの整形スクリプト

 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39
#!/bin/bash -vx # # SECURE_NORMALIZE secureログの正規化 # # usage: ./SECURE_NORMALIZE # written by R. Ueda (USP研究所) Dec. 30, 2011

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

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

#前半のコメントは省略 awk '{print FILENAME,$0}' secure-* $tmp-$today | sed -e 's/^[^-]-//' | sed -e '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 -e 's/ / /' > $dir/LOG/SECURE

rm -f $tmp-* exit 0

これで、次の出力のように日付が数字で表現できます。

[ SYS]$ tail -n 3 ../LOG/SECURE 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 

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

 次にaccess_logを整形します。これも大変です。 access_logには、左から順に9項目の情報が記述されています。 私は全項目を人に解説できるほどの知識は無いので詳しくは http://httpd.apache.org/docs/2.2/ja/logs.html 等を参照願いたいのですが、大雑把に説明すると、

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

です。

 整形の方法は一種類だけではありませんが、 ここではawkにあわせて空白区切りのデータにします。 その後、日時を8桁6桁に整形します。 整形の際、もともとデータ内にある空白が邪魔なので、

  • 空白はアンダースコア「」に変換
  • アンダースコアは「 \ 」に変換

します。また、区切りに使われている” “や[ ]など、 余計な文字は取り去ります。

 まず、空白区切りにするところまでの処理をリスト2に示します。 sedを使うと以下のようになります。 6行目のsedがお化けみたいになっていますが、 前半の正規表現はレコード全体に一致するように書いてあります。 これで、1から9までに各項目が入ります。 「でりみた」という文字は、暫定的に区切りにする文字列です。 ファイル中に存在する可能性がほぼゼロの文字列ならば何でもかまいません。

▼リスト3: access_logを空白区切りにするまでのスクリプト

 1 2 3 4 5 6 7 8 9 10 11 12
#!/bin/bash # HTTPD_ACCESS_NORMALIZEスクリプト

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

出力は例えば次のようになります。

[ SYS]$ ./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を使います。 NFは、読み込んだレコードのフィールド数が入る変数です。

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

 6行目のsedはお化けみたいでちょっとという方には、 リスト4のようにawkを使って分割する方法があります。 この方法は、日本 gnu awk ユーザー会の斉藤さんから教えていただいたものです。 awkの-Fは、入力の区切り文字を指定するオプションです。 この例では「”」を区切り文字に指定しています。 (エスケープするために \" と指定しています。)

▼リスト4: awkを使ったaccess_logの整形

 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23
dir=/home/ueda/GIHYO tmp=/tmp/$$ cat $dir/LOG/httpd/access_{log.,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}

 リスト4のコードで、次の出力のように縦にデータが整理されます。 一番左のコードはレコード番号です。 こちらの方が空白も残っていて、自分で区切り文字を作る必要もありません。 ただ、整形したデータをさらにawkで捌こうとするなら、 データは縦でなく横並びになっていた方が楽ちんです。

[ SYS]$ ./HTTPD_ACCESS_NORMALIZE.awk | head -n 9 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版の続きを作成しましょう。日時を加工する部分を記述します。 完成したものをリスト5に示します。コードの部分はたった14行です。 このコードは、紙面で見やすくするために変数を使ったり、 エスケープの”や’を使い分けたりしてコンパクトに書いていますが、 ベタに書いて動けば十分です。

▼リスト5: access_logの整形スクリプト

 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34
#!/bin/bash -vx # # HTTP_ACCRESS_NORMALIZE accrss_logの正規化 # usage: ./HTTP_ACCESS_NORMALIZE # # written by R. Ueda (USP研究所) Nov. 29, 2011 dir=/home/ueda/GIHYO

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.*,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

[ SYS]$ head -n 3 ../LOG/ACCESS_LOG 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 

3.2.3. あとは端末でさっと処理

 では、整形したものから情報を取り出してみましょう。

 まず、secureログから、不正なユーザでアクセスしてきたIPでも抽出しましょう。 まず、sshdのログの「Invalid user」のレコードを抽出します。 下の例のように、headを使って出力を確認しながら書いていきます。 一度入力したコマンド列は、bashの場合、上ボタンを押すと再利用できます。 筆者の場合、一つコマンドを書いたら出力して確認することを繰り返しながら、 泥縄式にコマンドを並べていく場合が多いです。 多少コマンドが多くなっても、ファイルにプログラムを書いて動作確認して・・・ という方法よりは、さっさと終わります。 慣れないうちは、リダイレクトを使ってファイルにデータを貯めて確認しながら練習しましょう。

[ LOG]$ 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 

あとは最後のフィールドのIPアドレスを表示するだけです。

[ LOG]$ awk '$4~/^sshd/' SECURE | awk '$5=="Invalid"' | awk '$6=="user"' | awk '{print $NF}' | sort | uniq > tmp [ LOG]$ head tmp 110.234.96.196 111.92.236.251 112.65.165.131 (略) 

 今度は、secureログから不正なユーザ名と、使われた回数を表示します。 以下は完成したコマンドラインです。2回出てくるuniqは、

  • 前のuniq: 連続して使われたユーザ名の回数を1と数えるために重複を除去
  • 後のuniq: ソートされたユーザ名の個数をカウント

しています。最後に使用数の多いものから上に並べて上位5個を表示しています。

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

 次はaccess_logをいじります。 まず、一日に何種類のIPアドレスから受信があったかを調べてみましょう。 下のように、日付とIPの対でuniqして、その後日付だけ残してソートし、 日付の数を数えます。

[ LOG]$ awk &##39;{print $1,$3}' ACCESS_LOG | sort | uniq | awk '{print $1}' | uniq -c > tmp [ LOG]$ cat tmp 28 20111009 24 20111010 28 20111011 44 20111012 (略) 

昔はもっとアクセスあったんですが・・・。

 最後の例です。自分のサイトのページに対して、 アクセスランキングでもつくってみましょう。 まず、ステータスコード($7)が200(OK)のものからリクエストを取り出し、 パスを抜き出します。 これはちょっとややこしい操作になっていますので、 もしかしたらリクエストの文字列はもう少し分解したほうが良いかもしれません。

[ LOG]$ awk '$7==200&&$6~/^GET/{print $6}' ACCESS_LOG | sed 's/^GET\(..*\)[^_]$/\1/' | sed 's/?..//' > tmp [ LOG]$ 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 

 次に、ランキング対象の拡張子を引っ張り出したいのですが、 どんな拡張子があるか確認してみましょう。

[ LOG]$ cat tmp | awk -F. '{print $NF}' | sort | uniq | tr '\n' ' ' / // /haribote/ /ueda/ /usage/ /webalizer/ JPG PNG cgi com/ css gif htm html jar jpg mpeg mpg pdf php png wmv 

個人サイトにありがちな統一感の無さですが、「/」で終わっているものと、 cgi、htm、html、phpあたりを対象にしましょう。

[ LOG]$ cat tmp | awk -F. '$NF~/\/$|^htm|^cgi|^php/' | sort | uniq -c | sort -k1,1nr | sed 's;\\;_;g' | head 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 

3.3. 終わりに

 今回は、ログを整形するシェルスクリプトと端末でのログ集計の例を示しました。 今回、forやwhileの使用はゼロでした。if文はawk中で1回だけ使いました。

 端末でのログ集計では当然グラフを描くなどの派手なことはできませんが、 ログに書いてあることは何でも集計できるので、慣れておくと自由が利きます。 また、「集計部分をシェルスクリプトにして、CGIから起動してブラウザで見る」 ということも、他の言語と比べてもそんなに手間にならないので、 機会があったら扱ってみたいと考えています。