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.

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

JRuby 9.2.12.0 OpenJDK11 java.lang.ArrayIndexOutOfBoundsException from JRuby Runtime #6337

Closed
JohnPhillips31416 opened this issue Jul 20, 2020 · 9 comments · Fixed by #6323
Closed

Comments

@JohnPhillips31416
Copy link

JohnPhillips31416 commented Jul 20, 2020

Seeing the following exception when running Java VM OpenJDK 64-Bit Server VM Java Version 11.0.7 JRuby Version 9.2.12.0 JRuby Revision db01a49

2020-07-20 22:07:15.662 +0000 [WARN|00898|java:stderr] :: java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 40
2020-07-20 22:07:15.662 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.runtime.ThreadContext.popScope(ThreadContext.java:339)
2020-07-20 22:07:15.663 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.internal.runtime.methods.MixedModeIRMethod.post(MixedModeIRMethod.java:43)
2020-07-20 22:07:15.663 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:158)
2020-07-20 22:07:15.664 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:143)
2020-07-20 22:07:15.664 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:200)
2020-07-20 22:07:15.665 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:375)
2020-07-20 22:07:15.665 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:174)
2020-07-20 22:07:15.666 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.util.IOOutputStream.write(IOOutputStream.java:129)
2020-07-20 22:07:15.667 +0000 [WARN|00898|java:stderr] :: 	at java.base/java.io.PrintStream.write(PrintStream.java:559)
2020-07-20 22:07:15.667 +0000 [WARN|00898|java:stderr] :: 	at java.base/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:233)
2020-07-20 22:07:15.669 +0000 [WARN|00898|java:stderr] :: 	at java.base/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:312)
2020-07-20 22:07:15.669 +0000 [WARN|00898|java:stderr] :: 	at java.base/sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
2020-07-20 22:07:15.670 +0000 [WARN|00898|java:stderr] :: 	at java.base/java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:184)
2020-07-20 22:07:15.670 +0000 [WARN|00898|java:stderr] :: 	at java.base/java.io.PrintStream.write(PrintStream.java:606)
2020-07-20 22:07:15.671 +0000 [WARN|00898|java:stderr] :: 	at java.base/java.io.PrintStream.print(PrintStream.java:745)
2020-07-20 22:07:15.671 +0000 [WARN|00898|java:stderr] :: 	at java.base/java.io.PrintStream.println(PrintStream.java:882)
2020-07-20 22:07:15.672 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.RubyThread.printReportExceptionWarning(RubyThread.java:1787)
2020-07-20 22:07:15.672 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.RubyThread.exceptionRaised(RubyThread.java:1818)
2020-07-20 22:07:15.673 +0000 [WARN|00898|java:stderr] :: 	at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:112)
2020-07-20 22:07:15.673 +0000 [WARN|00898|java:stderr] :: 	at java.base/java.lang.Thread.run(Thread.java:834)

@JohnPhillips31416 JohnPhillips31416 changed the title JRuby 9.2.12.0 java.lang.ArrayIndexOutOfBoundsException from JRuby Runtime JRuby 9.2.12.0 OpenJDK11 java.lang.ArrayIndexOutOfBoundsException from JRuby Runtime Jul 20, 2020
@headius
Copy link
Member

headius commented Jul 21, 2020

This is pretty likely to be the same concurrency issue we've been fixing for #6319. As with that case, a scope is not getting pushed at the right time, and then we attempt to pop it.

@headius headius added this to the 9.2.13.0 milestone Jul 21, 2020
@enebo
Copy link
Member

enebo commented Jul 21, 2020

@JohnPhillips31416 Hopefully this happens enough to build some confident that the ir_concurrency branch fixes this.

@JohnPhillips31416
Copy link
Author

JohnPhillips31416 commented Jul 21, 2020

I've tested ir_concurrency with jdk8 and 9.2.12.0 with openjdk11, I'll try to do some testing with ir_concurrency and openjdk11 as well.

@headius
Copy link
Member

headius commented Jul 21, 2020

The relevant part of this code is below:

try {
this.pre(ic, context, self, name, block, implClass);
return ic.getEngine().interpret(context, null, self, ic, implClass, name, arg1, block);
} finally {
this.post(ic, context);
}

The issue you're seeing would indicate that there's a mismatch between what pre and post do. Those are shown below:

