はんにんさがし

数カ月前からウェブサーバのトラフィックの上がりが、ノコギリ状に増えている問題があった。
状況としては

NFSのreadが定期的に頻発している。

NFSのwriteも中長期で見ると右肩上がり

短期で見ると特徴的なノコギリ波形を示す

１時間に３～４回ペースで定期的に急激なNFS read/writeが生じている。
NFSの微々たるreadだし、放っておいてもサービスにはまったく問題ないんだけど、グラフが汚れて見辛いので原因追求。
長中期で見るとreadの回数は調子こいて右肩上がりのまま留まることを知らないので、このままエスカレートしていくのを放っておくわけにもいかない。
犯人の追跡開始。

・apacheのログ解析では不明だった
・mod_securityでPOSTを取ったが問題は見当たらなかった

そのため
・tcpdump port nfs -nxXs 6000 | grep read -C 20
・sar -n NFS 1 0
を同時に記録して解析を進めていくことにした。

・sarで３０秒間ほど急激なreadが定期的に発生していることを確認。

・一時的にreadが急激に上がった時間をメモしておく
10時36分31秒
10時51分39秒
11時05分58秒
11時21分14秒
11時36分03秒

次に、上記時刻のtcpdumpのhexdumpをみてみる。
すると11時21分17秒に一意のデータである特定キーワード(メールアドレス)が確認できたので、これを鍵にすることにした。

・ファイルサーバーからこのメールアドレスを全ファイル検索

grep -r 'drfadsee3@yahoo.com' ./

その結果

バイナリー・ファイル./ユーザA/blog/db/comment.email.idxは一致しました
バイナリー・ファイル./ユーザA/blog/db/comment.dbは一致しました

とユーザAのウェブスペースにこのメールアドレスを含むファイルがあることが判明。
ユーザAのアクセスログからPOSTしている時間だけ抜き取ってみた。
するとメモした時間とアクセスログのPOSTの時間が一致した。

・apacheのログ

grep ユーザA apache_log | grep blog | grep POST
09:18:13 :31367: [gw4.winserversecure.com] 85.17.145.7 ユーザーA POST /blog/mt-tb.cgi/145 HTTP/1.0 500 -
09:20:20 :31153: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
09:35:41 :9147: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
09:50:56 :21595: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
10:05:58 :24286: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
10:20:41 :29154: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
10:36:01 :32163: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
10:51:07 :3821: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
11:05:28 :6609: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
11:20:44 :8161: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
11:35:33 :21388: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
11:51:17 :30978: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
12:06:07 :6032: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
12:21:20 :13718: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
12:37:55 :25341: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
12:51:58 :5509: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
13:07:38 :14897: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
13:23:05 :21912: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
13:38:30 :31049: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
13:53:28 :9117: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
14:08:33 :20520: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
14:11:35 :12844: [66.90.77.6] 66.90.77.6 ユーザーA POST /blog/mt-tb.cgi/81 HTTP/1.0 200 79
14:23:46 :28173: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
14:34:18 :4474: [xanhlacay.info] 74.86.238.186 ユーザーA POST /blog/mt-tb.cgi/105 HTTP/1.0 500 -
14:39:20 :8180: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
14:54:36 :19139: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
15:09:06 :30925: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
15:24:28 :7162: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
15:39:50 :17200: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
15:54:30 :29185: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -
16:10:49 :6930: [93.174.93.58] 93.174.93.58 ユーザーA POST /blog/mt-comments.cgi HTTP/1.1 500 -

原因はユーザAに定期的に訪れる掲示板SPAMのボットによるものであることがわかった。

一般的にこの手のボットからのアクセスはapacheのログ解析やmod_securityのログ解析だけで比較的簡単に発見できるものだけど、今回は特異なケースだった。
SPAMをPOSTされて500エラーを返しているにもかかわらず、mt-comments.cgiは実際に書き込みを行っているんである(もちろんコメント自体にSPAMは表示されないし、ログにも500エラーしか残らない)。
そもそも特定の変則的なメッセージのPOSTで500エラーが発生する時点でMTの不具合だろう。
他でこんな変態ポストをされたら犯人特定は極めて困難だと思う。

対策方法

・GeoIPでアクセス規制を入れる

GeoIPEnable On
Order deny,allow
deny from all
SetEnvIf GEOIP_COUNTRY_CODE JP AllowCountry
Allow from .googlebot.com
Allow from .yahoo.net
Allow from .msn.com
Allow from .naver.jp
Allow from env=AllowCountry

結果、下記のように問題は解決した。