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

strange stacktrace #3177

Closed
yamam opened this Issue Jul 24, 2015 · 4 comments

Comments

Projects
None yet
2 participants
@yamam
Copy link

yamam commented Jul 24, 2015

"org/jruby/" appears many times in the stacktrace of the following script.

Test.java

public class Test {
    private Runnable r;
    public Test(Runnable run)
    {
        r = run;
    }

    public void run()
    {
        r.run();
    }
}

test.rb

java_import 'Test'

test = Test.new {
    2.times {
        test.run
    }
}

test.run

output

> javac Test.java
> jruby -v test.rb
jruby 9.0.0.0 (2.2.2) 2015-07-21 e10ec96 Java HotSpot(TM) Client VM 25.51-b03 on 1.8.0_51-b16 +jit [Windows 7-x86]
io/console not supported; tty will not be manipulated
Error: Your application used more stack memory than the safety cap of 2048K.
Specify -J-Xss####k to increase it (#### = cap size in KB).
Exception trace follows:
java.lang.StackOverflowError
        at test.block in test.rb(test.rb:5)
        at org.jruby.RubyFixnum.times(org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jrubyorg/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org/jruby/org
@kares

This comment has been minimized.

Copy link
Member

kares commented Jul 24, 2015

its the JVM trying to get you some information about why you're "deep into recursion" ... the script as-is simply won't work without the JVM failing with a StackOverflowError try "fixing" it first e.g.

java_import 'Test'

test = Test.new {
    2.times { puts "running #{self}" }
}

test.run

@kares kares added this to the Won't Fix milestone Jul 24, 2015

@yamam

This comment has been minimized.

Copy link
Author

yamam commented Jul 26, 2015

I debugged with jdb and I found the cause of the bug.

I rewrote the test programs to clarify the cause.

public class Test {
    private Runnable r;
    public Test(Runnable run)
    {
        r = run;
    }

    public void java_run(int i) throws Exception
    {
        if (i == 2)
        {
            throw new Exception();
        }
        else
        {
            r.run();
        }
    }
}
java_import 'Test'

i = 0

test = Test.new {
    1.times {
        begin
            test.java_run(i += 1)
        rescue java.lang.Exception
            puts $!.backtrace
            puts
            raise
        end
    }
}

begin
    test.java_run(0)
rescue java.lang.Exception
    puts $!.backtrace
end

The following is the output.
org.jruby.runtime.Helpers.rewriteStackTraceAndThrow is called for the same exception 3 times.
In rewriteStackTraceAndThrow, stacktrace of the exeption is rewritten.
Each time stacktrace is rewritten, "org/jruby/" is added to the stacktrace.

> javac Test.java
> jruby -v test.rb
jruby 9.0.0.0 (2.2.2) 2015-07-21 e10ec96 Java HotSpot(TM) Client VM 25.51-b03 on 1.8.0_51-b16 +jit [Windows 7-x86]
io/console not supported; tty will not be manipulated
Test.java_run(Test.java:12)
test.block in test.rb(test.rb:8)
org.jruby.RubyFixnum.times(org/jruby/RubyFixnum.java:299)
test.block in test.rb(test.rb:6)
Test.java_run(Test.java:16)
test.block in test.rb(test.rb:8)
org.jruby.RubyFixnum.times(org/jruby/RubyFixnum.java:299)
test.block in test.rb(test.rb:6)
Test.java_run(Test.java:16)
test.<top>(test.rb:18)

Test.java_run(Test.java:12)
test.block in test.rb(test.rb:8)
org.jruby.RubyFixnum.times(org/jruby/org/jruby/RubyFixnum.java:299)
test.block in test.rb(test.rb:6)
Test.java_run(Test.java:16)
test.block in test.rb(test.rb:8)
org.jruby.RubyFixnum.times(org/jruby/org/jruby/RubyFixnum.java:299)
test.block in test.rb(test.rb:6)
Test.java_run(Test.java:16)
test.<top>(test.rb:18)

Test.java_run(Test.java:12)
test.block in test.rb(test.rb:8)
org.jruby.RubyFixnum.times(org/jruby/org/jruby/org/jruby/RubyFixnum.java:299)
test.block in test.rb(test.rb:6)
Test.java_run(Test.java:16)
test.block in test.rb(test.rb:8)
org.jruby.RubyFixnum.times(org/jruby/org/jruby/org/jruby/RubyFixnum.java:299)
test.block in test.rb(test.rb:6)
Test.java_run(Test.java:16)
test.<top>(test.rb:18)

@kares kares modified the milestones: JRuby 1.7.22, Won't Fix Aug 8, 2015

@kares kares self-assigned this Aug 8, 2015

@kares

This comment has been minimized.

Copy link
Member

kares commented Aug 8, 2015

OK, now I get it - the new code helped me to grasp, thanks! confirmed on 1.7.21 as well, fix on its way ...

kares added a commit that referenced this issue Aug 8, 2015

improve backtrace rewriting when native exception is re-thrown (fixes #…
…3177)

... some parts e.g. Java based core-methods had their filename part incorrect when re-thrown (adding package prefix path twice)

kares added a commit that referenced this issue Aug 8, 2015

kares added a commit that referenced this issue Aug 8, 2015

@kares

This comment has been minimized.

Copy link
Member

kares commented Aug 8, 2015

fix works but there's another issue appearing when exception is re-thrown - duplicating .rb parts e.g. :

     [java]   1) Failure:
     [java] test_throwing_runnable_backtrace(TestBacktraces)
     [java]     [/home/travis/build/jruby/jruby/test/test_backtraces.rb:286:in `test_throwing_runnable_backtrace'
     [java]      org/jruby/RubyKernel.java:2190:in `send'
     [java]      org/jruby/RubyArray.java:1613:in `each'
     [java]      org/jruby/RubyArray.java:1613:in `each']:

     [java] <["java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:622)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:269)",
     [java]  "org.jruby.RubyFixnum.times(org/jruby/RubyFixnum.java:275)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:267)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:290)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:228)",
     [java]  "org.jruby.gen.InterfaceImpl564501503.run(org/jruby/gen/InterfaceImpl564501503.gen:13)",
     [java]  "java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:622)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:280)",
     [java]  "org.jruby.RubyKernel.send(org/jruby/RubyKernel.java:2190)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testcase.rb:78)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:34)",
     [java]  "org.jruby.RubyArray.each(org/jruby/RubyArray.java:1613)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:33)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:34)",
     [java]  "org.jruby.RubyArray.each(org/jruby/RubyArray.java:1613)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:33)",
     [java]  "RUBY.run_suite(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/testrunnermediator.rb:46)",
     [java]  "RUBY.start_mediator(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/console/testrunner.rb:67)",
     [java]  "RUBY.start(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/console/testrunner.rb:41)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/testrunnerutilities.rb:29)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/autorunner.rb:216)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/autorunner.rb:12)",
     [java]  "RUBY.(root)(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit.rb:279)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:290)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:228)"]> expected but was

     [java] <["java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:622)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:269)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:269)",
     [java]  "org.jruby.RubyFixnum.times(org/jruby/RubyFixnum.java:275)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:267)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:267)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:290)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:228)",
     [java]  "org.jruby.gen.InterfaceImpl564501503.run(org/jruby/gen/InterfaceImpl564501503.gen:13)",
     [java]  "java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:622)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:280)",
     [java]  "RUBY.test_throwing_runnable_backtrace(/home/travis/build/jruby/jruby/test/test_backtraces.rb:280)",
     [java]  "org.jruby.RubyKernel.send(org/jruby/RubyKernel.java:2190)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testcase.rb:78)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testcase.rb:78)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:34)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:34)",
     [java]  "org.jruby.RubyArray.each(org/jruby/RubyArray.java:1613)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:33)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:33)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:34)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:34)",
     [java]  "org.jruby.RubyArray.each(org/jruby/RubyArray.java:1613)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:33)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/testsuite.rb:33)",
     [java]  "RUBY.run_suite(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/testrunnermediator.rb:46)",
     [java]  "RUBY.run_suite(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/testrunnermediator.rb:46)",
     [java]  "RUBY.start_mediator(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/console/testrunner.rb:67)",
     [java]  "RUBY.start_mediator(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/console/testrunner.rb:67)",
     [java]  "RUBY.start(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/console/testrunner.rb:41)",
     [java]  "RUBY.start(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/console/testrunner.rb:41)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/testrunnerutilities.rb:29)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/ui/testrunnerutilities.rb:29)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/autorunner.rb:216)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/autorunner.rb:216)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/autorunner.rb:12)",
     [java]  "RUBY.run(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit/autorunner.rb:12)",
     [java]  "RUBY.(root)(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit.rb:279)",
     [java]  "RUBY.(root)(/home/travis/build/jruby/jruby/lib/ruby/1.8/test/unit.rb:279)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:290)",
     [java]  "org.jruby.RubyProc.call(org/jruby/RubyProc.java:228)"]>.

https://travis-ci.org/jruby/jruby/jobs/74682481#L723-L724

@kares kares closed this in b62957b Aug 10, 2015

kares added a commit that referenced this issue Aug 10, 2015

Merge branch 'jruby-1_7'
* jruby-1_7:
  FrameType's INTERPRETER_ constants are a leaky abstraction - deprecate
  for now we do not care about duplicate .rb frames in re-thrown Java exception
  occupy less space with FrameType's static collections
  deprecate no longer used Helpers.invokeMethodMissing method
  toArray one-liner
  add a test reproducing backtrace issue #3177
  improve backtrace rewriting when native exception is re-thrown (fixes #3177)
  more test_backtraces TODO left-overs ... these are passing just fine as well
  removed TODOs in test_backtraces - they seem to be all passing
  cleanup test_backtraces
  save an interim builder+string with mangleStringForCleanJavaIdentifier + guess string builder length for possibly less internal array resizing
  avoid 'too much' of try-catch IOException - throw runtime error directly
  minor name mangler cleanup + "micro opts" - slightly less code to execute
  cleanup JRubyFile

Conflicts:
	core/src/main/java/org/jruby/runtime/backtrace/BacktraceData.java
	core/src/main/java/org/jruby/runtime/backtrace/FrameType.java
	core/src/main/java/org/jruby/util/JRubyFile.java
	test/test_backtraces.rb
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.