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

java.lang.ArrayIndexOutOfBoundsException in 9.2.13.0 #6466

Closed
AlexWayfer opened this issue Nov 16, 2020 · 20 comments · Fixed by #6546
Closed

java.lang.ArrayIndexOutOfBoundsException in 9.2.13.0 #6466

AlexWayfer opened this issue Nov 16, 2020 · 20 comments · Fixed by #6546

Comments

@AlexWayfer
Copy link

AlexWayfer commented Nov 16, 2020

Environment Information

Provide at least:

  • Cirrus CI jruby 9.2.13.0 (2.5.7) 2020-08-03 9a89c94bcc OpenJDK 64-Bit Server VM 25.275-b01 on 1.8.0_275-b01 +jit [linux-x86_64]
  • Arch Linux (5.9.8-arch1-1) jruby 9.2.13.0 (2.5.7) 2020-08-03 9a89c94bcc OpenJDK 64-Bit Server VM 14.0.2+12 on 14.0.2+12 +jit [linux-x86_64]

Other relevant info you may wish to add:

Expected Behavior

No errors.

Actual Behavior

In Cirrus CI:

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

warning: thread "Ruby-0-Thread-2: /tmp/cirrus-ci-build/spec/filewatcher/cli/spec_helper/shell_watch_run.rb:68" terminated with exception (report_on_exception is true):
java.lang.ArrayIndexOutOfBoundsException: -1
	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:4125)
	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.lang.Thread.run(Thread.java:748)

On Arch Linux:

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

Ok I think this is a bug in how we handle exceptions in the thread spawned by Process::detach. In this case it looks like the waitpid call fails and attempts to raise an error around the code below (which creates the wait thread):

BlockCallback callback = new BlockCallback() {
@Override
public IRubyObject call(ThreadContext context, IRubyObject[] args, Block block) {
int[] status = new int[1];
Ruby runtime = context.runtime;
int result = checkErrno(runtime, runtime.getPosix().waitpid(pid, status, 0));
return RubyStatus.newProcessStatus(runtime, status[0], pid);
}
};

Raising an exception from this thread is fine, except when we have tracing turned on (via set_trace_func or similar). If there is a trace hook installed for raise events, raising an exception here will try to assemble a full binding to pass to the hook, including file and line number information from the Ruby stack. Since there is no Ruby stack, it blows up.

Running this without tracing should work fine as a workaround, but I assume you have it on for a reason in these specs.

On the JRuby side, moving the wait thread into Ruby would be a reasonable fix, but we should also (or should instead) fix the raise trace logic to fail gracefully when there is no Ruby frame available.

@headius
Copy link
Member

headius commented Nov 16, 2020

Trivial reproduction based on my theory:

$ jruby -e "set_trace_func ->(){ }; bogus = 12345678; Process.detach(bogus).join"
-e:1: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag
warning: thread "Ruby-0-Thread-1: -e:1" terminated with exception (report_on_exception is true):
java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 10
	at org.jruby.dist/org.jruby.runtime.ThreadContext.getCurrentFrame(ThreadContext.java:546)
	at org.jruby.dist/org.jruby.runtime.ThreadContext.getFrameName(ThreadContext.java:680)
	at org.jruby.dist/org.jruby.exceptions.RaiseException.doCallEventHook(RaiseException.java:246)
	at org.jruby.dist/org.jruby.exceptions.RaiseException.preRaise(RaiseException.java:186)
	at org.jruby.dist/org.jruby.exceptions.RaiseException.<init>(RaiseException.java:65)
	at org.jruby.dist/org.jruby.exceptions.Exception.<init>(Exception.java:39)
	at org.jruby.dist/org.jruby.exceptions.StandardError.<init>(StandardError.java:38)
	at org.jruby.dist/org.jruby.exceptions.SystemCallError.<init>(SystemCallError.java:38)
	at org.jruby.dist/org.jruby.RubySystemCallError.constructThrowable(RubySystemCallError.java:133)
	at org.jruby.dist/org.jruby.RubyException.toThrowable(RubyException.java:364)
	at org.jruby.dist/org.jruby.exceptions.RaiseException.from(RaiseException.java:84)
	at org.jruby.dist/org.jruby.Ruby.newRaiseException(Ruby.java:4259)
	at org.jruby.dist/org.jruby.Ruby.newErrnoFromInt(Ruby.java:3858)
	at org.jruby.dist/org.jruby.Ruby.newErrnoFromInt(Ruby.java:3877)
	at org.jruby.dist/org.jruby.RubyProcess.raiseErrnoIfSet(RubyProcess.java:1699)
	at org.jruby.dist/org.jruby.RubyProcess.checkErrno(RubyProcess.java:1689)
	at org.jruby.dist/org.jruby.RubyProcess.checkErrno(RubyProcess.java:1683)
	at org.jruby.dist/org.jruby.RubyProcess.access$000(RubyProcess.java:83)
	at org.jruby.dist/org.jruby.RubyProcess$3.call(RubyProcess.java:1452)
	at org.jruby.dist/org.jruby.runtime.CallBlock.call(CallBlock.java:76)
	at org.jruby.dist/org.jruby.runtime.Block.call(Block.java:139)
	at org.jruby.dist/org.jruby.RubyProc.call(RubyProc.java:318)
	at org.jruby.dist/org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)
	at java.base/java.lang.Thread.run(Thread.java:834)
