Occasional ArrayIndexOutOfBoundsException from a line of Ruby that isn't doing array lookups #3729

Closed
trejkaz opened this Issue Mar 14, 2016 · 7 comments

Projects

None yet

3 participants

@trejkaz
trejkaz commented Mar 14, 2016

Environment

JRuby: JRuby 9.0.5.0
OS: OSX 10.11.1

We don't set JRUBY_OPTS. For a change we're running this using the command-line instead of embedding it. We're basically firing up rspec as part of functional testing. None of our command-line options are for changing behaviour in JRuby, other than deliberately setting file.encoding=UTF-8 for the benefit of Windows, which is not relevant for this run here as I'm on OSX.

Gems: rspec-core, rspec-mocks, ci-reporter.

Other environment variables of Ruby relevance:

RBENV_ROOT=/Users/tester/DevEnv/rbenv
RBENV_SHELL=bash

rbenv is indeed present, although we are not using it when running the tests - the tests run by <java classname="org.jruby.Main"> from an Ant task.

Expected Behaviour

I have a spec written as follows:

it 'notifies the callback of each result' do
  callback = double(:callback)
  expect(callback).to receive(:found).exactly(24).times
  @thing.search('mime-type:message/rfc822', callback)
end

Of note, this Thing#search method internally performs work in a thread pool, so the callback gets called from multiple threads, possibly all simultaneously. So the issue I'm about to describe could be a thread safety bug.

Of course I expect this test to pass. ;)

(But due to other circumstances, the test fails about half the time, because this search method ultimately calls the callback on multiple threads and rspec-mocks is not thread-safe. That's another issue and not what I'm reporting here.)

Actual Behaviour

