ログの読み方について


１．はじめに

最近に限らず、「コンピュータを利用する者はログに注意すべきである」と言われ続けてますが、実際にどのログのどの部分を読めば良いのかとか、注意しなければならないポイントとかを解説してくれている所ってなかなか目につきません。ボクの探し方が悪いのかもしれませんが。

このHPでも「Snort入れろ」「iplog入れろ」とか言ってますけど、それらがせっかく重要な記録を残してくれていても、読み方をちゃんと書いておかないと片手落ちですよね。それなので、ログチェックについてちょっと考えてみました。

例によってRedHat系のLinux上でのお話です。他のディストリビューションやOSでは、記録が残っているファイル等がちょっと違っていると思いますけど、それほど違いは無いはずです。

むろんこれで十分とは思ってません。いろいろ意見があるとは思います。アドバイス等頂けると幸せです。




２．ログを読む上でのポイント

ログファイルを読む時はいろいろな事に注意しなければなりません。もっとも重要なのは、見落とししない事と誤判断をしない事の２点であると考えます。

見落としはここで書くまでもないことでしょう。せっかく記録されていても、見落としていたのでは何の役に立ちませんから。

またこちらの方が重要かもしれませんが、不審な記録が残っていたとしても決して慌ててはいけません。なるべく多くの情報を集めて慎重に検討しましょう。

不正な利用かどうかを判断するポイントとしては

・ログファイルは正常か？
・その利用者はその場所からアクセスすべきか？
・その利用者はその時間にアクセスすべきか？
・その利用者はそのサービスにアクセスすべきか？
・行動に不審な点は無いか？
と、以上のような事を注意しつつログファイルを読みます。




３．syslogが記録したログファイル

大半のUN*X系OSは syslog がシステム上に起こった重要な出来事をログファイルに記録してくれているはずです。Solarisなど一部のOSではinetdにオプションを追加しないと、アクセス元のIPアドレスを記録してくれなかったりしますけど、Linux系ではデフォルトでほぼ十分な情報が記録されます。

RH系でデフォルトなら、/var/log/messages と /var/log/secure の２つだけは最低でも目を通すようにしてください。syslog.confを自分でいじって、重要な記録をまとめたログファイルを作成するのも良い方法ですね。

さて、/var/log/messages をちょっと覗いてみましょう。

Feb 15 00:12:42 hoge kernel: Packet log: input DENY eth0 PROTO=1 194.94.214.4:8 210.253.169.19:0 L=1500 S=0x00 I=351 F=0x4000 T=232
Feb 15 10:16:41 hoge PAM_pwdb[10651]: (sshd) session opened for user micky by (uid=0)
Feb 15 10:18:01 hoge PAM_pwdb[10697]: authentication failure; micky(uid=1005) -> root for su service
Feb 15 10:18:06 hoge PAM_pwdb[10700]: (su) session opened for user root by micky(uid=1005)
Feb 15 10:18:23 hoge snmpd: Connection from xxx.xxx.xxx.51
Feb 15 10:42:02 hoge ftpd[10063]: FTP LOGIN FROM xxx.xxxx.ne.jp [xxx.xxx.xxx.218], micky
Feb 15 10:42:46 hoge ftpd[10063]: FTP session closed
Feb 15 11:16:40 hoge sshd[10651]: Accepted password for micky from xxx.xxx.xxx.222 port 861
Feb 15 12:38:47 hoge PAM_pwdb[10801]: (su) session closed for user root
Feb 15 12:38:48 hoge PAM_pwdb[10823]: (sshd) session closed for user micky
Feb 15 12:50:50 hoge PAM_pwdb[12020]: (login) session opened for user micky by (uid=0)
こんなようなカンジで記録されていると思います。他にもDNSが動いていれば、named のログが残るでしょうし、mail関係のログが存在する場合もありますが、特に PAM_ で始まるログを注意しましょう。認証モジュールの pam が設定されている環境であれば、ほとんどの認証情報が /var/log/messages 内に残ります。

Feb 15 10:16:41 hoge PAM_pwdb[10651]: (sshd) session opened for user micky by (uid=0)
 user:micky により sshd へのセッションが開始されたことを記録しています。


