_grokparsefailure Tag in all parsed logs with multiple grok filter

I am trying to parse minecraft log with Elastic Stack and I'v faced a very strange problem (likely strange for me!)

all line of my log get parsed correctly but I got _grokparsefailure tag in everyone of them.

my logstash pipeline config is this:

input {
  file {
    path => [ "/path/to/my/log" ]
    #start_position => "beginning"
    tags => ["minecraft"]
  }
}

filter {
  if "minecraft" in [tags] {

#    mutate {
#      gsub => [
#        "message", "\\n", ""
#      ]
#    }



    #############################
    #           Num 1           #
    #############################
    grok {
      match => [ "message", "\[%{TIME:timestamp}] \[(?<originator>[^\/]+)?/%{LOGLEVEL:level}]: %{GREEDYDATA:message}" ]
      overwrite => [ "message" ]
      break_on_match => false
    }


    #############################
    #           Num 2           #
    #############################
    grok {
      match => [ "message", "UUID of player %{USERNAME} is %{UUID}" ]
      add_tag => [ "player", "uuid" ]
      break_on_match => true
    }


    #############################
    #           Num 3           #
    #############################
    grok {
      match => [ "message",  "\A(?<player>[a-zA-Z0-9_]+)\[/%{IPV4:ip_address}:%{POSINT}\] logged in with entity id %{POSINT:entity_id} at \(\[(?<world>[a-zA-Z]+)\](?<pos>[^\)]+)\)\Z" ]
      add_tag => [ "player", "join" ]
      break_on_match => true
    }
#
#    grok {
#      match => [ "message",  "^(?<player>[a-zA-Z0-9_]+) has just earned the achievement \[(?<achievement>[^\[]+)\]$" ]
#      add_tag => [ "player", "achievement" ]
#    }
#
#    grok {
#      match => [ "message", "^(?<player>[a-zA-Z0-9_]+) left the game$" ]
#      add_tag => [ "player", "part" ]
#    }
#
#    grok {
#      match => [ "message", "^<(?<player>[a-zA-Z0-9_]+)> .*$" ]
#      add_tag => [ "player", "chat" ]
#    }
  }
}

output {
        elasticsearch {
                hosts => ["elasticsearch:xxxx"]
                user => "xxxx"
                password => "xxxxxx"
        index => "minecraft_s1v15_%{+YYYY.MM.dd}"
        }
}

AND A SAMPLE OF MY LOG IS:

[11:21:46] [User Authenticator #7/INFO]: UUID of player MyAwsomeUsername is d800b63e-c2d2-3140-83a7-32315d09feca
[11:21:46] [Server thread/INFO]: MyAwsomeUsername joined the game
[11:21:46] [Server thread/INFO]: MyAwsomeUsername[/111.111.111.111:45140] logged in with entity id 6868 at ([world]61.45686149445207, 70.9375, -175.44700729217607)
[11:21:49] [Server thread/INFO]: MyAwsomeUsername issued server command: //efererg
[11:21:52] [Async Chat Thread - #1/INFO]: <MyAwsomeUsername> egerg
[11:21:54] [Async Chat Thread - #1/INFO]: <MyAwsomeUsername> ef
[12:00:19] [Server thread/INFO]: MyAwsomeUsername lost connection: Disconnected
[12:00:19] [Server thread/INFO]: MyAwsomeUsername left the game
[12:00:21] [User Authenticator #8/INFO]: UUID of player MyAwsomeUsername is d800b63e-c2d2-3140-83a7-32315d09feca
[12:00:21] [Server thread/INFO]: MyAwsomeUsername joined the game
[12:00:21] [Server thread/INFO]: MyAwsomeUsername[/111.111.111.111:45470] logged in with entity id 11767 at ([world]61.45686149445207, 70.9375, -175.44700729217607)
[12:00:27] [Server thread/INFO]: MyAwsomeUsername issued server command: /wgergerger
[12:00:29] [Async Chat Thread - #2/INFO]: <MyAwsomeUsername> gerg
[12:00:33] [Async Chat Thread - #2/INFO]: <MyAwsomeUsername> gerger
[12:00:35] [Async Chat Thread - #2/INFO]: <MyAwsomeUsername> rerg
[12:00:37] [Server thread/INFO]: MyAwsomeUsername lost connection: Disconnected
[12:00:37] [Server thread/INFO]: MyAwsomeUsername left the game
[12:00:38] [User Authenticator #8/INFO]: UUID of player MyAwsomeUsername is d800b63e-c2d2-3140-83a7-32315d09feca
[12:00:38] [Server thread/INFO]: MyAwsomeUsername joined the game
[12:00:38] [Server thread/INFO]: MyAwsomeUsername[/111.111.111.111:45476] logged in with entity id 11793 at ([world]62.97573252632079, 71.0, -179.01739415148737)
[12:00:40] [Server thread/INFO]: MyAwsomeUsername lost connection: Disconnected
[12:00:40] [Server thread/INFO]: MyAwsomeUsername left the game
[12:00:51] [User Authenticator #8/INFO]: UUID of player MyAwsomeUsername is d800b63e-c2d2-3140-83a7-32315d09feca
[12:00:51] [Server thread/INFO]: MyAwsomeUsername joined the game
[12:00:51] [Server thread/INFO]: MyAwsomeUsername[/111.111.111.111:45486] logged in with entity id 11805 at ([world]62.97573252632079, 71.0, -179.01739415148737)
[12:00:55] [Server thread/INFO]: MyAwsomeUsername lost connection: Disconnected
[12:00:55] [Server thread/INFO]: MyAwsomeUsername left the game


Explanation:

I commented other grok to explain the problem simpler (Exact same problem when uncommnet them)

I'v tested 3 situation:

  1. Comment 2 and 3 as well as others and only 1 was active, in this case every line of log got parsed without any _grokparsefailure in the record.
  2. Only was commented as well as others and 1 and 2 were active. in this case the line of log with match the grok number 2 was parsed with no _grokparsefailure and others get _grokparsefailure. this is still make sense!
  3. In last situation I uncommented all 3 grok (1, 2, 3 were active) and every line of log get parsed BUT with _grokparsefailure in it! even though the break_on_match is true by default and when it match by grok 2 it shouldn't be tested with grok 3.

I've read some other question similar to me in stackoverflow: Similar Question 1 and I added the mutate block before the grok filters (cause every line of the log end with \n) but nothing changed and the problem persist!

other thing I think I need to mention is the fact that I know adding more grok beside grok 2 (3 and others) cause this tag cause some of the logs don't match grok 2 at all and have to wrap them with a regex. but for now at lease the logs that match grok 2 should be Ok (no _grokparsefailure) but they are not! (Read it in a stackoverflow question: Similar Question 2

If you have multiple grok filters then each one will process the message and add a _grokparsefailure if the pattern does not match. That means a message has to match every single pattern to avoid getting tagged.

it does not make sense to me :slightly_frowning_face:
the first grok match a line of log and override this message so it couldn't be process all together. there must be some order.
and if they parse one by one in an order that I don't know so what is the use of break_on_match => true/false if the line of log checked by all of them!
can u explain it a bit more to me or give me an article or something like that to read?
want to know about order if exist ...

break_on_match is used when you pass an array of patterns to a single grok filter. See here for an example where the same message is matched against multiple patterns to pick out different parts of it.

Aha
there is no order to multiple grok?
if there is no order so how first grok override message and others use the overridden message?

If there are multiple filters they are executed in order and independently.

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.