Occasionally (1 per 20 runs or so, based on today's runs), I get this failure instead:

 [java] Failures:
 [java] 
 [java]   1) Thing#search when a callback is provided notifies the callback of each result
 [java]      Failure/Error: Unable to find org.jruby.RubyArray.map(org/jruby/RubyArray.java to read failed line
 [java] 
 [java]      Java::JavaLang::ArrayIndexOutOfBoundsException:
 [java]        7
 [java]      # org.jruby.RubyArray.map(org/jruby/RubyArray.java:2300)
 [java]      # RUBY.(root)(/path/to/project/functional-tests/src/test/rspec/lib/case/search_unsorted_spec.rb:42)
 [java]      # RUBY.run(uri:classloader:/gems/rspec-core-3.4.3/lib/rspec/core/example.rb:236)
 [java]      # RUBY.with_around_and_singleton_context_hooks(uri:classloader:/gems/rspec-core-3.4.3/lib/rspec/core/example.rb:478)
 [java]      # RUBY.block in with_around_example_hooks(uri:classloader:/gems/rspec-core-3.4.3/lib/rspec/core/example.rb:435)
  ...

Line 42 is this one:

      @thing.search('mime-type:message/rfc822', callback)

No call to Array#map on that line, no array lookups either, no idea what is going on.

@kares
Member
kares commented Mar 14, 2016

its likely to be at thread-safety issue - this kind of failures (usually) happens when an array instance is being accessed concurrently.

@jmettraux

I'm facing the same intermittent issue. It would be nice if the actual point in the Ruby (not Java) code would be indicated. That would help fix the issue in your code.

Here's what JRuby tells me: https://gist.github.com/jmettraux/91e04143828e22259aa06390ad7a1d28 not a single pointer to my code.

Context:

$ java -Xmx32m -version
java version "1.7.0_76"
Java(TM) SE Runtime Environment (build 1.7.0_76-b13)
Java HotSpot(TM) 64-Bit Server VM (build 24.76-b04, mixed mode)
$ javac -J-Xmx32m -version
javac 1.7.0_76
$ ruby --version
jruby 1.7.19 (1.9.3p551) 2015-02-05 32f5af0 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_76-b13 +jit [linux-amd64]

Thanks for JRuby.

@kares
Member
kares commented Dec 23, 2016

@jmettraux haven't looked, but could you please confirm its there in the latest of JRuby 1.7 (1.7.26 atm)

@jmettraux

@kares OK, give me some time to gather the info.

@jmettraux

@kares I made a testbed at https://github.com/jmettraux/jruby-gh3729

It happens on the main thread.

When happening in another thread, there is a useful indication like:

Exception in thread "Ruby-0-Thread-15: test.rb:10" 200Exception in thread "Ruby-0-Thread-17: test.rb:10"

No such info when on the main thread (see below).

The code looks like ( https://github.com/jmettraux/jruby-gh3729/blob/master/test.rb ):

a = []

Thread.new do
  loop do
    a << Time.now.to_f
  end
end

1000.times do
  p a.collect { |f| f.to_i }.size
end

sample output ( https://github.com/jmettraux/jruby-gh3729/blob/master/sample-output.txt ):

jruby --dev -G test.rb

jruby 1.7.26 (1.9.3p551) 2016-08-26 69763b8 on Java HotSpot(TM) 64-Bit Server VM 1.8.0_60-b27 [darwin-x86_64]

java version "1.8.0_60"
Java(TM) SE Runtime Environment (build 1.8.0_60-b27)
Java HotSpot(TM) 64-Bit Server VM (build 25.60-b23, mixed mode)

0
0
0
0
0
0
0
RubyArray.java:2400:in `collect': java.lang.ArrayIndexOutOfBoundsException: 2
	from RubyArray.java:2409:in `collect19'
	from RubyArray$INVOKER$i$0$0$collect19.gen:-1:in `call'
	from CachingCallSite.java:143:in `callBlock'
	from CachingCallSite.java:154:in `callIter'
	from CallNoArgBlockNode.java:64:in `interpret'
	from CallNoArgNode.java:60:in `interpret'
	from FCallOneArgNode.java:36:in `interpret'
	from NewlineNode.java:105:in `interpret'
	from ASTInterpreter.java:112:in `INTERPRET_BLOCK'
	from Interpreted19Block.java:206:in `evalBlockBody'
	from Interpreted19Block.java:157:in `yield'
	from Interpreted19Block.java:130:in `yieldSpecific'
	from Block.java:111:in `yieldSpecific'
	from RubyFixnum.java:275:in `times'
	from RubyFixnum$INVOKER$i$0$0$times.gen:-1:in `call'
	from CachingCallSite.java:316:in `cacheAndCall'
	from CachingCallSite.java:145:in `callBlock'
	from CachingCallSite.java:154:in `callIter'
	from CallNoArgBlockNode.java:64:in `interpret'
	from NewlineNode.java:105:in `interpret'
	from BlockNode.java:71:in `interpret'
	from RootNode.java:129:in `interpret'
	from ASTInterpreter.java:121:in `INTERPRET_ROOT'
	from Ruby.java:884:in `runInterpreter'
	from Ruby.java:892:in `runInterpreter'
	from Ruby.java:733:in `runNormally'
	from Ruby.java:578:in `runFromMain'
	from Main.java:393:in `doRunFromMain'
	from Main.java:288:in `internalRun'
	from Main.java:217:in `run'
	from Main.java:197:in `main'
make: *** [test] Error 1

Seen on JRuby 1.7.19 and 1.7.26

@kares
Member
kares commented Dec 23, 2016

@jmettraux aah so its the same concurrency issue -> JRuby's Array should raise ConcurrencyError here
-> just like it does elsewhere. but that won't indicate the problematic .rb line (from the other thread)

but collect should get improved, thanks for the reminder (not sure it will happen on 1.7.x due EOL)

@jmettraux

Keep up the great work guys!

@kares kares added a commit to kares/jruby that referenced this issue Dec 30, 2016
@kares kares raise ConcurrencyError on thread-safety issue from Array#collect
see #3729
1d2f3d8
@kares kares closed this Dec 30, 2016
@kares kares added this to the JRuby 9.1.7.0 milestone Dec 30, 2016
@kares kares added a commit to kares/jruby that referenced this issue Dec 30, 2016
@kares kares raise ConcurrencyError on thread-safety issue from Array#collect
see #3729
b6b31e8
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment