Logstash: Pipeline stops processing events because of exception in filterworker "#<NoMethodError: undefined method `>' for nil:NilClass>"

[robinsmidsrod]

I'm getting this error in the logstash error log, and when it happens the pipeline stops processing events. The inputs are still able to receive events, but no events get through to the output stage.

{:timestamp=>"2014-08-14T08:09:19.415000+0000", :message=>"Exception in filterworker", "exception"=>#<NoMethodError: undefined method `>' for nil:NilClass>, "backtrace"=>["(eval):920:in `initialize'", "org/jruby/RubyProc.java:271:in `call'", "/opt/logstash/lib/logstash/pipeline.rb:262:in `filter'", "/opt/logstash/lib/logstash/pipeline.rb:203:in `filterworker'", "/opt/logstash/lib/logstash/pipeline.rb:143:in `start_filters'"], :level=>:error}

The error happens infrequently (about every other day or so), so I'm unsure what exactly is causing it.

I'm using the website DEB of logstash 1.4.2 on Ubuntu 14.04.

# java -version
java version "1.7.0_55"
OpenJDK Runtime Environment (IcedTea 2.4.7) (7u55-2.4.7-1ubuntu1)
OpenJDK 64-Bit Server VM (build 24.51-b03, mixed mode)

What other information do you need to debug this further?

[electrical]

Can you gist your config as well?

[robinsmidsrod]

@electrical: You can find my logstash.conf here: https://gist.github.com/robinsmidsrod/019ef6d415dbc3f9e0f1

[colinsurprenant]

@robinsmidsrod is this something you can reproduce with some sample input? the best for us would be to have a sample input and the minimal config that reproduces this. If you can't trim you config that's ok, the most helpful would be to get some input that can trigger this.

[robinsmidsrod]

@colinsurprenant Unfortunately, I'm unable to figure out what input data is causing it. Is there some way to dump the content from the inputs before they hit the filter, so that I can try to re-run the saved input data when I notice that the pipeline has stalled?

[jordansissel]

Based on the error, I believe it is dying within the filter conditionals. It dies because it tries, basically, 'x > y' but x is nil.

Reading your config, I see this line (https://gist.github.com/robinsmidsrod/019ef6d415dbc3f9e0f1#file-logstash-conf-L330):

if [request][time][now] > 0 {

This will give you the exception you reported if the field [request][time][now] is not present. We should make this better, but for now, you could check if the field is set before trying to compare it:

if [request][time][now] and [request][time][now] > 0 {

[jordansissel]

We should somehow improve the config parser here. I have two ideas:

First idea: Make left-hand-side field references in comparison operators always evaluate false.

• So if [no-such-field] > 100 always returns false. Same for any of the other operators <, ==, =~.
• Except for negative equality if [no-such-field] != somevalue and also !~ is always true.

Positive conditions (ones without negation) could automatically imply existence checks, in this way: [fieldref] < value could imply [fieldref] and [fieldref] < value. For negative comparisons, it could imply ![fieldref] or [fieldref] != value

Second idea: Make a config compilation error if the user attempts to do a comparison on a field reference and hasn't done an existence-check previously. I'm not really liking this one because it burdens users with more code and write-debug-fix steps.

[robinsmidsrod]

@jordansissel Thanks for the feedback. I've put your suggested workaround in and will report back if, for some reason, my pipeline is still stalling. I don't expect it to, though.

As for a long-term fix I think the first idea is probably the best one, as it will most likely cause less support issues with users. Although changing conditional logic might trigger some edge-case regressions.

Keep making a great piece of software. It's awesome!

[shihpeng]

It seems that LogStash stops processing events while some kind of exception occurs.

For example, the following config makes LogStash stops processing anything if it receives an empty JSON (i.e., {}):
https://gist.github.com/shihpeng/5ff66834f18b618285a9

The following is the error log from LogStash:

Exception in filterworker {"exception"=>#<TypeError: can't dup NilClass>, "backtrace"=>["org/jruby/RubyKernel.java:2064:in `dup'", "file:/Users/shihpeng/Downloads/logstash-1.4.2/vendor/jar/jruby-complete-1.7.11.jar!/META-INF/jruby.home/lib/ruby/1.9/date/format.rb:833:in `_parse'", "file:/Users/shihpeng/Downloads/logstash-1.4.2/vendor/jar/jruby-complete-1.7.11.jar!/META-INF/jruby.home/lib/ruby/1.9/date.rb:1823:in `parse'", "(ruby filter code):2:in `register'", "org/jruby/RubyProc.java:271:in `call'", "/Users/shihpeng/Downloads/logstash-1.4.2/lib/logstash/filters/ruby.rb:38:in `filter'", "(eval):40:in `initialize'", "org/jruby/RubyProc.java:271:in `call'", "/Users/shihpeng/Downloads/logstash-1.4.2/lib/logstash/pipeline.rb:262:in `filter'", "/Users/shihpeng/Downloads/logstash-1.4.2/lib/logstash/pipeline.rb:203:in `filterworker'", "/Users/shihpeng/Downloads/logstash-1.4.2/lib/logstash/pipeline.rb:143:in `start_filters'"], :level=>:error}

I think this is a serious issue since this makes LogStash cannot output anything anymore but the process is still resides in memory and the problem is hard to be detected.

[robinsmidsrod]

@shihpeng As far as I can see, that is not the same bug as mine. I think you should report it separately.

[tmortensen]

I ran into the same issue, I am glad to report the workaround solved my issue.
My filter sample is pretty short, It for sure is a result of testing an empty field.

http://pastebin.com/xy4r41rQ

[chenryn]

I got similar exceptions when I wrote some codes in filters/ruby. I know I should use conditions before my evnet['fieldname'].split() operation, but, only 0.01% lines don't have such fieldname exists, why we must jadge this every line?

I image whether logstash can has a mechanism to restart the died filterworker to force the number of filterworkers equal -w setting.

btw: we need so many date to determine why the worker die. So, force logstash to run right before we perfect our configuration maybe a good idea?

[derjohn]

Workaround?

ruby {
    # because if [somevar] doesnt work in all cases
    code => "if not defined? event['somevar']; event['somevar'] = 'dummyvalue' end"
}

[hmorgado]

Same thing happened to me and a simple verification if the field is not null solved the problem.
(logstash 1.4.2)

if [responsetime] {
        ruby {
        code => "event['responsetime'] = event['responsetime'] / 1000"
        }
}

This doesnt happen in logstash 1.5.3 which i've tested for myself.
So i suggest update and check if the field is not nil.

[suyograo]

We'll reopen this if it happens in 2.x

[sprysprocket]

This just happened to me in 2.2.1. The case is nearly identical to the original timestamp comparison case that kicked off this issue.

My configuration is pretty beefy, and would take a while to boil down. That said, I was able to reproduce easily by just adding the following to any ol' filter:

filter {
  if [bogusfield] < 100 {
    drop {}
  }
}

...which kills the logstash process. The logstash.err log shows the following:

NoMethodError: undefined method `<' for nil:NilClass
  cond_func_613 at (eval):11739
           each at org/jruby/RubyArray.java:1613
  cond_func_613 at (eval):11737
    filter_func at (eval):2024
   filter_batch at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.1-java/lib/logstash/pipeline.rb:256
           each at org/jruby/RubyArray.java:1613
         inject at org/jruby/RubyEnumerable.java:852
   filter_batch at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.1-java/lib/logstash/pipeline.rb:254
    worker_loop at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.1-java/lib/logstash/pipeline.rb:212
  start_workers at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.2.1-java/lib/logstash/pipeline.rb:190

Adding the null check eliminates the problem, but it does seem less than ideal that the entire process exits, rather than registering the error, and moving along.

[FlorianLiers]

Happened to me as well in version 2.3.0. That's very anoying and reduces the stability of the whole solution significantly. @suyograo: Can you please re-open this issue?

[ebuildy]

You should add an option on LogStash in order to catch filter exceptions, since these exceptions are based on input data that user cannot predict. (I am running the same very important issue with useragent filter, if useragent value is not a string, filter throws an exception then LogStash itself stops).

[andrewvc]

I'm reopening this issue since its still a problem in 2.x / 5.0, and yes, is serious and preventable.

[andrewvc]

My $0.02

1. We should catch filter exceptions and log them rather than crashing
2. The UX around these things is tricky. I think the most sensible thing is to convert [foo] > 0 to [foo] and [foo] > 0.

[ikoniaris]

Yup, adding a check for the actual field in your condition before the comparison should work as @andrewvc said above.