search

logstash-plugins / logstash-filter-grok

Grok plugin to parse unstructured (log) data into something structured.
https://www.elastic.co/guide/en/logstash/current/plugins-filters-grok.html
Apache License 2.0
122 stars 97 forks source link

Interrupts during Mutex locks not caught #97

Closed andrewvc closed 7 years ago

andrewvc commented 7 years ago

From https://discuss.elastic.co/t/grok-terminating-logstash-5-0/64307 and https://github.com/logstash-plugins/logstash-filter-grok/issues/95

This error:

[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'"]}

Cleaned up stack trace:

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
andrewvc commented 7 years ago

To add to this, the second error in the log looks to be from not clearing the interrupted flag on the thread, causing the next =~ usage in the pipeline to fail.

andrewvc commented 7 years ago

Actually, looking at Mutex.java it looks like the interrupted status should have cleared. However, the exception would have prevented the TimeoutEnforcer from knowing that the thread had been interrupted and that would have caused it to interrupt the thread again.

sjivan commented 7 years ago

Thanks so much for the quick turnaround! I'll try picking up the patch and give it a whirl. Due to our intranet setup installing new plugins from git has been painful due to SSL certificate errors. Hopefully it gets rolled into the next LS release.

I can confirm my mapping file had multiple =~ checks