Feb 15 10:18:01 hoge PAM_pwdb[10697]: authentication failure; micky(uid=1005) -> root for su service
 user:micky が su コマンドにより root 特権を得ようとしましたが、認証エラーが発生したことを記録しています。


Feb 15 10:18:06 hoge PAM_pwdb[10700]: (su) session opened for user root by micky(uid=1005)
 user:micky が su コマンドにより、正常に root 特権を得たことを記録しています。


Feb 15 12:38:47 hoge PAM_pwdb[10801]: (su) session closed for user root
 user:root が su コマンドによるセッションを終了したことを記録しています。


Feb 15 12:38:48 hoge PAM_pwdb[10823]: (sshd) session closed for user micky
 user:micky が sshd へのセッションを終了したことを記録しています。


また、ipchainsによりセッションを記録するよう設定している場合などには、以下のような記録が残ることがあります。

Feb 15 00:12:42 hoge kernel: Packet log: input DENY eth0 PROTO=1 194.94.214.4:8 xxx.xxx.xxx.19:0 L=1500 S=0x00 I=351 F=0x4000 T=232
これは ftp による接続を表しています。

Feb 15 10:42:02 hoge ftpd[10063]: FTP LOGIN FROM xxx.xxxx.ne.jp [xxx.xxx.xxx.218], micky
Feb 15 10:42:46 hoge ftpd[10063]: FTP session closed
ftp により認証エラーが発生した場合などには、以下のように非常に目立つように記録されています。

Feb 13 08:39:16 hoge ftpd[2442]: FTP LOGIN FROM xxx.xxxx.net [xxx.xxx.xxx.69], badboy
Feb 13 08:40:40 hoge PAM_pwdb[2468]: authentication failure; (uid=0) -> badboy for ftp service
Feb 13 08:40:41 hoge xxx.xxx.net: connected: IDLE



[2468]: failed login from matrix xxx.xxx.net [xxx.xxx.xxx.69]
telnet 等による接続の場合は、以下のような記録が残ることがあります。

Feb 15 12:50:50 hoge PAM_pwdb[12020]: (login) session opened for user micky by (uid=0)

また、/var/log/secure ファイルにも以下のようにセッション・ログイン情報等が記録されますが、ボクの場合は、後で説明する snort のログをこのファイルに記録するようにしています。

Feb 13 11:50:09 hoge in.ftpd[16981]: connect from xxx.xxx.xxx.112
Feb 13 12:48:14 hoge login: ROOT LOGIN ON tty1

以上のようなログファイルへの記録を読んで

・認証エラーの記録が残っているか？
・不審なアクセス元から接続の試みが発生していないか？
・不審なサービスへの接続の試みが発生していないか？

などを特に注意するようにしてください。




４．iplogの場合

適切に設定されたiplogを運用しているれば、かなり正確に不正利用などを発見することが可能になります。もちろん、自分のホストの状態を理解していればの話ですが。

では、ボクの所有するMatrixクンのiplogが記録したログを覗いてみましょう。

Mar 9 16:02:53 TCP: sunrpc connection attempt from xxxx.xxx.com.br:3933
Mar 9 18:10:58 TCP: auth connection attempt from xx.xxxx.gr.jp:4129
Mar 9 20:29:01 TCP: auth connection attempt from xx.xxxx.gr.jp:4199
Mar 9 20:36:48 TCP: ftp connection attempt from xxxx.xxx.xxxx.edu.tr:1682
Mar 9 21:23:02 TCP: domain connection attempt from xxxx.xxx.xxxx.edu.tr:3739
Mar 9 23:09:01 TCP: auth connection attempt from xxx.xxx.xxx.11:2553
Mar 9 23:24:33 TCP: domain connection attempt from xxxx.xxx.xxxx.edu.tr:4610
Mar 10 01:29:02 TCP: ftp connection attempt from xxx.xxxxx.ne.jp:3837
Mar 10 09:23:43 TCP: ssh connection attempt from xxxx.xxxx.xxx.ne.jp:512
Mar 10 11:02:15 TCP: auth connection attempt from xx.xxxxx.net:4284
Mar 10 14:43:35 TCP: ftp connection attempt from xxxx.xxx.xxxx.edu.tr:2988
Mar 10 16:18:55 TCP: ssh connection attempt from xxx.xxxxx.ne.jp:748
Mar 10 17:12:50 TCP: auth connection attempt from xx.xxxx.to:20549
Mar 10 18:39:24 TCP: webcache connection attempt from xxx.xxx.xxx.165:4528
Mar 10 20:59:17 TCP: port 54321 connection attempt from xxxx.xxxxx.net:54321
iplogの記録したログ読む場合は、特に以下の点について注意してください。