protected void post(InterpreterContext ic, ThreadContext context) {
// update call stacks (pop: ..)
context.popFrame();
if (ic.popDynScope()) {
context.popScope();
}
}
protected void pre(InterpreterContext ic, ThreadContext context, IRubyObject self, String name, Block block, RubyModule implClass) {
// update call stacks (push: frame, class, scope, etc.)
context.preMethodFrameOnly(implClass, name, self, block);
if (ic.pushNewDynScope()) {
context.pushScope(DynamicScope.newDynamicScope(ic.getStaticScope()));
}
}

Specifically, if the ic pushNewDynScope and popDynScope booleans must be mismatched. This is the same situation as #6319 but in this case since we're at the top of the stack we see it try to pop a scope that was never pushed, and the stack size goes negative.

The ic is always held in hand, so it's not getting swapped out between these two calls. So some state accessed here is changing while we are executing. Here's those two pieces of logic in InterpreterContext:

    public boolean pushNewDynScope() {
        if (instructions == null) getEngine();

        return pushNewDynScope;
    }

    public boolean popDynScope() {
        if (instructions == null) getEngine();

        return popDynScope;
    }

@enebo
Copy link
Member

enebo commented Jul 21, 2020

If this is from flags I think I have the incriminating evidence in #6319. I will attack flags again in the morning. We will get this.

@headius
Copy link
Member

headius commented Aug 1, 2020

Fixed by #6323.

@AlexWayfer
Copy link

AlexWayfer commented Nov 15, 2020

Seems existing still in 9.2.13.0:

JRuby version: https://cirrus-ci.com/task/5614335160483840?command=bundle#L3

Error: https://cirrus-ci.com/task/5614335160483840?command=test#L63

Locally, with the same 9.2.13, I'm getting such errors:

warning: thread "Ruby-0-Thread-13: /home/alex/Projects/ruby/filewatcher-cli/spec/filewatcher/cli/spec_helper/shell_watch_run.rb:68" terminated with exception (report_on_exception is true):
java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 10
	at org.jruby.runtime.ThreadContext.getCurrentFrame(ThreadContext.java:541)
	at org.jruby.runtime.ThreadContext.getFrameName(ThreadContext.java:675)
	at org.jruby.exceptions.RaiseException.doCallEventHook(RaiseException.java:171)
	at org.jruby.exceptions.RaiseException.preRaise(RaiseException.java:111)
	at org.jruby.exceptions.RaiseException.<init>(RaiseException.java:65)
	at org.jruby.exceptions.Exception.<init>(Exception.java:38)
	at org.jruby.exceptions.StandardError.<init>(StandardError.java:38)
	at org.jruby.exceptions.SystemCallError.<init>(SystemCallError.java:38)
	at org.jruby.RubySystemCallError.constructThrowable(RubySystemCallError.java:133)
	at org.jruby.RubyException.toThrowable(RubyException.java:349)
	at org.jruby.exceptions.RaiseException.from(RaiseException.java:81)
	at org.jruby.Ruby.newRaiseException(Ruby.java:4120)
	at org.jruby.Ruby.newErrnoFromInt(Ruby.java:3746)
	at org.jruby.Ruby.newErrnoFromInt(Ruby.java:3765)
	at org.jruby.RubyProcess.raiseErrnoIfSet(RubyProcess.java:1698)
	at org.jruby.RubyProcess.checkErrno(RubyProcess.java:1688)
	at org.jruby.RubyProcess.checkErrno(RubyProcess.java:1682)
	at org.jruby.RubyProcess.access$000(RubyProcess.java:83)
	at org.jruby.RubyProcess$3.call(RubyProcess.java:1451)
	at org.jruby.runtime.CallBlock.call(CallBlock.java:76)
	at org.jruby.runtime.Block.call(Block.java:139)
	at org.jruby.RubyProc.call(RubyProc.java:318)
	at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)
	at java.base/java.lang.Thread.run(Thread.java:832)

@headius
Copy link
Member

headius commented Nov 16, 2020

This actually looks like an error raising an exception at the very top of the stack, when there are no frames available. Could be a bug during startup.

@AlexWayfer Could you open a separate issue for this?

@AlexWayfer
Copy link

AlexWayfer commented Nov 16, 2020

@AlexWayfer Could you open a separate issue for this?

Created #6466

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants