Dissector mapping, field found in event but it was empty (reopening #46)

[gyoetam]

Issue #46 was supposed to be fixed in dissect 1.1.3, which is shipped with LS 6.2.0, however, the issue still persists.

• Version: LS 6.2.0, dissect 1.1.3
• Operating System: docker image version
• Config File, Sample Data, Steps to Reproduce:

  user@host ~> echo -e 'one good line\none bád líne' | docker run --rm -i docker.elastic.co/logstash/logstash:6.2.0 -f '' -e 'input { stdin { } }
                  filter { dissect { mapping => { "message" => "%{a} %{b} %{c}" } } }
                  output { stdout { codec => rubydebug } }'

  Output:

  [2018-02-07T10:24:11,485][WARN ][org.logstash.dissect.Dissector] Dissector mapping, field found in event but it was empty {"field"=>"message", "event"=>{"message"=>"one bád líne", "@version"=>"1", "@timestamp"=>2018-02-07T10:24:11.344Z, "a"=>"one", "c"=>"líne", "b"=>"bád", "host"=>"183794f6cf83"}}
  {
     "message" => "one good line",
    "@version" => "1",
  "@timestamp" => 2018-02-07T10:24:11.299Z,
           "a" => "one",
           "c" => "line",
           "b" => "good",
        "host" => "183794f6cf83"
  }
  {
     "message" => "one bád líne",
        "tags" => [
      [0] "_dissectfailure"
  ],
    "@version" => "1",
  "@timestamp" => 2018-02-07T10:24:11.344Z,
           "a" => "one",
           "c" => "líne",
           "b" => "bád",
        "host" => "183794f6cf83"
  }

[guyboertje]

This bug does not affect the building of an event. The bug is that the **WARN*** log message is misleading/useless - it is logged when the byte position reached by the Dissector is less than the byte length of the original string. This is of no use to the user. I will investigate why the two counts don't tally but all the tests indicate that Dissect is working satisfactorily.

[marnikvde]

But the fact that it gets tagged as failure is annoying, since it's impossible to disinguish it from other possible failures.

[marnikvde]

Actually, there's another side effect. This is my config:

dissect { mapping => { "foo" => "%{a} %{b}" } add_field => [ "bar", "bleh" ] }

The field "bar" is not in my result, so I'm guessing that the failure stopped the execution somewhere. So although all the dissect fields are OK, the pipeline seems to be broken.

[marnikvde]

Confirmed: echo -e 'one good line\none bád líne' | docker run --rm -i docker.elastic.co/logstash/logstash:6.2.0 -f '' -e 'input { stdin { } } filter { dissect { mapping => { "message" => "%{a} %{b} %{c}" } add_field => [ "bar", "bleh" ] } } output { stdout { codec => rubydebug } }'

result:

[2018-02-13T21:42:50,280][WARN ][org.logstash.dissect.Dissector] Dissector mapping, field found in event but it was empty {"field"=>"message", "event"=>{"b"=>"bád", "c"=>"líne", "a"=>"one", "message"=>"one bád líne", "host"=>"17d01f283198", "@timestamp"=>2018-02-13T21:42:50.166Z, "@version"=>"1"}}
{
             "b" => "good",
             "c" => "line",
           "bar" => "bleh",
             "a" => "one",
       "message" => "one good line",
          "host" => "17d01f283198",
    "@timestamp" => 2018-02-13T21:42:50.135Z,
      "@version" => "1"
}
{
             "b" => "bád",
             "c" => "líne",
             "a" => "one",
       "message" => "one bád líne",
          "host" => "17d01f283198",
    "@timestamp" => 2018-02-13T21:42:50.166Z,
          "tags" => [
        [0] "_dissectfailure"
    ],
      "@version" => "1"
}

Notice the missing bar field on dissect failure.

Bleh, moved a lot of config from grok to dissect because of speed, but I guess I'll have to move back until this is fixed.

[guyboertje]

Fixing now

[guyboertje]

The plugin is published with the wrong Java build jar. The 1.1.3 plugin version is using the jar from v 1.1.1. 😞 I will have to publish v1.1.4.

[guyboertje]

Solved.

@gyoetam @marnikvde

Please remove 1.1.3 and install v 1.1.4 - report back or close.

bin/logstash-plugin remove logstash-filter-dissect
bin/logstash-plugin install --version 1.1.4 logstash-filter-dissect

After doing the above, I can confirm this test config now works :

input {
  generator {
    lines => [
      "one good line",
      "one bád líne"
    ]
    count => 1
  }
}

filter {
  dissect {
    mapping => {
      message => "%{a} %{b} %{c}"
    }
    add_field => {"d" => "yayyyy"}
  }
}

output {
  stdout {
    codec => rubydebug
  }
}

Results:

{
    "@timestamp" => 2018-02-15T15:55:42.955Z,
          "host" => "Elastics-MacBook-Pro.local",
             "b" => "bád",
      "sequence" => 0,
             "d" => "yayyyy",
             "a" => "one",
             "c" => "líne",
       "message" => "one bád líne",
      "@version" => "1"
}
{
    "@timestamp" => 2018-02-15T15:55:42.922Z,
          "host" => "Elastics-MacBook-Pro.local",
             "b" => "good",
      "sequence" => 0,
             "d" => "yayyyy",
             "a" => "one",
             "c" => "line",
       "message" => "one good line",
      "@version" => "1"
}

[gyoetam]

@guyboertje After upgrading to 1.1.4, it worked for me too in LS 6.2.0. Thanks for the fix!

[guyboertje]

Closing