Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Interrupts during Mutex locks not caught #97

Closed
andrewvc opened this issue Nov 1, 2016 · 3 comments
Closed

Interrupts during Mutex locks not caught #97

andrewvc opened this issue Nov 1, 2016 · 3 comments
Assignees
@andrewvc
Labels
bug P2

Comments

@andrewvc
Copy link
Contributor

andrewvc commented Nov 1, 2016

From https://discuss.elastic.co/t/grok-terminating-logstash-5-0/64307 and #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 andrewvc self-assigned this Nov 1, 2016
@andrewvc andrewvc mentioned this issue Nov 1, 2016
Closed
@andrewvc
Copy link
Contributor Author

andrewvc commented Nov 1, 2016

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
Copy link
Contributor Author

andrewvc commented Nov 1, 2016

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.

andrewvc added a commit to andrewvc/logstash-filter-grok that referenced this issue Nov 1, 2016
@andrewvc
Fix Uncaught Mutex Interrupt Exceptions
82a75e9 
The TimeoutEnforcer used ruby's Mutex class which is interruptible
and throws a special exception. This switches the code to use
ReentrantLock (which JRuby's Mutex is based on) directly, and use
ReentrantLock.lock instead of ReentrantLock.lockInterruptibly

This also adds a small note about the placement of thread.interrupted.

Fixes logstash-plugins#97
@andrewvc andrewvc mentioned this issue Nov 1, 2016
Closed
@sjivan
Copy link

sjivan commented Nov 2, 2016 •
edited
Loading

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@andrewvc andrewvc

Labels
bug P2
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@andrewvc @sjivan