・そのサービスは運用されているか？
・そのネットワークからアクセスすべきか？
・行動に不審な点は無いか？

それでは、１行目から順に読んでいってみましょう。


Mar 9 16:02:53 TCP: sunrpc connection attempt from xxxx.xxx.com.br:3933

 まずxxxx.xxx.com.brからsunrpcにアクセスがありました。あなたのホストでは NFS などのrpcサービスを運用して、外部に対して公開していますか？ボクのホストではしてません。それどころかrpcは完全に止めています。これはもうプロービング以外の何者でもないですね。


Mar 9 18:10:58 TCP: auth connection attempt from xx.xxxx.gr.jp:4129

 ２行目は tcp/113 auth 。これは identd への接続要求です。SMTPセッションを開始した場合などに、サービスの利用状況などの情報を扱うために使用されます。ほとんどの場合で無視しても良いと思います。


Mar 9 20:36:48 TCP: ftp connection attempt from xxxx.xxx.xxxx.edu.tr:1682

 ４行目でへxxxx.xxx.xxxx.edu.trからftpのセッション要求が来ていますね。少なくともボクはトルコに知り合いいませんし、anonymous ftpサービスもやってません。これも何らかの悪戯である可能性が考えられます。


Mar 9 21:23:02 TCP: domain connection attempt from xxxx.xxx.xxxx.edu.tr:3739

 ５行目では同じサイトから tcp/53 domain に対してセッション要求が来ています。このホストでは、確かにDNSも運用していますが、ゾーントランスファを外部に許可していません。

この時点でxxxx.xxx.xxxx.edu.trから凄まじく遅いスローポートスキャンを受けている疑いが考えられます。


Mar 9 23:24:33 TCP: domain connection attempt from xxxx.xxx.xxxx.edu.tr:4610

 ６行目でもまた同じサイトから domain に対して繋げられてます。


Mar 10 01:29:02 TCP: ftp connection attempt from xxx.xxxxx.ne.jp:3837

 国内ISPからのftpセッションです。このホストはWebスペースを知人にレンタルしてますので、国内からでしたらftpセッションは日常的に発生しますが、どうもこのサイトには心当たりがありません。

ここで３.に戻って、同時刻にsyslogやftpdが残してくれた記録を参照します。正規の利用者が正常に認証を得てるか確認しましょう。認証エラーになっている場合は不正にログインしようとした可能性が考えられますし、FTP session closedの記録だけが残っている場合などはスキャンを受けた可能性が考えられます。


Mar 10 09:23:43 TCP: ssh connection attempt from xxxx.xxxx.xxx.ne.jp:512

 ９行目ではsshコネクションが記録されています。ボクのホストではtelnetの代わりにsshを利用していますので、この接続が正しいかどうかを上記のftpと同様にsyslog等の記録を参照して調べます。


Mar 10 14:43:35 TCP: ftp connection attempt from xxxx.xxx.xxxx.edu.tr:2988
おや、またxxxx.xxx.xxxx.edu.trからしつこくftpを探られています。これはもう何らかの攻撃を行ってこようとする意志が感じられます。
システム全体を再度確認して脆弱性が無いか調べるか、ipchains等を使用して該当サイトからの通信を拒絶した方が良いと思われます。


Mar 10 20:59:17 TCP: port 54321 connection attempt from xxxx.xxxxx.net:54321

 最後の行には不思議なポートへのセッションが記録されています。このセッションが記録された同時刻帯に同一サイトからのftpセッションが記録されていれば、PSVモードでftpセッションが開始されたと想像できます。

この場合は、ftpセッションが張られた形跡が無いことから、何らかのスキャンを受けているものと想像できます。

