Logstash: NumberFormatException thrown from if statement after a split

[alcanzar]

Verified against 5.1.1 on Macos:

Config file:

input {
    stdin { codec => "json" }
}
filter {
    split { field => "events" }
    if ([events] == "" or [events][Code] == "") { 
        drop {} 
    }
}  
output {
    stdout { codec => "rubydebug" }
}

Command line:

echo '{"key1":"value1","key2":"value2","events":[{"Level":"Information","Code":"100"},{"Level":"Information","SomeKey":"SomeValue"},{"Level":"Error","Message":"Something went wrong"}]}' | bin/logstash -f test.conf

Result:

Exception in thread "[main]>worker7" java.lang.NumberFormatException: For input string: "Code"
    at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
    at java.lang.Integer.parseInt(Integer.java:580)
    at java.lang.Integer.parseInt(Integer.java:615)
    at org.logstash.Accessors.fetch(Accessors.java:130)
    at org.logstash.Accessors.get(Accessors.java:20)
    at org.logstash.Event.getUnconvertedField(Event.java:160)
    at org.logstash.ext.JrubyEventExtLibrary$RubyEvent.ruby_get_field(JrubyEventExtLibrary.java:113)
    at org.logstash.ext.JrubyEventExtLibrary$RubyEvent$INVOKER$i$1$0$ruby_get_field.call(JrubyEventExtLibrary$RubyEvent$INVOKER$i$1$0$ruby_get_field.gen)

It seems that it thinks that events is an array and it's trying to index it by "Code"

[guptaabhinav206]

Can I work on this issue ?

[untergeek]

@guptaabhinav206 Sure! We accept PRs. Please include RSpec tests to ensure code changes work as expected.

[guptaabhinav206]

Thanks. It would be very helpful for me if you could get me started as this being my first bug on Elastic Logstash. How to reproduce this bug or if I can contact you on your email id.

[wainersm]

It needs to double check but I believe the PR #6883 already solve this bug too. The fix merged handles the NumberFormatException in Acessors class.

[guyboertje]

@alcanzar, @wainersm, @guptaabhinav206

This is a bug in way the split filter is generating the new events. The bug is not in the split filter itself, but rather in the way that logstash calls it.

[guyboertje]

@alcanzar, @wainersm, @guptaabhinav206

I found the bug. Unfortunately I am not exactly sure what the correct fix is. I am sure it will be debated by the rest of the Logstash team.

define_singleton_method :filter_func do |event|
  events = [event]
  @logger.debug? && @logger.debug("filter received", "event" => event.to_hash)
  events = @generated_objects[:filter_split_2].multi_filter(events)
  events = @generated_objects[:cond_func_2].call(events)
  events = @generated_objects[:filter_date_4].multi_filter(events)

  events
end
# ...
@generated_objects[:cond_func_2] = lambda do |input_events|
  result = []
  input_events.each do |event|
    events = [event]
    # if ([records] == "" or [records][last] == "")
    if ((((event.get("[records]") == ("")) or (event.get("[records][last]") == ("")))))
      events = @generated_objects[:filter_drop_3].multi_filter(events)
    end
    result += events
  end
  result
end

Logstash generates the above bit of ruby code when it compiles this config.

filter {
    split {
        field => "records"
    }
    if ([records] == "" or [records][last] == "") {
      drop {}
    }
    date {
        locale => "en"
        match => ["[records][last]", "ISO8601"]
        target => "@timestamp"
    }
}

event data

{"records": [{"last":"2017-03-02T20:41:13"}]}

The bug is that the cancelled event from the split filter is still being passed into the cond_func_2 and the filter_date_4 generated objects but the user is not expecting the cancelled object shape.

Remedy: I suggest modifying the config_ast to reject cancelled events when returning events from a generated_objects[].multi_filter call (Line 201).

define_singleton_method :filter_func do |event|
  events = [event]
  @logger.debug? && @logger.debug("filter received", "event" => event.to_hash)
  events = @generated_objects[:filter_split_2].multi_filter(events).reject(&:cancelled?)
  events = @generated_objects[:cond_func_2].call(events)
  events = @generated_objects[:filter_date_4].multi_filter(events).reject(&:cancelled?)

  events
end

[guyboertje]

NOTE: the PR from @wainersm #6883 does fix the if condition expecting a different shape.

[andrewvc]

@guyboertje I agree that we should iterate through the events and remove all cancelled events in the generated pipeline code.

[colinsurprenant]

but the generated object already iterate through the events so wouldn't be more efficient to ignore/reject cancelled events at this point instead of adding a .reject(&:cancelled?) after the multi_filter(events) ?
Or even in the filter_delegator multi_filter we already check for the cancelled? events for metrics, they could also be discarded there?

[guyboertje]

NOTE: The bug as described above applies when the the PR is removed. That is, the PR indirectly fixes the bug in for the above config but without addressing the cancelled events it still means that cancelled events are processed unnecessarily and may manifest itself in other ways.

