Logstash を使ってログの整形と収集をいい感じにできないかなーとここ数日調べています。 その中で Grok フィルターの細かい挙動が気になったので検証してみました。
Grok フィルター
テキストにパターンマッチを行い構造化する Logstash のフィルタープラグインです。
Grok がどのように機能するのか例を使って簡単に紹介します。
次に示すのは、Minecraft サーバーにプレーヤーがログインした時のログです。
[03:26:35] [Server thread/INFO]: tama[/127.0.0.1:58472] logged in with entity id 396 at ([world]-208.5, 69.0, -133.5)
このログを次の設定によって処理してみます。
input { file { path => "/tmp/input.log" } } filter { grok { match => { "message" => "%{USERNAME:player}\[/%{IP:remote_ip}:%{POSINT:remote_port}\] logged in with entity id %{POSINT:entity_id} at \(\[%{DATA:world}\]%{BASE10NUM:pos_x}, %{BASE10NUM:pos_y}, %{BASE10NUM:pos_z}\)" } } } output { file { path => "/tmp/output.log" } }
動作確認のため入出力は /tmp
配下のファイルを使います。
結果は次の通りになりました。
$ echo '[03:26:35] [Server thread/INFO]: tama[/127.0.0.1:58472] logged in with entity id 396 at ([world]-208.5, 69.0, -133.5)' >> /tmp/input.log $ tail -1 /tmp/input.log | jq { "remote_port": "58472", "pos_z": "-133.5", "entity_id": "396", "pos_y": "69.0", "path": "/tmp/input.log", "@timestamp": "2020-12-09T16:43:29.454Z", "pos_x": "-208.5", "player": "tama", "host": "localhost.localdomain", "message": "[03:26:35] [Server thread/INFO]: tama[/127.0.0.1:58472] logged in with entity id 396 at ([world]-208.5, 69.0, -133.5)", "world": "world", "remote_ip": "127.0.0.1", "@version": "1" }
いい感じに構造化されて出力されました。 後はこれをDBにでも突っ込めば、分析にしろ監視にしろ、何もしない状態に比べるとかなり扱いやすくなったんじゃないでしょうか。
前置きはこの辺にして...本題に
細かい挙動が気になる
Grok の設定方法についてはドキュメントに載ってるわけですが、ここでカバーされてないような細かいところが気になって、実際に検証してみました。
検証
1. grok
の設定が空
input { file { path => "/tmp/input.log" } } filter { grok { } } output { file { path => "/tmp/output.log" } }
Grok はほとんどの場合 match
設定を入れて使うと思いますが、実は match
は必須設定ではないんですよ(ドキュメントで Required: No となってます)。
実際にこれでログを処理させてみます。
$ echo 'hoge' >> /tmp/input.log $ tail -1 /tmp/output.log { "@timestamp": "2020-12-09T14:54:28.396Z", "tags": [ "_grokparsefailure" ], "message": "hoge", "@version": "1", "path": "/tmp/input.log", "host": "localhost.localdomain" }
問題なく出力されましたが、タグに "_grokparsefailure"
が追加されているため、マッチ失敗扱いのようです。
match
が無い場合、常にマッチ失敗扱いとなるみたいです。どういう場合にこの挙動が役に立つんでしょうか...
※ 以降設定の input / output の設定部分は同じなので省略します。
2. match
設定に同名のフィールドが複数
filter { grok { match => { "message" => "%{GREEDYDATA:hoge}" "message" => "%{GREEDYDATA:fuga}" } } }
パターンのコンパイルエラーとなり Logstash が動きません。以上!
3. match
に複数フィールド
filter { mutate { add_field => { "hoge" => "%{message}" "fuga" => "%{message}" } } grok { match => { "hoge" => "ho%{GREEDYDATA:hoge2}e" "fuga" => "fu%{GREEDYDATA:fuga2}a" } } }
match
に同名フィールドが複数あると Logstash が動かなかったですが、別名で複数ある場合はどうでしょうか。
Grok の処理の前に Mutate を使ってログの値を hoge
と fuga
のフィールドに複製しておきます。
$ echo 'hoge' >> /tmp/input.log $ echo 'fuga' >> /tmp/input.log $ echo 'hogefuga' >> /tmp/input.log $ echo 'piyo' >> /tmp/input.log $ tail -4 /tmp/output.log | jq { "@version": "1", "@timestamp": "2020-12-09T15:53:25.152Z", "message": "hoge", "host": "localhost.localdomain", "hoge": "hoge", "path": "/tmp/input.log", "fuga": "hoge", "hoge2": "g" } { "@version": "1", "@timestamp": "2020-12-09T15:53:30.156Z", "message": "fuga", "host": "localhost.localdomain", "hoge": "fuga", "path": "/tmp/input.log", "fuga": "fuga", "fuga2": "g" } { "@version": "1", "@timestamp": "2020-12-09T15:53:35.160Z", "message": "hogefuga", "host": "localhost.localdomain", "hoge": "hogefuga", "path": "/tmp/input.log", "fuga": "hogefuga", "hoge2": "g" } { "@version": "1", "tags": [ "_grokparsefailure" ], "@timestamp": "2020-12-09T15:53:40.164Z", "message": "piyo", "host": "localhost.localdomain", "hoge": "piyo", "path": "/tmp/input.log", "fuga": "piyo" }
match
に複数の異なるフィールドがあると、何らかの順番(辞書順?)で評価され、先にマッチしたものが結果として出力されるようです。
どのフィールドでもマッチしなかった場合はマッチ失敗となるみたいです。
4. match
設定が複数
filter { grok { match => { "message" => "ho%{GREEDYDATA:hoge}e" } match => { "message" => "fu%{GREEDYDATA:fuga}a" } } }
match
に複数同名のフィールドがあるのは許容されませんでしたが、match
設定が複数あるのは許容されるようです。
$ echo 'hoge' >> /tmp/input.log $ echo 'fuga' >> /tmp/input.log $ echo 'hogefuga' >> /tmp/input.log $ echo 'piyo' >> /tmp/input.log $ tail -4 /tmp/output.log | jq { "hoge": "g", "@timestamp": "2020-12-09T16:04:32.119Z", "message": "hoge", "host": "localhost.localdomain", "@version": "1", "path": "/tmp/input.log" } { "@timestamp": "2020-12-09T16:04:32.155Z", "message": "fuga", "host": "localhost.localdomain", "fuga": "g", "@version": "1", "path": "/tmp/input.log" } { "hoge": "g", "@timestamp": "2020-12-09T16:04:53.224Z", "message": "hogefuga", "host": "localhost.localdomain", "@version": "1", "path": "/tmp/input.log" } { "@timestamp": "2020-12-09T16:05:03.234Z", "message": "piyo", "tags": [ "_grokparsefailure" ], "host": "localhost.localdomain", "@version": "1", "path": "/tmp/input.log" }
おそらく記述した順で上から評価され、最初にマッチしたものが結果として出力されるみたいです。どれにもマッチしなかった場合はマッチ失敗になるようです。
まとめ
ここまで書いておいてですが... こういう設定をしたらこうなったよ!という話であり、実際の所仕様がどうなっているのか(そもそも仕様で定義されてる挙動なのか)は不明です。 この設定が必要になることは...まあないと思いますが、もし使う場合は自己責任でお願いします。