この後、port serch等で調べるてみたところ、どうやらバックドアとして使われる可能性のあるポートであることが分かりました。バックドアが仕掛けられているサイトを探し回っているのかもしれません。


と、こんな感じで丹念にログを読んでいきます。iplogのログ、ポートへのサービス割当て状況、それにsyslogの記録を照らしあわせてゆけば不正利用の痕跡が浮かび上がってくるでしょう。

ほんとはこういうのも自動化できると良いのですけどね。ちょっと面倒な作業です。



５．snortの場合

snortのログを読むにあたっては「すべて誤検知である」ことを前提に読む事がポイントです。なんかこのHPで目指している物を根底からひっくり返すような発言ですね。いや、でもホントに大切なのです。

誤検知はIDSの宿命と言っても過言ではありません。この先IDSがどのように進歩していったとしても、それは常に誤検知との戦いを伴うことでしょうし、現在の技術では完璧なIDSを構築するのは不可能ではないかと考えます。ここらについては、リクエストでもあれば別な所で書いてみたい気もします。賛否あるだろうなぁ。

ではこれまでと同様にサンプルのログをみながら....種類が膨大で、シグネチャによって書式も変わってしまうので、ひとつひとつヤルのは不可能です。しかたがありませんので、ポイントを箇条書き形式で書いてゆきます。順不同です。

その１．snortのportscan detectorはあんまりアテにしない
これはもう誤検知しまくりです。むろんちゃんと検知してくれるのですけど、正しく検出されているか調べる方法を学ぶよりも、snortのportscan detectorは停めて、４．で説明したiplogとsyslogの組み合わせでportscan検知を行う方が効率的です。

どうしてもsnortのportscan detecotorを使いたい場合は、４．の手順でiplogの部分をsnortに置き換えて読んでみてください。結局のところは「何処から何に誰がアクセスしているか」がポイントになります。

その２．-dオプションを使う
snortの起動オプションで-dを指定すると、ログディレクトリ内にアラートとして記録されたIPアドレスのディレクトリが作成され、アラートの詳細な情報とアプリケーションレイヤのデータがテキスト形式で記録されます。

重大なアラートが発生したら、直ちにこのデータを参照します。ここでsourceとdestinationのIPaddressとportを確認し、それでも不正利用である疑いを持ったのであれば、アプリケーションレイヤのデータに目を通します。

例えばexploitを検出した場合にありがちなのは、単にexploitのサンプルバイナリをftpしてたとか、メールで送ったなどといったものです。

ここで得られる情報を元に「その３」で解説するルールセットの確認や、「その４」で説明されるwhitehatsのサイトを利用しての確認を行うと、なぜそのアラートが発生してしまったのか理解できることでしょう。

その３．ルールにも目を通す
ルールセットを良く知ってください。なぜそのアラートが発生するのか理解できます。

ルールの中には驚くほど簡単に書かれたものも多数存在します。例えば特定のポートにアクセスがあった場合はバックドアであるとか、アプリケーションレイヤ中に特定の文字列を発見すると、バッファーオーバーフローであるといった感じです。

これらは決して間違っているわけではありませんが、ごく普通の通信の中に類似のパターンを持ったデータが流れてしまう確率が非常に高く、結果として誤検知が多いという現実になってしまうのです。

これを避けるため、ルールセットそのものを良く知っておき、その振るまいを理解しておく事が重要なのです。また「その５」で解説するwhitehatsでは、実際の攻撃パターンのサンプルなども掲載しているので、「その２」で得られた詳細なデータと実際の攻撃サンプル、それからルールセットの３つの要素を合わせて評価することにより、手動式ですけどかなり精度の高い検出結果を得ることができます。

その４．ルールはまめに更新する
snortのルールセットは常に更新され続けています。http://www.snort.org/snort-files.htm#Rulesから最新のルールを入手することが可能です。

ルールセットはアンチウィルスソフトのウィルスパターンデータとまったく同様の理由で定期的なアップデートとメンテナンスを必要とします。新しい攻撃手法をsnortは勝手に学習してくれませんからね。

ルールセットのメンテナンスなどについては、現在作成中のメモsnortを使い倒すを参照してください。

