たそらぼ

日頃思ったこととかメモとか。

ロググループから特定ログを抽出するフィルターのパターンについて考える

複数種のログが混ざって格納されるロググループにサブスクリプションフィルタを設定して、特定種類のログのみ取り出したいのですが、パースとフィルターをする方法に癖があったのでまとめました。

やりたいこと

docs.aws.amazon.com

CloudWatch Logsでは、収集したログに対してフィルターを使うことで、様々な機能を実現することができます。

  • ログ内の文字をひっかけてカスタムメトリクスに変換する
  • サブスクリプションフィルタでkinesisなどほかのサービスに転送する

今回は、あるロググループに複数種類のログがまとめて格納されているとき、特定のログだけCloudWatch Logs外に転送するユースケースを考えています。
特に、ApacheログやSecureログなどは普通スペース区切りで格納されると思いますが、ペース区切りのログを対象としたパターンの書き方に癖があるので、上手くひっかける方法を調査しました。

Apacheログをパースする

角括弧 [] や 2 個の二重引用符 ("") が入っているログ

例えば以下のようなログです。

127.0.0.1 - frank [10/Oct/2000:13:25:15 -0700] "GET /apache_pb.gif HTTP/1.0" 200 1534

いわゆるApacheアクセスログですが、こちらは公式ガイドに例があり、標準のフォーマットであれば簡単に検知できるようです。
docs.aws.amazon.com


この例では、"[ip, user, username, timestamp, request, status_code, bytes]"という風に、ログに対してフィールド名を自分でつけたサブスクリプションフィルターを作成しています。

f:id:tasotasoso:20200524160416p:plain:w500
Apacheアクセスログの例1

ここで気になるのが、

  • [10/Oct/2000:13:25:15 -0700]
  • "GET /apache_pb.gif HTTP/1.0"

です。一見非常に簡単にパースできるように見えます。

ドキュメントを見ると、

メトリクスフィルターを使用してスペース区切りログイベントから値を取得できます。角括弧 [] または 2 個の二重引用符 ("") で囲まれた文字は単一のフィールドとして扱われます。

基本的に、前方から空白区切りでパースされるような挙動をするので、フォーマットとしてまとめて認識したい場合は、あらかじめログ内で角括弧 [] または 2 個の二重引用符 ("") で囲まれている必要があります。

角括弧 [] や 2 個の二重引用符 ("")が入っていないログ

例えば以下のようなログです。

127.0.0.1 - frank 10/Oct/2000:13:25:15 -0700 GET /apache_pb.gif HTTP/1.0 200 1534

さっきのログとは異なり、角括弧 [] や 2 個の二重引用符 ("")が入っていません。
このログに対して先ほどのようにパターンを設定すると以下のような結果になります。

f:id:tasotasoso:20200524163026p:plain:w500
パースに失敗した例
$requestに時差が来ていて、明らかにずれています。

上手く認識させるためには、フィールド名を増やす必要があります。

f:id:tasotasoso:20200524163211p:plain:w500
パースに成功した例

ちなみに、[ip, user, username, timestamp, timestamp2, ... ,request, status_code, bytes] のように、フィールド数が不明な場合に省略符号("...")を入れることができますが、まとめて解釈してくれるというよりは、適当なフィールド名を付けて認識してくれるようです。

f:id:tasotasoso:20200524164045p:plain:w500
パースに失敗した例2

このように、フィールド名を増やすことでパースをすること自体は可能ですが、ログフォーマットの定義に従ったフィールド定義は場合によってはできないことが分かります。

Syslog ログをパースする

つづいて、別の例としてSecureログをパースしてみます。
設定にもよると思いますが、ログの例としては以下のようなものを考えるとよさそうです。

#https://www.ipa.go.jp/security/awareness/administrator/secure-web/chap8/8_log-2.html

Feb 13 21:47:04 sol8 rsh[2429]: connection from bad port
Feb 13 21:47:04 sol8 rsh[2429]: connection from bad port
Feb 13 21:47:05 sol8 telnetd[2424]: ttloop: peer died: Bad file number
Feb 13 21:47:05 sol8 telnetd[2424]: ttloop: peer died: Bad file number
Feb 13 21:47:05 sol8 bsd-gw[2417]: Error reading from connection: Bad file number
Feb 13 21:47:05 sol8 bsd-gw[2417]: Error reading from connection: Bad file number
Feb 13 21:47:06 sol8 sendmail[2420]: NOQUEUE: Null connection from [192.168.200.10]
Feb 13 21:47:06 sol8 sendmail[2420]: NOQUEUE: Null connection from [192.168.200.10]

secureログはフィールド数も少ないので、フィールド名だけだと違うログもひっかける可能性が高そうです。
そこで、syslogtagやtimestampは形式が決まっているので、条件を入れていきたいと思います。
フィルターはこんな感じになります。

[month, day, time = "*:*:*",  hostname,syslogtag = "*[*]:", msg]

f:id:tasotasoso:20200524170731p:plain:w500
syslogのフィルターの結果

なお、条件の書き方は、以下に注意すると大体書けました。

  • 文字列は""で囲む
  • ""で囲っても、元のログにスペースが入っていると1フィールドとしては認識しない

Apacheログが混ざったロググループから、Syslogだけ抽出する

ここまでで条件付きでログをフィルターする方法が分かったので、最後に、Apacheログや、ほかの文字列と混ざったログからsecureログ"だけ"抽出するフィルターを確認します。
ログは以下を例として使ってみます。
2行目にApacheログ、4行名にsecureログっぽいけどなんか違う変な文字列をいれてあります。

Feb 13 21:47:04 sol8 rsh[2429]: connection from bad port
127.0.0.1 - frank 10/Oct/2000:13:25:15 -0700 GET /apache_pb.gif HTTP/1.0 200 1534
Feb 13 21:47:04 sol8 rsh[2429]: connection from bad port
Feb 13 21:47:05 sol8 telnetd[2424]: ttloop: peer died: Bad file number
AAA 99 0000000 sol8 xxxxxxx yyyyyyyyyyyyyyyyyyyyyyyyyyy
Feb 13 21:47:05 sol8 telnetd[2424]: ttloop: peer died: Bad file number
Feb 13 21:47:05 sol8 bsd-gw[2417]: Error reading from connection: Bad file number
Feb 13 21:47:05 sol8 bsd-gw[2417]: Error reading from connection: Bad file number
Feb 13 21:47:06 sol8 sendmail[2420]: NOQUEUE: Null connection from [192.168.200.10]
Feb 13 21:47:06 sol8 sendmail[2420]: NOQUEUE: Null connection from [192.168.200.10]

※ふつうは流石にログ種別ごとにlogStreamが分かれていると思いますが、検証しやすくするため一緒くたにしています。付けられたサブスクリプションフィルターから見ると、このように見えるはずです。


フィルターはSecureログの時と同じです。

[month, day, time = "*:*:*",  hostname,syslogtag = "*[*]:", msg]

f:id:tasotasoso:20200524171442p:plain:w500
Secureログだけフィルターした結果

ちゃんとSecureログだけヒットしていることがわかります。

感想

条件とフィールド名の数を組み合わせることでSecureログを分離することができました。ただ、正規表現に比べるとだいぶざっくりしているので、フィルターした後に違うログが混ざってしまう可能性がもありそうでした。

今回は同じロググループ内に異なるログ種別のログが混ざる想定でしたが、そもそも最初から異なるログ種別は異なるロググループになるように設計するのがよいのかなぁと思います。

参考

IPAのsyslogの説明。Secureログの例はここから拝借しました。
www.ipa.go.jp