Grok terminating Logstash 5.0

Elastic Stack Logstash
1

Hi,
I'm upgrading from LS 2.2.2 to LS 5.0 and as part of the upgrade moved the multiline filter to the file input codec but the grok filter remained unchanged. The grok pattern worked fine with LS 2.2.2 however when running LS 5.0 it terminates with the FATAL below :

[2016-10-27T13:48:40,003][ERROR][logstash.filters.grok    ] Error while attempting to check/cancel excessively long grok patterns {:message=>"Mutex relocking by same thread", :class=>"ThreadError", :backtrace=>["org/jruby/ext/thread/Mutex.java:90:in `lock'", "org/jruby/ext/thread/Mutex.java:147:in `synchronize'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:38:in `stop_thread_groking'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:53:in `cancel_timed_out!'", "org/jruby/RubyHash.java:1342:in `each'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:45:in `cancel_timed_out!'", "org/jruby/ext/thread/Mutex.java:149:in `synchronize'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:44:in `cancel_timed_out!'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:63:in `start!'"]}
[2016-10-27T13:48:38,941][FATAL][logstash.runner          ] An unexpected error occurred! {:error=>#<InterruptedRegexpError: Regexp Interrupted>, :backtrace=>["org/jruby/RubyRegexp.java:1657:in `=~'", "org/jruby/RubyString.java:1729:in `=~'", "(eval):8618:in `initialize'", "org/jruby/RubyArray.java:1613:in `each'", "(eval):8616:in `initialize'", "org/jruby/RubyProc.java:281:in `call'", "(eval):2888:in `filter_func'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:260:in `filter_batch'", "org/jruby/RubyProc.java:281:in `call'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:186:in `each'", "org/jruby/RubyHash.java:1342:in `each'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:185:in `each'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:258:in `filter_batch'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:246:in `worker_loop'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:225:in `start_workers'"]}

The grok pattern itself is quite simple

        grok {
            match => { "message" => "%{OPENLINK_TIMESTAMP:openlink_timestamp}:%{OPENLINK_MODULE:openlink_module}: %{OPENLINK_LOGLEVEL:level} -%{OPENLINK_DESCRIPTION:openlink_description} >: %{OPENLINK_CODE:openlink_code} %{OPENLINK_MESSAGE:message}" }
            overwrite => ["message"]
        }

where the patterns are

OPENLINK_TIMESTAMP %{MONTHDAY} %{MONTH} %{YEAR} %{TIME}
OPENLINK_LOGLEVEL INFORMATION|ERROR|WARNING
OPENLINK_MODULE %{DATA}
OPENLINK_CODE OL:%{DATA}
OPENLINK_DESCRIPTION %{DATA}
OPENLINK_MESSAGE (?<message>(.|\r|\n)*)

Any thoughts on how I can resolve this?

Due to the length of the errors, I'll post additional error message details in a reply to this post.

Thanks,
Sanjiv

1 Like
2

Log message just prior to the message I posted in the initial post

[2016-10-27T13:48:38,855][WARN ][logstash.filters.grok    ] Grok regexp threw exception {:exception=>"interrupted waiting for mutex: null", :backtrace=>["org/jruby/ext/thread/Mutex.java:94:in `lock'", "org/jruby/ext/thread/Mutex.java:147:in `synchronize'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:38:in `stop_thread_groking'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:23:in `grok_till_timeout'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok/timeout_enforcer.rb:16:in `grok_till_timeout'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok.rb:333:in `match_against_groks'", "org/jruby/RubyArray.java:1613:in `each'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok.rb:330:in `match_against_groks'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok.rb:319:in `match'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok.rb:285:in `filter'", "org/jruby/RubyHash.java:1342:in `each'", "c:/java8/elk5/logstash-5.0.0/vendor/bundle/jruby/1.9/gems/logstash-filter-grok-3.2.3/lib/logstash/filters/grok.rb:284:in `filter'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/filters/base.rb:156:in `multi_filter'", "org/jruby/RubyArray.java:1613:in `each'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/filters/base.rb:153:in `multi_filter'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/filter_delegator.rb:41:in `multi_filter'", "(eval):8757:in `initialize'", "org/jruby/RubyArray.java:1613:in `each'", "(eval):8754:in `initialize'", "org/jruby/RubyProc.java:281:in `call'", "(eval):2889:in `filter_func'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:260:in `filter_batch'", "org/jruby/RubyProc.java:281:in `call'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:186:in `each'", "org/jruby/RubyHash.java:1342:in `each'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:185:in `each'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:258:in `filter_batch'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:246:in `worker_loop'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:225:in `start_workers'"], :class=>"ConcurrencyError"}
[2016-10-27T13:48:38,860][ERROR][logstash.pipeline        ] Exception in pipelineworker, the pipeline stopped processing new events, please check your filter configuration and restart Logstash. {"exception"=>#<InterruptedRegexpError: Regexp Interrupted>, "backtrace"=>["org/jruby/RubyRegexp.java:1657:in `=~'", "org/jruby/RubyString.java:1729:in `=~'", "(eval):8618:in `initialize'", "org/jruby/RubyArray.java:1613:in `each'", "(eval):8616:in `initialize'", "org/jruby/RubyProc.java:281:in `call'", "(eval):2888:in `filter_func'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:260:in `filter_batch'", "org/jruby/RubyProc.java:281:in `call'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:186:in `each'", "org/jruby/RubyHash.java:1342:in `each'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:185:in `each'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:258:in `filter_batch'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:246:in `worker_loop'", "c:/java8/elk5/logstash-5.0.0/logstash-core/lib/logstash/pipeline.rb:225:in `start_workers'"]}
3

This has been logged as a bug https://github.com/logstash-plugins/logstash-filter-grok/issues/97

4

So I still receive this error and the github you linked to doesn't explain how to get rid of it even though it's closed. How do I deal with the error message of having "excessively long grok patterns"? I cant seem to get it to go away although I am only getting that error message and not the rest you have posted...

5

I am working a build off the 5.x branch where the fixes were committed and I no longer have this issue. Doing a full build off the logstash branch pulls in the fixes the the various bundled plugins too and I found it much easier to do than trying to build and install individual plugins that had the fixes I was looking for.