その５．Whitehatsを参照する
セキュリティ関係のポータルサイトWhitehats Network Security ResourceではIDSに関する情報が豊富にそろっています。

IDSに関する情報は、WhitehatsのSearch and Browse the Databaseを参照してください。このページには脆弱情報がとても詳しく解説されており、それぞれの情報はIDSxxxのようにコード化して管理されています。このコード番号は、snortのアラートで時折見かける物とリンクしていますので、snortのアラートを元にwhitehatsを参照して、詳しい脆弱情報を得ることが可能です。
とにかく、snortを運用する人々にとっては必見のサイトです

その６．セキュリティ情報には良く目を通す
Security Focus や PacketStorm 等で得られるセキュリティ情報に注意してください。
せめてSecurity Focusの VULNERABILITIES だけでも毎日巡回チェックしてください。





６．アラートの見方とバックドア Tips

a.普段のアラート発生状況を良く把握しておく

誤検知の傾向が強いアラートは、通常の運用状態で比較的安定した発生状況をみせます。
これから通常状態のアラートの発生傾向を把握しておいてください。このためには、普段からアラートに良く目を通しておく必要があります。また、マネージメントツールを活用したり、アラートの発生状況をグラフ等により視覚化しておくことも良いアイディアでしょう。


b.突然発生しだしたアラートに注意する
c.突然件数が増えだしたアラートに注意する

この２点は、a.と強く関連付けられています。a.による普段のアラートの発生傾向から大きく外れたアラートを知ることにより、異常の発生を知ることができます。

NIDSのルールセットで誤検知の傾向が強い物は数多く存在します。しかしながら、これらのルールは、該当する不正行為が発生した場合には、ほぼ確実に反応するとてもセンシティブなルールであると言えます。また、これらのルールが実際に反応した場合、一度に同じアラートが大量に発生するといった傾向を見せます。

よって、それらのルールは、ルールセット上から削除するのではなく、管理者であるあなたがしきい値を意識しながら監視してゆくことにより、いくぶん古臭い方法ではありますが、異常状態を検知することが可能となります。

また、普段滅多に発生しないようなアラートが、突然発生しだしたら要注意です。これは当然ですよね。


d.不自然なポートへの大量のトラフィックに注意する

こういうのを検出できるように、NIDSのルールを整備しとかないとなりませんが、ヒマな時とかに試してみると思わぬ収穫が得られたりします。

たとえば、お得意のsnortを使って、以下のルールを動かしてみます。

alert tcp any any -> any any (msg:"tcp traffic";)
alert udp any any -> any any (msg:"udp traffic";)
alert icmp any any -> any any (msg:"icmp traffic";)

とうぜん大量のアラートが発生しますが、pass ルールと、SQLでも使って上手くマネージメントしましょう。

これで何が検出できるか、感の良い人ならわかりますよね。べつにスニファーにしてアレなデータ集めるためじゃ無いですからね。

あとは、最近流行りなsnortルールで、こーゆーのもアリかな。

alert tcp any any <- any 1024: (msg:"detect ssh backdoor";content:"SSH-";flags:A+;)


e.アラートの対象となったホストのsyslogを調べる

いまさらこんな事を書くまでもないのですが、あたりまえの事を意外とやってないんですよね。対象となったシステムのログにはちゃんと目を通しましょう。


f.対象となったホストにポートスキャンをかける

これも重要です。怪しいアラートが発見された場合、特にexploits系のアラートが検出された場合には、攻撃対象となったホストに対してポートスキャンを行って、不審なポートが開いていないか確認してください。

最近の侵入者は、telnet や ssh などの経路を使ってシステムに再度侵入するよりも、バックドアを使う方を好むようです。

もちろん、単にポートスキャンだけでは検出できないバックドアも存在しますので、これだけでは発見しきれませんが、けっこう引っかかる可能性は高かったりします。


f.不審なポートが開いていたら、telnetで繋げてみる

これはバックドアを検出するための基本です。とにかく不審な不審を発見したら telnet で繋げて、何かタイプしてみましょう。できれば nc などを使用することをお勧めします。

運がよければ意味のある文字列が表示されるかもしれません。


と、ちょっと気づいたことを書いてみました。他にも「こんなんアリなんじゃない？」とかありましたら、お知らせください。