"org.jruby.runtime.scopes.DynamicScope1 only supports scopes with 1 variables" with Deeply Nested Blocks #4739
Description
EDIT:
I was able to create a non-Logstash reproducer by creating a somewhat arbitrary set of classes with a bunch of blocks and multi-threading.
See reproduced error here:
https://github.com/original-brownbear/jruby-jit-issue-reproducer#jit-dynamicscope-size-error (code is in that repo, link points at the error reproduced (top of the readme contains a second error that I reproduced using this code, it seems we're randomly going into an endless loop here, but I haven't 100% verified that it's not just stupidity on my end introducing recursion of some kind) the the command used to trigger it )
In JRuby 9.1.12.0 we can still reproduce #4516 with the latest Logstash versions in a case of many nested blocks and a number of threads likely trying to JIT them at the same time.
The exception I see is:
{ :exception => "org.jruby.runtime.scopes.DynamicScope1 only supports scopes with 1 variables",
:backtrace => [
"org.jruby.runtime.scopes.DynamicScope1.sizeError(Unknown Source)",
"org.jruby.runtime.scopes.DynamicScope1.getValueDepthZero(Unknown Source)",
"org.jruby.runtime.DynamicScope.getValueDepthZeroOrNil(DynamicScope.java:257)",
"org.jruby.runtime.DynamicScope.getValueOrNil(DynamicScope.java:249)",
"org.jruby.runtime.DynamicScope.getValueOrNil(DynamicScope.java:247)",
"Users.brownbear.src.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_grok_minus_3_dot_4_dot_2.lib.logstash.filters.grok.RUBY$block$match_against_groks$1(/Users/brownbear/src/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-3.4.2/lib/logstash/filters/grok.rb:348)",
"org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)",
"org.jruby.runtime.IRBlockBody.yieldSpecific(IRBlockBody.java:80)",
"org.jruby.runtime.Block.yieldSpecific(Block.java:134)",
"org.jruby.ir.runtime.IRRuntimeHelpers.yieldSpecific(IRRuntimeHelpers.java:419)",
"org.jruby.ir.targets.YieldSite.yieldSpecific(YieldSite.java:114)",
"Users.brownbear.src.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_grok_minus_3_dot_4_dot_2.lib.logstash.filters.grok.timeout_enforcer.RUBY$method$grok_till_timeout$0(/Users/brownbear/src/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-3.4.2/lib/logstash/filters/grok/timeout_enforcer.rb:21)", "Users.brownbear.src.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_grok_minus_3_dot_4_dot_2.lib.logstash.filters.grok.RUBY$block$match_against_groks$1(/Users/brownbear/src/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-3.4.2/lib/logstash/filters/grok.rb:348)", "org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)", "org.jruby.runtime.BlockBody.yield(BlockBody.java:114)", "org.jruby.runtime.Block.yield(Block.java:165)", "org.jruby.RubyArray.each(RubyArray.java:1734)", "Users.brownbear.src.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_grok_minus_3_dot_4_dot_2.lib.logstash.filters.grok.RUBY$method$match_against_groks$0(/Users/brownbear/src/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-3.4.2/lib/logstash/filters/grok.rb:345)", "Users.brownbear.src.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_grok_minus_3_dot_4_dot_2.lib.logstash.filters.grok.RUBY$method$match$0(/Users/brownbear/src/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-3.4.2/lib/logstash/filters/grok.rb:334)", "Users.brownbear.src.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_grok_minus_3_dot_4_dot_2.lib.logstash.filters.grok.RUBY$block$filter$1(/Users/brownbear/src/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-3.4.2/lib/logstash/filters/grok.rb:300)", "org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)", "org.jruby.runtime.BlockBody.yield(BlockBody.java:114)", "org.jruby.runtime.Block.yield(Block.java:165)", "org.jruby.RubyHash$12.visit(RubyHash.java:1362)", "org.jruby.RubyHash$12.visit(RubyHash.java:1359)", "org.jruby.RubyHash.visitLimited(RubyHash.java:662)", "org.jruby.RubyHash.visitAll(RubyHash.java:647)", "org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1319)", "org.jruby.RubyHash.each_pairCommon(RubyHash.java:1354)", "org.jruby.RubyHash.each(RubyHash.java:1343)", "Users.brownbear.src.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.logstash_minus_filter_minus_grok_minus_3_dot_4_dot_2.lib.logstash.filters.grok.RUBY$method$filter$0(/Users/brownbear/src/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-filter-grok-3.4.2/lib/logstash/filters/grok.rb:299)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.filters.base.RUBY$method$do_filter$0(/Users/brownbear/src/logstash/logstash-core/lib/logstash/filters/base.rb:145)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.filters.base.RUBY$block$multi_filter$1(/Users/brownbear/src/logstash/logstash-core/lib/logstash/filters/base.rb:164)",
"org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)",
"org.jruby.runtime.BlockBody.yield(BlockBody.java:114)",
"org.jruby.runtime.Block.yield(Block.java:165)",
"org.jruby.RubyArray.each(RubyArray.java:1734)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.filters.base.RUBY$method$multi_filter$0(/Users/brownbear/src/logstash/logstash-core/lib/logstash/filters/base.rb:161)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.filter_delegator.RUBY$method$multi_filter$0(/Users/brownbear/src/logstash/logstash-core/lib/logstash/filter_delegator.rb:48)",
"org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:103)",
"org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:163)",
"org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:200)",
"org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:161)",
"org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:314)",
"org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:73)",
"org.jruby.ir.interpreter.Interpreter.INTERPRET_BLOCK(Interpreter.java:132)",
"org.jruby.runtime.MixedModeIRBlockBody.commonYieldPath(MixedModeIRBlockBody.java:148)",
"org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:73)",
"org.jruby.runtime.Block.call(Block.java:124)",
"org.jruby.RubyProc.call(RubyProc.java:289)",
"org.jruby.internal.runtime.methods.ProcMethod.call(ProcMethod.java:63)",
"org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:204)",
"org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:200)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$block$filter_batch$1(/Users/brownbear/src/logstash/logstash-core/lib/logstash/pipeline.rb:499)",
"org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)",
"org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)",
"org.jruby.runtime.Block.call(Block.java:124)",
"org.jruby.RubyProc.call(RubyProc.java:289)",
"org.jruby.RubyProc.call19(RubyProc.java:273)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.util.wrapped_synchronous_queue.RUBY$block$each$1(/Users/brownbear/src/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:227)",
"org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)",
"org.jruby.runtime.BlockBody.yield(BlockBody.java:114)",
"org.jruby.runtime.Block.yield(Block.java:165)",
"org.jruby.javasupport.ext.JavaLang$Iterable.each(JavaLang.java:93)",
"org.jruby.javasupport.ext.JavaUtil$Collection.each(JavaUtil.java:133)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.util.wrapped_synchronous_queue.RUBY$method$each$0(/Users/brownbear/src/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:226)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$filter_batch$0(/Users/brownbear/src/logstash/logstash-core/lib/logstash/pipeline.rb:498)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$worker_loop$0(/Users/brownbear/src/logstash/logstash-core/lib/logstash/pipeline.rb:477)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$method$worker_loop$0$__VARARGS__(/Users/brownbear/src/logstash/logstash-core/lib/logstash/pipeline.rb)",
"org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)",
"org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)",
"org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)",
"Users.brownbear.src.logstash.logstash_minus_core.lib.logstash.pipeline.RUBY$block$start_workers$2(/Users/brownbear/src/logstash/logstash-core/lib/logstash/pipeline.rb:437)",
"org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)",
"org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)",
"org.jruby.runtime.Block.call(Block.java:124)",
"org.jruby.RubyProc.call(RubyProc.java:289)",
"org.jruby.RubyProc.call(RubyProc.java:246)",
"org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:104)",
"java.lang.Thread.run(Thread.java:748)"
], :class => "Java::JavaLang::RuntimeException"
}the last few steps here are:
def match_against_groks(groks, field, input, event)
input = input.to_s
matched = false
groks.each do |grok|
# Convert anything else to string (number, hash, etc)
matched = @timeout_enforcer.grok_till_timeout(event, grok, field, input) { grok.execute(input) }
if matched
grok.capture(matched) {|field, value| handle(field, value, event)}
break if @break_on_match
end
end
matched
endusing:
def start_thread_groking(thread)
# Clear any interrupts from any previous invocations that were not caught by Joni
thread.interrupted
synchronize do
@threads_to_start_time[thread] = java.lang.System.nanoTime()
end
end def synchronize
# The JRuby Mutex uses lockInterruptibly which is what we DO NOT want
@state_lock.lock
yield
ensure
@state_lock.unlock
end def grok_till_timeout(event, grok, field, value)
begin
thread = java.lang.Thread.currentThread()
start_thread_groking(thread)
yield
rescue InterruptedRegexpError => e
raise ::LogStash::Filters::Grok::TimeoutException.new(grok, field, value)
ensure
stop_thread_groking(thread)
# Clear any interrupts from any previous invocations that were not caught by Joni
# It may appear that this should go in #stop_thread_groking but that would actually
# break functionality! If this were moved there we would clear the interrupt
# immediately after setting it in #cancel_timed_out, hence this MUST be here
thread.interrupted
end
endSorry for not having a shorter reproducer, but as far as I understand the JRuby codebase and the explainations in #4516 and related issue this probably very hard to reproduce in isolation.
- I'm pretty certain this is a concurrency issue since we can tune the number of threads concurrently going through this code, and the higher that number goes the more likely this exception is to show up.
- Enabling AOT (compile mode
FORCE) compilation makes the issue go away (or at least so unlikely that I couldn't reproduce it so far) - We haven't see this in 1.7.x ever
- I tried running this code in isolation across multiple threads but couldn't reproduce the problem, so I guess it matters how much unrelated load is on the JIT(/Ruby Runtime) in other threads concurrently?
- I can reproduce this with a JRuby I build from today's master 158574d as well
I'll try to get you more details to work with.