記憶力が無い

プログラミングとランニングとカメラと何か

Logstash の Grok フィルターの細かい挙動を調べた

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 を使ってログの値を hogefuga のフィールドに複製しておきます。

$ 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"
}

おそらく記述した順で上から評価され、最初にマッチしたものが結果として出力されるみたいです。どれにもマッチしなかった場合はマッチ失敗になるようです。

まとめ

ここまで書いておいてですが... こういう設定をしたらこうなったよ!という話であり、実際の所仕様がどうなっているのか(そもそも仕様で定義されてる挙動なのか)は不明です。 この設定が必要になることは...まあないと思いますが、もし使う場合は自己責任でお願いします。

Copyright © 2017 ttk1