Unhandled Java exception: java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 10
java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 10
     getCurrentFrame at org/jruby/runtime/ThreadContext.java:546
        getFrameName at org/jruby/runtime/ThreadContext.java:680
     doCallEventHook at org/jruby/exceptions/RaiseException.java:246
            preRaise at org/jruby/exceptions/RaiseException.java:186
              <init> at org/jruby/exceptions/RaiseException.java:65
              <init> at org/jruby/exceptions/Exception.java:39
              <init> at org/jruby/exceptions/StandardError.java:38
              <init> at org/jruby/exceptions/SystemCallError.java:38
  constructThrowable at org/jruby/RubySystemCallError.java:133
         toThrowable at org/jruby/RubyException.java:364
                from at org/jruby/exceptions/RaiseException.java:84
   newRaiseException at org/jruby/Ruby.java:4259
     newErrnoFromInt at org/jruby/Ruby.java:3858
     newErrnoFromInt at org/jruby/Ruby.java:3877
     raiseErrnoIfSet at org/jruby/RubyProcess.java:1699
          checkErrno at org/jruby/RubyProcess.java:1689
          checkErrno at org/jruby/RubyProcess.java:1683
          access$000 at org/jruby/RubyProcess.java:83
                call at org/jruby/RubyProcess.java:1452
                call at org/jruby/runtime/CallBlock.java:76
                call at org/jruby/runtime/Block.java:139
                call at org/jruby/RubyProc.java:318
                 run at org/jruby/internal/runtime/RubyRunnable.java:105
                 run at java/lang/Thread.java:834