[guyboertje]

@colinsurprenant - the conditional does not use the filter delegator so skipping cancelled events in the filter_delegator will not cover the conditionals. 2 pence.

[andrewvc]

@colinsurprenant anything we can do to minimize iteration is good! I just meant we should do that conceptually. It sounds like you've found better spots to do that :)

[guyboertje]

The graph execution should fix this properly.

[guyboertje]

I have no preference on where we exclude the cancelled events. I merely verified that my suggestion works without PR #6883 :-)

[colinsurprenant]

@guyboertje I meant that the filter delegator should reject the event since it already iterate over the events and also check the cancelled? state so it shouldn't have any perf impact to do it there instead of adding and extra iteration lower down.

[colinsurprenant]

ok, so lets first find a way to reproduce the problem with PR #6883 applied and then spec it and fix it, probably in multi_filter by trying to avoid a new iteration.

[colinsurprenant]

I cannot reproduce the cancellation hypothesis. I used:

input { stdin {} }
filter {
    if ([message] == "drop") {
      mutate {
        add_tag => ["cancelled"]
      }
      drop {}
    }
    mutate {
      add_tag => ["not_cancelled"]
    }
    if ([message] == "drop") {
      mutate {
        add_tag => ["cancel_failed"]
      }
    }

    ruby { code => "@logger.error(event.to_hash.inspect)" }
}
output { stdout { codec => rubydebug }}

and then tested with

bin/logstash -f tmp/cancel.conf
ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.
Sending Logstash's logs to /Users/colin/dev/src/elasticsearch/logstash/logs which is now configured via log4j2.properties
/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/compiler/lscl.rb:557 warning: `eval' should not be aliased
[2017-04-18T18:12:57,374][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
[2017-04-18T18:12:58,824][INFO ][logstash.pipeline        ] Starting pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x159c4da5 run>", "pipeline.workers"=>4, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>5, "pipeline.max_inflight"=>500}
[2017-04-18T18:12:58,845][INFO ][logstash.pipeline        ] Pipeline started {:pipeline_id=>"main", :thread=>"#<Thread:0x159c4da5 run>"}
The stdin plugin is now waiting for input:
[2017-04-18T18:12:58,869][INFO ][logstash.agent           ] Pipelines running {:count=>1, :pipelines=>["main"]}


drop
test
[2017-04-18T18:13:02,485][ERROR][logstash.filters.ruby    ] {"@timestamp"=>2017-04-19T00:13:02.475Z, "@version"=>"1", "host"=>"colin-mbp13r-2.local", "message"=>"test", "tags"=>["not_cancelled"]}
{
    "@timestamp" => 2017-04-19T00:13:02.475Z,
      "@version" => "1",
          "host" => "colin-mbp13r-2.local",
       "message" => "test",
          "tags" => [
        [0] "not_cancelled"
    ]
}
drop

Unless I am missing something, it seems the cancelled events (when typing "drop") are not being passed down to conditionals or filters.

[guyboertje]

@colinsurprenant
The implementation of multi_filter in filters base excludes cancelled events

  def multi_filter(events)
    LogStash::Util.set_thread_plugin(self)
    result = []
    events.each do |event|
      unless event.cancelled?
        result << event
        do_filter(event){|new_event| result << new_event}
      end
    end
    result
  end

However some plugins like the date filter have overridden the base method and they may or may not exclude cancelled events.
My question is more about whether cancelled events should be excluded before a plugin receives a list of events. The batch object is designed to specifically exclude cancelled events from its iterator meaning that plugins should only have to deal with cancelling an event if they choose.

We must deal with this properly in the Java plugin API.

[colinsurprenant]

@guy thanks, right. ok, then I guess in this issue context this is a specific date filter problem. Filters overriding multi_filter need to preserve that cancellation behaviour and we should verify this is the case until we move forward with the batch object.

[colinsurprenant]

To recap:

The problem is that the date filter overrides the base multi_filter method but does not follow the same logic that the base multi_filter method by rejecting cancelled event.

The date filter must be fixed.

[jordansissel]

@colinsurprenant I look at the code you linked and I wonder .. should it really be the responsibility of the plugin author to skip cancelled events? Can we instead provide the 'events' that already excludes cancelled ones?

[jordansissel]

I was abrupt in my response. We can (and should) fix the Date filter first to align with the current API expectations. We can fix the plugin api to omit cancelled events later if we decide to do that.

[colinsurprenant]

@jordansissel agree. first fix now with current design and limitations and as discussed this will be refactored and the batch object will/should probably take care of this.
It is normally hidden from the plugin author because this happens in the base class method and it was never really intended to be overridden without making sure its original behaviour was respected.

[colinsurprenant]

@jsvd already opened an issue about this some time ago in the date filter repo: logstash-plugins/logstash-filter-date/issues/90

[colinsurprenant]

the date filter has been fixed and is published as v3.1.5

[colinsurprenant]

I believe this issue can now be closed.