`

@headius
Copy link
Member

headius commented Nov 16, 2020

It appears that MRI does not raise errors from the detach thread. Need to research a bit more to see how they propagate the errno if one occurs.

headius added a commit to headius/jruby that referenced this issue Nov 16, 2020
In jruby#6466 we see that the thread from a Process::detach is raising
an error when the waitpid fails with an error. This does not
appear to match the logic in MRI and also breaks if there is a
"raise" hook installed in the system.

This change should better match MRI logic for the detach thread
and avoid the hook issue reported in jruby#6466. It does not address a
separate bug in the trace hook logic when no Ruby frames are
available.
@headius
Copy link
Member

headius commented Nov 16, 2020

I have pushed #6467 to address the detach bug. The fragility in the "raise" hook remains.

@AlexWayfer You may be able to work around this locally by replacing our detach logic with a pure-Ruby version. See the PR and basically do that but in Ruby, something like this untested code:

class << Process
  def detach(pid)
    Thread.new { while waitpid(pid) == 0; end; $? }
  end
end

@headius headius added this to the JRuby 9.2.14.0 milestone Nov 16, 2020
@AlexWayfer
Copy link
Author

Running this without tracing should work fine as a workaround, but I assume you have it on for a reason in these specs.

What? Where? I have no --backtrace option for RSpec.

It appears that MRI does not raise errors from the detach thread. Need to research a bit more to see how they propagate the errno if one occurs.

I'm not sure, but I see terminology confusion: do you mean "process" and not "thread"?

I have pushed #6467 to address the detach bug. The fragility in the "raise" hook remains.

@AlexWayfer You may be able to work around this locally by replacing our detach logic with a pure-Ruby version. See the PR and basically do that but in Ruby, something like this untested code:

class << Process
  def detach(pid)
    Thread.new { while waitpid(pid) == 0; end; $? }
  end
end

Now I'm getting (locally) this:

warning: thread "Ruby-0-Thread-2: /home/alex/Projects/ruby/filewatcher-cli/lib/filewatcher/cli/spec_helper.rb:7" terminated with exception (report_on_exception is true):
Errno::ECHILD: No child processes - No child processes
  waitpid at org/jruby/RubyProcess.java:919
  waitpid at org/jruby/RubyProcess.java:901
  waitpid at org/jruby/RubyProcess.java:888
   detach at /home/alex/Projects/ruby/filewatcher-cli/lib/filewatcher/cli/spec_helper.rb:7

I don't know, why is something like this here at all while nothing like this with MRI.

@headius
Copy link
Member

headius commented Nov 16, 2020

What? Where? I have no --backtrace option for RSpec.

Not backtrace – Ruby debugging trace hooks, like set_trace_func. Some code running as part of your spec suite appears to install such a hook. That is why we see the doCallEventHook call in your backtrace.

I'm not sure, but I see terminology confusion: do you mean "process" and not "thread"?

Process::detach mostly just spins up a thread that calls waitpid on the given pid and blocks. That thread is started up entirely from Java code (or C code in CRuby) and has no Ruby code executing in it, which caused the aforementioned trace hook to fail. The bug with our trace hook is not fixed, but I have fixed the Process::detach logic to not try to raise errors.

Now I'm getting (locally) this:

Ok, my untested code is probably not quite right and might need some adjustment. It does seem as though the pid passed to this Process::detach call is no longer a valid process, though, so perhaps some subprocess your spec launches has been prematurely terminated?

@headius
Copy link
Member

headius commented Nov 16, 2020

A more elaborate patch that may help. I still believe you have a process dying prematurely during those specs, though.

require 'ffi'

class << Process
  module Waitpid
    extend FFI::Library
    ffi_lib 'c'
    attach_function :waitpid, [:long, :int], :long
  end

  def detach(pid)
    Thread.new { while (ret = Waitpid.waitpid(pid, 0)) == 0; end; ret }
  end
end

@headius
Copy link
Member

headius commented Nov 16, 2020

Note that ret in the above patch is not quite right, and does not do appropriate bit masking to pull out the process termination status. This version is a little hackier (uses JRuby internals) but may be a better fit to the Process.detach API:

require 'ffi'
require 'jruby'

class << Process
  module Waitpid
    extend FFI::Library
    ffi_lib 'c'
    attach_function :waitpid, [:long, :int], :int
  end

  def detach(pid)
    Thread.new do
      while (ret = Waitpid.waitpid(pid, 0)) == 0; end
      if ret == -1
        nil
      else
        org.jruby.RubyProcess::RubyStatus.newProcessStatus(JRuby.runtime, ret, pid)
      end
    end
  end
end

@AlexWayfer
Copy link
Author

Not backtrace – Ruby debugging trace hooks, like set_trace_func. Some code running as part of your spec suite appears to install such a hook. That is why we see the doCallEventHook call in your backtrace.

I mean… "but I assume you have it on for a reason in these specs" is wrong for me — I didn't make something special for any reason.

It does seem as though the pid passed to this Process::detach call is no longer a valid process, though, so perhaps some subprocess your spec launches has been prematurely terminated?

Sorry, I don't understand completely: I have debug "@pid = #{@pid}" and at the next line of code debug Process.detach(@pid), so… how?

OK, I've added puts 'END OF ENV DUMPER' to the spec/filewatcher/cli/dumpers/env_dumper.rb, and I've got such output:

> bundle exec rspec -e 'ENV variables when file created file existence'
Coverage may be inaccurate; set the "--debug" command line option, or do JRUBY_OPTS="--debug" or set the "debug.fullTrace=true" option in your .jrubyrc
/home/alex/.rbenv/versions/jruby-9.2.13.0/lib/ruby/gems/shared/gems/simplecov-0.18.5/lib/simplecov.rb:345: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag
Run options: include {:full_description=>/ENV\ variables\ when\ file\ created\ file\ existence/}

Filewatcher::CLI
  ENV variables
    when file created
      file existence
D, [2020-11-17T01:58:24.788481 #159639] DEBUG -- : Thread #2002 action = create
D, [2020-11-17T01:58:24.794867 #159639] DEBUG -- : Thread #2002 options = --interval=0.2
D, [2020-11-17T01:58:24.796023 #159639] DEBUG -- : Thread #2002 dumper = env
D, [2020-11-17T01:58:24.797078 #159639] DEBUG -- : Thread #2002 start
D, [2020-11-17T01:58:24.798450 #159639] DEBUG -- : Thread #2002 sleep without intervals 3
D, [2020-11-17T01:58:27.800099 #159639] DEBUG -- : Thread #2002 spawn_command = /home/alex/Projects/ruby/filewatcher-cli/exe/filewatcher --interval=0.2 "/home/alex/Projects/ruby/filewatcher-cli/spec/tmp/foo.txt" "ruby /home/alex/Projects/ruby/filewatcher-cli/spec/filewatcher/cli/spec_helper/../dumpers/env_dumper.rb "
D, [2020-11-17T01:58:27.809974 #159639] DEBUG -- : Thread #2002 @pid = 159707
D, [2020-11-17T01:58:27.812850 #159639] DEBUG -- : Thread #2002 #<Thread:0x71c17a57>
D, [2020-11-17T01:58:27.814727 #159639] DEBUG -- : Thread #2002 sleep without intervals 3
D, [2020-11-17T01:58:30.830916 #159639] DEBUG -- : Thread #2002 pid state = S
D, [2020-11-17T01:58:30.832051 #159639] DEBUG -- : Thread #2002 start: File.exist?(DUMP_FILE) = false
D, [2020-11-17T01:58:30.845965 #159639] DEBUG -- : Thread #2002 make changes, @action = create, @filename = /home/alex/Projects/ruby/filewatcher-cli/spec/tmp/foo.txt
D, [2020-11-17T01:58:30.850169 #159639] DEBUG -- : Thread #2002 stat /home/alex/Projects/ruby/filewatcher-cli/spec/tmp/foo.txt: Unknown OS for system `stat`
D, [2020-11-17T01:58:30.850844 #159639] DEBUG -- : Thread #2002 File.mtime = 2020-11-17 01:58:30.844657301
D, [2020-11-17T01:58:30.851293 #159639] DEBUG -- : Thread #2002 sleep without intervals 3
END OF ENV DUMPER
D, [2020-11-17T01:58:33.852838 #159639] DEBUG -- : Thread #2002 make_changes: File.exist?(DUMP_FILE) = true
D, [2020-11-17T01:58:33.853396 #159639] DEBUG -- : Thread #2002 sleep without intervals 6
D, [2020-11-17T01:58:39.854082 #159639] DEBUG -- : Thread #2002 kill_filewatcher
D, [2020-11-17T01:58:39.891831 #159639] DEBUG -- : Thread #2002 sleep without intervals 3
warning: thread "Ruby-0-Thread-1: /home/alex/Projects/ruby/filewatcher-cli/lib/filewatcher/cli/spec_helper.rb:7" terminated with exception (report_on_exception is true):
Errno::ECHILD: No child processes - No child processes
  waitpid at org/jruby/RubyProcess.java:919
  waitpid at org/jruby/RubyProcess.java:901
  waitpid at org/jruby/RubyProcess.java:888
   detach at /home/alex/Projects/ruby/filewatcher-cli/lib/filewatcher/cli/spec_helper.rb:7
D, [2020-11-17T01:58:42.905536 #159639] DEBUG -- : Thread #2002 stop
D, [2020-11-17T01:58:42.912912 #159639] DEBUG -- : FileUtils.rm_r /home/alex/Projects/ruby/filewatcher-cli/spec/tmp
        is expected to equal true

But why is it not here with MRI?

Note that ret in the above patch is not quite right, and does not do appropriate bit masking to pull out the process termination status. This version is a little hackier (uses JRuby internals) but may be a better fit to the Process.detach API:

require 'ffi'
require 'jruby'

class << Process
  module Waitpid
    extend FFI::Library
    ffi_lib 'c'
    attach_function :waitpid, [:long, :int], :int
  end

  def detach(pid)
    Thread.new do
      while (ret = Waitpid.waitpid(pid, 0)) == 0; end
      if ret == -1
        nil
      else
        org.jruby.RubyProcess::RubyStatus.newProcessStatus(JRuby.runtime, ret, pid)
      end
    end
  end
end

OK, with this code (patch, work-around) output is cleaner:


> bundle exec rspec -e 'ENV variables when file created file existence'
Coverage may be inaccurate; set the "--debug" command line option, or do JRUBY_OPTS="--debug" or set the "debug.fullTrace=true" option in your .jrubyrc
/home/alex/.rbenv/versions/jruby-9.2.13.0/lib/ruby/gems/shared/gems/simplecov-0.18.5/lib/simplecov.rb:345: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag
Run options: include {:full_description=>/ENV\ variables\ when\ file\ created\ file\ existence/}

Filewatcher::CLI
  ENV variables
    when file created
      file existence
D, [2020-11-17T02:01:10.128151 #160868] DEBUG -- : Thread #2002 action = create
D, [2020-11-17T02:01:10.133772 #160868] DEBUG -- : Thread #2002 options = --interval=0.2
D, [2020-11-17T02:01:10.134303 #160868] DEBUG -- : Thread #2002 dumper = env
D, [2020-11-17T02:01:10.134879 #160868] DEBUG -- : Thread #2002 start
D, [2020-11-17T02:01:10.135969 #160868] DEBUG -- : Thread #2002 sleep without intervals 3
D, [2020-11-17T02:01:13.137577 #160868] DEBUG -- : Thread #2002 spawn_command = /home/alex/Projects/ruby/filewatcher-cli/exe/filewatcher --interval=0.2 "/home/alex/Projects/ruby/filewatcher-cli/spec/tmp/foo.txt" "ruby /home/alex/Projects/ruby/filewatcher-cli/spec/filewatcher/cli/spec_helper/../dumpers/env_dumper.rb "
D, [2020-11-17T02:01:13.146051 #160868] DEBUG -- : Thread #2002 @pid = 160941
D, [2020-11-17T02:01:13.147891 #160868] DEBUG -- : Thread #2002 #<Thread:0x4fd05028>
D, [2020-11-17T02:01:13.148351 #160868] DEBUG -- : Thread #2002 sleep without intervals 3
D, [2020-11-17T02:01:16.167238 #160868] DEBUG -- : Thread #2002 pid state = S
D, [2020-11-17T02:01:16.167769 #160868] DEBUG -- : Thread #2002 start: File.exist?(DUMP_FILE) = false
D, [2020-11-17T02:01:16.184802 #160868] DEBUG -- : Thread #2002 make changes, @action = create, @filename = /home/alex/Projects/ruby/filewatcher-cli/spec/tmp/foo.txt
D, [2020-11-17T02:01:16.191048 #160868] DEBUG -- : Thread #2002 stat /home/alex/Projects/ruby/filewatcher-cli/spec/tmp/foo.txt: Unknown OS for system `stat`
D, [2020-11-17T02:01:16.191964 #160868] DEBUG -- : Thread #2002 File.mtime = 2020-11-17 02:01:16.187783811
D, [2020-11-17T02:01:16.193854 #160868] DEBUG -- : Thread #2002 sleep without intervals 3
END OF ENV DUMPER
D, [2020-11-17T02:01:19.197253 #160868] DEBUG -- : Thread #2002 make_changes: File.exist?(DUMP_FILE) = true
D, [2020-11-17T02:01:19.198009 #160868] DEBUG -- : Thread #2002 sleep without intervals 6
D, [2020-11-17T02:01:25.198649 #160868] DEBUG -- : Thread #2002 kill_filewatcher
D, [2020-11-17T02:01:25.226295 #160868] DEBUG -- : Thread #2002 sleep without intervals 3
D, [2020-11-17T02:01:28.244417 #160868] DEBUG -- : Thread #2002 stop
D, [2020-11-17T02:01:28.250464 #160868] DEBUG -- : FileUtils.rm_r /home/alex/Projects/ruby/filewatcher-cli/spec/tmp
        is expected to equal true

Finished in 18.16 seconds (files took 0.83257 seconds to load)
1 example, 0 failures

So, I guess, such code should be in the core of JRuby to match MRI behavior.

@headius
Copy link
Member

headius commented Nov 19, 2020

So, I guess, such code should be in the core of JRuby to match MRI behavior.

The PR in #6467 will fix the base issue with Process.detach

I also see now where the trace hook is happening. From your output this line indicates that you are running coverage in these spec runs, which uses the hook mechanism:

Coverage may be inaccurate; set the "--debug" command line option, or do JRUBY_OPTS="--debug" or set the "debug.fullTrace=true" option in your .jrubyrc
/home/alex/.rbenv/versions/jruby-9.2.13.0/lib/ruby/gems/shared/gems/simplecov-0.18.5/lib/simplecov.rb:345: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag

There is nothing wrong with this... I just point it out to show how this bug is being exposed.

And it is indeed a bug here, which will be fixed by #6467.

@headius
Copy link
Member

headius commented Nov 19, 2020

If you like we have snapshot builds of 9.2.14.0 at https://oss.sonatype.org/content/repositories/snapshots/org/jruby/jruby-dist/9.2.14.0-SNAPSHOT/

@headius headius closed this as completed Nov 19, 2020
@deivid-rodriguez
Copy link
Contributor

Hello! 👋 👋

I just run into this same error here. But I'm using 9.2.14.0 there, so maybe there's another edge case not yet fixed? In that failing test I'm using Open3.capture2e so maybe Process.spawn has a similar issue?


  1) Error:
TestProjectSanity#test_require_rubygems_package:
Java::JavaLang::ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 10
    org.jruby.dist/org.jruby.runtime.ThreadContext.getCurrentFrame(ThreadContext.java:541)
    org.jruby.dist/org.jruby.runtime.ThreadContext.getFrameName(ThreadContext.java:675)
    org.jruby.dist/org.jruby.exceptions.RaiseException.doCallEventHook(RaiseException.java:171)
    org.jruby.dist/org.jruby.exceptions.RaiseException.preRaise(RaiseException.java:111)
    org.jruby.dist/org.jruby.exceptions.RaiseException.<init>(RaiseException.java:65)
    org.jruby.dist/org.jruby.exceptions.Exception.<init>(Exception.java:38)
    org.jruby.dist/org.jruby.exceptions.StandardError.<init>(StandardError.java:38)
    org.jruby.dist/org.jruby.exceptions.SystemCallError.<init>(SystemCallError.java:38)
    org.jruby.dist/org.jruby.RubySystemCallError.constructThrowable(RubySystemCallError.java:133)
    org.jruby.dist/org.jruby.RubyException.toThrowable(RubyException.java:349)
    org.jruby.dist/org.jruby.exceptions.RaiseException.from(RaiseException.java:81)
    org.jruby.dist/org.jruby.Ruby.newRaiseException(Ruby.java:4125)
    org.jruby.dist/org.jruby.Ruby.newErrnoFromInt(Ruby.java:3746)
    org.jruby.dist/org.jruby.Ruby.newErrnoFromInt(Ruby.java:3765)
    org.jruby.dist/org.jruby.RubyProcess.raiseErrnoIfSet(RubyProcess.java:1693)
    org.jruby.dist/org.jruby.RubyProcess.waitpid(RubyProcess.java:919)
    org.jruby.dist/org.jruby.RubyProcess.lambda$detach$4(RubyProcess.java:1447)
    org.jruby.dist/org.jruby.runtime.CallBlock.call(CallBlock.java:76)
    org.jruby.dist/org.jruby.runtime.Block.call(Block.java:139)
    org.jruby.dist/org.jruby.RubyProc.call(RubyProc.java:318)
    org.jruby.dist/org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)
    java.base/java.lang.Thread.run(Thread.java:834)

2092 runs, 6432 assertions, 0 failures, 1 errors, 42 skips

You have skipped tests. Run with --verbose for details.
Coverage report generated for Unit Tests to /home/runner/work/rubygems/rubygems/coverage. 0 / 9150 LOC (0.0%) covered.
SimpleCov failed with exit 1rake aborted!
Command failed with status (1)

I'm planning to not run tests with the --debug flag on jruby so that should fix the issue and give me a proper backtrace, right?

@headius
Copy link
Member

headius commented Feb 1, 2021

@deivid-rodriguez Hmm that does look like another manifestation of the same issue.

capture2e uses popen2e which uses spawn and detach but there was an unexpected gap in my fix. My change was intended to avoid raising any errors at all from the detach thread, avoiding it being part of Ruby tracing altogether. However I overlooked that waitpid can raise an error if the underlying system call triggers an error.

I think it is appropriate to reopen this since it was not completely fixed.

@headius headius reopened this Feb 1, 2021
@headius
Copy link
Member

headius commented Feb 1, 2021

I'm planning to not run tests with the --debug flag on jruby so that should fix the issue and give me a proper backtrace, right?

I don't think that will prevent this since even in non---debug mode we still fire this particular event hook. The --debug flag is needed for the more aggressive hooks like line and call.

@headius
Copy link
Member

headius commented Feb 1, 2021

@deivid-rodriguez I would appreciate a reproduction for this. I am not sure how to trigger it since the logic in popen2e should normally not trigger an error in waitpid during the detach thread. waitpid may raise an error if another thread has already joined the subprocess, but that is not possible here.

I have a possible fix pending that I will do as a PR, so we can get a repro/test together before merging it.

@deivid-rodriguez
Copy link
Contributor

Hei @headius, not sure how to repro this, I only saw it once on a CI log. Actually the link I posted before is wrong, the log is this one: https://github.com/rubygems/rubygems/runs/1806426748?check_suite_focus=true.

headius added a commit to headius/jruby that referenced this issue Feb 1, 2021
The rb-waitpid function in CRuby does not actually trigger an
exception raise when the waitpid errors, leaving that to callers
to decide. Because ours did so, any errors during the
Process.detach call to waitpid would trigger the raise event hook
and unfix jruby#6466.

This change moves the errno check outside of our rb_waitpid
equivalent, making it safe to use in the Process.detach thread.

Fixes jruby#6466 again.
@headius
Copy link
Member

headius commented Feb 1, 2021

@deivid-rodriguez Ok, I have pushed #6546 to fix this but I will have to think on how to test it.

@headius
Copy link
Member

headius commented Feb 1, 2021

I have a way to reproduce: detach a non-existent pid.

$ rvm jruby-9.2.14.0 do ruby -rtracer -e "Process.detach(12345).join"
/Users/headius/.rvm/rubies/jruby-9.2.14.0/lib/ruby/stdlib/tracer.rb:134: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag
warning: thread "Ruby-0-Thread-1: -e:1" terminated with exception (report_on_exception is true):
java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 10
	at org.jruby.dist/org.jruby.runtime.ThreadContext.getCurrentFrame(ThreadContext.java:541)

I also realized that even with my waitpid change in #6546, there's still a blocking wait on waitpid that might be interrupted using thread events, so exceptions raising here is unavoidable. The fix in #6546 is correct, but I will push an additional change that makes sure there's a (dummy) Ruby frame available on the detach thread.

headius added a commit to headius/jruby that referenced this issue Feb 1, 2021
* Propagate long pid.
* Push a dummy frame because of interrupts and thread events being
  able to raise an error during waitpid.

Additional fix for jruby#6466.
@headius headius linked a pull request Feb 1, 2021 that will close this issue
@headius headius modified the milestones: JRuby 9.2.14.0, JRuby 9.2.15.0 Feb 1, 2021
@headius
Copy link
Member

headius commented Feb 1, 2021

@deivid-rodriguez FWIW you are probably seeing this because some library is causing a "raise" event hook to get installed, usually via set_trace_func. Libraries that use TracePoint or coverage can avoid this because "raise" events are not necessarily hooked up.

@AlexWayfer
Copy link
Author

You're guys awesome! 😍 I've noticed this error with JRuby > 9.2.13, < 9.2.16, but I didn't have time to write — you're already had nice detailed discussion, investigation and fix. I'm glad to see such Ruby community members, thank you.

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.

3 participants