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

NoMethodError being reported as "UndefinedValue.java:52:in `undefinedOperation': java.lang.RuntimeException: IR compiler/interpreter bug: org.jruby.ir.operands” in jruby-9.0.0.0.pre2 #3094

Closed
DougEverly opened this issue Jun 30, 2015 · 17 comments
Labels
Milestone

Comments

@DougEverly
Copy link

@DougEverly DougEverly commented Jun 30, 2015

When I call a nonexistent method on an object, I get this in ruby 1.7.19:

NoMethodError: undefined method stop_responder' for #SharedRPCClient:0x7237dd8c`

However, same code using jruby-9.0.0.0.pre2, i get this non-helpful (from a ruby perspective) java output:

UndefinedValue.java:52:in `undefinedOperation': java.lang.RuntimeException: IR compiler/interpreter bug: org.jruby.ir.operands.UndefinedValue should not be used as a valid value during execution.
    from UndefinedValue.java:134:in `getMetaClass'
    from Helpers.java:2742:in `invokedynamic'
    from RubyBasicObject.java:1136:in `inspectObj'
    from RubyBasicObject.java:1090:in `hashyInspect'
    from RubyBasicObject.java:1069:in `inspect'
    from RubyKernel.java:1948:in `inspect'
    from RubyKernel$INVOKER$s$0$0$inspect.gen:-1:in `call'
    from Helpers.java:2744:in `invokedynamic'
    from RubyBasicObject.java:1136:in `inspectObj'
    from RubyBasicObject.java:1090:in `hashyInspect'
    from RubyBasicObject.java:1069:in `inspect'
    from RubyKernel.java:1948:in `inspect'
    from RubyKernel$INVOKER$s$0$0$inspect.gen:-1:in `call'
    from RubyClass.java:616:in `finvoke'
    from Helpers.java:505:in `invoke'
    from RubyBasicObject.java:363:in `callMethod'
    from RubyObject.java:535:in `inspect'
    from RubyNameError.java:121:in `to_str'
    from RubyNameError$RubyNameErrorMessage$INVOKER$i$0$0$to_str.gen:-1:in `call'
    from RubyClass.java:616:in `finvoke'
    from Helpers.java:505:in `invoke'
    from RubyBasicObject.java:363:in `callMethod'
    from TypeConverter.java:75:in `convertToType'
    from TypeConverter.java:103:in `convertToType'
    from RubyBasicObject.java:762:in `convertToString'
    from RubyNameError.java:209:in `to_s'
    from RubyNameError$INVOKER$i$0$0$to_s.gen:-1:in `call'
    from RubyClass.java:616:in `finvoke'
    from Helpers.java:505:in `invoke'
    from RubyBasicObject.java:363:in `callMethod'
    from RubyException.java:145:in `message'
    from TraceType.java:329:in `printBacktraceJRuby'
    from TraceType.java:236:in `printBacktrace'
    from TraceType.java:62:in `printBacktrace'
    from Main.java:531:in `handleRaiseException'
    from Main.java:409:in `doRunFromMain'
    from Main.java:299:in `internalRun'
    from Main.java:226:in `run'
    from Main.java:198:in `main’
@enebo enebo added this to the JRuby 9.0.0.0.rc2 milestone Jun 30, 2015
@enebo
Copy link
Member

@enebo enebo commented Jun 30, 2015

@DougEverly Could you try this against rc1 as well to make sure it hasn't been fixed since pre2? If it is still a problem then we would like to get some more information on what is causing this. Your report mentions you are expecting NoMethodError but since we probably have hundreds of tests passing for NoMethodError cases I am guessing something more is at play (which is obviously not in any test suites we run).

The error itself is us forcing a hard error because this case should never happen. The proverbial pooch is so screwed at that point we cannot try and recover so we dump a hard error.

@DougEverly
Copy link
Author

@DougEverly DougEverly commented Jun 30, 2015

I changed to jruby 9.0.0.0.rc1 and still got this, even after removing what I thought was the bad line. Not sure how to pinpoint the Ruby code leading to this error.

$ jruby -v jruby 9.0.0.0.rc1 (2.2.2) 2015-06-10 a0bf3b3 OpenJDK 64-Bit Server VM 24.79-b02 on 1.7.0_79-mockbuild_2015_05_14_07_23-b00 [linux-amd64]

UndefinedValue.java:52:in `undefinedOperation': java.lang.RuntimeException: IR compiler/interpreter bug: org.jruby.ir.operands.UndefinedValue should not be used as a valid value during execution.
    from UndefinedValue.java:134:in `getMetaClass'
    from Helpers.java:2562:in `invokedynamic'
    from RubyBasicObject.java:1127:in `inspectObj'
    from RubyBasicObject.java:1081:in `hashyInspect'
    from RubyBasicObject.java:1060:in `inspect'
    from RubyKernel.java:1933:in `inspect'
    from RubyKernel$INVOKER$s$0$0$inspect.gen:-1:in `call'
    from Helpers.java:2564:in `invokedynamic'
    from RubyBasicObject.java:1127:in `inspectObj'
    from RubyBasicObject.java:1081:in `hashyInspect'
    from RubyBasicObject.java:1060:in `inspect'
    from RubyKernel.java:1933:in `inspect'
    from RubyKernel$INVOKER$s$0$0$inspect.gen:-1:in `call'
    from Helpers.java:2564:in `invokedynamic'
    from RubyBasicObject.java:1127:in `inspectObj'
    from RubyBasicObject.java:1081:in `hashyInspect'
    from RubyBasicObject.java:1060:in `inspect'
    from RubyKernel.java:1933:in `inspect'
    from RubyKernel$INVOKER$s$0$0$inspect.gen:-1:in `call'
    from RubyClass.java:616:in `finvoke'
    from Helpers.java:413:in `invoke'
    from RubyBasicObject.java:365:in `callMethod'
    from RubyObject.java:535:in `inspect'
    from RubyNameError.java:121:in `to_str'
    from RubyNameError$RubyNameErrorMessage$INVOKER$i$0$0$to_str.gen:-1:in `call'
    from RubyClass.java:616:in `finvoke'
    from Helpers.java:413:in `invoke'
    from RubyBasicObject.java:365:in `callMethod'
    from TypeConverter.java:75:in `convertToType'
    from TypeConverter.java:103:in `convertToType'
    from RubyBasicObject.java:761:in `convertToString'
    from RubyNameError.java:209:in `to_s'
    from RubyNameError$INVOKER$i$0$0$to_s.gen:-1:in `call'
    from RubyClass.java:616:in `finvoke'
    from Helpers.java:413:in `invoke'
    from RubyBasicObject.java:365:in `callMethod'
    from RubyException.java:145:in `message'
    from TraceType.java:329:in `printBacktraceJRuby'
    from TraceType.java:236:in `printBacktrace'
    from TraceType.java:62:in `printBacktrace'
    from Main.java:515:in `handleRaiseException'
    from Main.java:405:in `doRunFromMain'
    from Main.java:296:in `internalRun'
    from Main.java:225:in `run'
    from Main.java:197:in `main’
@enebo
Copy link
Member

@enebo enebo commented Jun 30, 2015

@DougEverly Thanks for checking so quickly. If you could dig a little bit I have a command-line for you:

JRUBY_OPTS="-X-C -Xir.compiler.debug=true -Xir.debug=true" jruby {your_whatever}.rb > output 2>&1

This will generate a heinous amount of output but it will make it possible to see what is blowing up (with a trained eye). Go to bottom of output file and search up to first occurrence of 'java.lang.RuntimeException: IR" and you should see an IR Instruction around there with UndefinedValue (I think it is printed out as %undefined). scrolling up a little ways from this area you should see a line marking whch code is being passed over. Line which sort of looks like this:

Instructions[../snippets/super_block1.rb#22#,IRClosure,EnsureTempsAssigned]:

This shows the file (super_block1.rb), line (22), scope type (a block - IRClosure), and compiler pass. You really don't need to know all that much about what this output means to find the general area. If you are not worried about privacy of the code you are running you can just upload this to a gist and I can look at it.

@headius
Copy link
Member

@headius headius commented Jul 1, 2015

If you can provide a way for us to reproduce this, it would also help a lot (and probably wouldn't take long to track down such a complete failure).

@DougEverly
Copy link
Author

@DougEverly DougEverly commented Jul 2, 2015

Unfortunately, I am unable to reproduce the problem now. I likely removed or avoided the condition somehow, and the code is running as expected. If it arises again, I’ll take better care to get a reproducible sample.

@headius
Copy link
Member

@headius headius commented Jul 2, 2015

@DougEverly Thanks for giving it a go!

@atambo
Copy link
Member

@atambo atambo commented Feb 3, 2016

I am able to reproduce the same error as above by upgrading my rails app from 1.7.24 to 9.0.5.0 and running rails s:

Java::JavaLang::RuntimeException: IR compiler/interpreter bug: org.jruby.ir.operands.UndefinedValue should not be used as a valid value during execution.

See full stack trace:
https://gist.github.com/atambo/4791ba58f26c6f836853

When I run JRUBY_OPTS="-X-C -Xir.compiler.debug=true -Xir.debug=true" rails s > output 2>&1 I end up with 477M of output. Below is the part of the file around where the group of java.lang.RuntimeException: IR exceptions are:

https://gist.github.com/atambo/812ac801f7f94ed94afb

If you need more of the file or the whole thing let me know and I can upload it somewhere.

@enebo

@atambo atambo reopened this Feb 3, 2016
@headius
Copy link
Member

@headius headius commented Feb 13, 2016

@atambo Ok thanks. I'll try to reproduce here based on that.

@headius
Copy link
Member

@headius headius commented Feb 13, 2016

I'm still unable to reproduce this, but I suspect that it's a bug in the full interpreter.

@atambo If you can still reproduce this, try adding -Xjit.threshold=-1. This will ensure we only run in the simple interpreter. If my theory is correct the errors should go away.

@enebo @subbuss Without a repro this is hard to find, but it may get fixed if we get our test runs passing with the full interpreter turned on.

@headius
Copy link
Member

@headius headius commented Feb 13, 2016

@atambo Also a separate backtrace with -Xbacktrace.style=full would be helpful.

@atambo
Copy link
Member

@atambo atambo commented Feb 14, 2016

Here is the stacktrace when I run JRUBY_OPTS="-Xbacktrace.style=full -Xjit.threshold=-1" rails s:

https://gist.github.com/atambo/5c7704d226e638e35614

Would you like the output with -X-C -Xir.compiler.debug=true -Xir.debug=true enabled as well as -Xbacktrace.style=full -Xjit.threshold=-1?

@headius
Copy link
Member

@headius headius commented Feb 14, 2016

@atambo The IR output would be helpful if we can get a complete file. Feel free to email me a zip or something.

And I guess I'll need you to pass -d to JRuby so I can see the error behind the LoadError.

@atambo
Copy link
Member

@atambo atambo commented Feb 15, 2016

Here is the output of JRUBY_OPTS="-Xbacktrace.style=full -Xjit.threshold=-1 -d" rails s:

https://gist.github.com/atambo/73f47b5f39831b13b7ec

Here is the output of JRUBY_OPTS="-X-C -Xir.compiler.debug=true -Xir.debug=true -Xbacktrace.style=full -Xjit.threshold=-1 -d" rails s > output 2>&1 (580mb ungzip'd):

http://alextambellini.com/output.gz

@headius
Copy link
Member

@headius headius commented Mar 4, 2016

Ok, we're narrowing it down. It looks like the file that triggers it is /Users/tambellini/repos/cxo/config/environment.

I'm going to add some better logging to this error so we can see exactly what body of code (and possibly what instruction) it's failing on.

@headius
Copy link
Member

@headius headius commented Mar 4, 2016

Dug a bit deeper...now I'm into the file /Users/tambellini/repos/cxo/lib/zookeeper.rb:27, which seems to be the earliest mention of the error. What is this file?

@headius
Copy link
Member

@headius headius commented Mar 4, 2016

Ok, @atambo stopped by IRC and let me see lib/zookeeper. Based on that I reduced the bug to something quite simple:

def foo(n = n)
  p n
end
foo

Run in JRuby:

$ jruby -e 'def foo(n = n); p n; end; foo'
-e:1: warning: circular argument reference - n
Unhandled Java exception: java.lang.RuntimeException: IR compiler/interpreter bug: org.jruby.ir.operands.UndefinedValue should not be used as a valid value during execution.
java.lang.RuntimeException: IR compiler/interpreter bug: org.jruby.ir.operands.UndefinedValue should not be used as a valid value during execution.
   undefinedOperation at org/jruby/ir/operands/UndefinedValue.java:57
           callMethod at org/jruby/ir/operands/UndefinedValue.java:63
            rbInspect at org/jruby/RubyBasicObject.java:1098
                    p at org/jruby/RubyKernel.java:461
                 call at org/jruby/internal/runtime/methods/JavaMethod.java:717
                 call at org/jruby/internal/runtime/methods/DynamicMethod.java:197
         cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:313
                 call at org/jruby/runtime/callsite/CachingCallSite.java:163
                  foo at -e:1
...

So this circular variable form is being parsed or compiled incorrectly. Here's parser output:

$ ast -e 'def foo(n = n); p n; end; foo'
-:1: warning: circular argument reference - n
AST:
RootNode 0
  BlockNode 0
    DefnNode:foo 0
      ArgsNode 0
        ListNode 0
        ListNode 0
          OptArgNode:n 0
            LocalAsgnNode:n 0
              LocalVarNode:n 0
        ListNode 0
        ListNode 0
      FCallNode:p 0
        ArrayNode 0
          LocalVarNode:n 0
, null
    VCallNode:foo 0

And here's relevant -y output from MRI (name changed from n to noob so it would stand out better):

Reading a token: Next token is token tIDENTIFIER ()
Shifting token tIDENTIFIER ()
Entering state 650
Reducing stack by rule 559 (line 4681):
   $1 = token tIDENTIFIER ()
-> $$ = nterm f_norm_arg ()
Stack now 0 2 96 399 599 749 864
Entering state 668
Reducing stack by rule 560 (line 4688):
   $1 = nterm f_norm_arg ()
-> $$ = nterm f_arg_asgn ()
Stack now 0 2 96 399 599 749 864
Entering state 669
lex_state: EXPR_ARG -> EXPR_BEG at line 8312
Reading a token: Next token is token '=' ()
Shifting token '=' ()
Entering state 781
lex_state: EXPR_BEG -> EXPR_ARG at line 8077
lex_state: EXPR_ARG -> EXPR_END at line 7816
Reading a token: Next token is token tIDENTIFIER ()
Shifting token tIDENTIFIER ()
Entering state 35
lex_state: EXPR_END -> EXPR_ENDFN at line 8554
Reading a token: Next token is token ')' ()
Reducing stack by rule 509 (line 4443):
   $1 = token tIDENTIFIER ()
-> $$ = nterm user_variable ()
Stack now 0 2 96 399 599 749 864 669 781
Entering state 220
Next token is token ')' ()
Reducing stack by rule 521 (line 4459):
   $1 = nterm user_variable ()
-e:1: warning: circular argument reference - noob

So we both appear to parse it as an optional var being assigned itself. This should have been a warning in @atambo's code, I think.

It comes down to IR; here's the IR for the above code:

begin INSTANCE_METHOD<foo>
signature(pre=0,opt=1,post=0,rest=NONE,kwargs=0,kwreq=0,kwrest=false)
declared variables
  n(0:0)

basic_block #1: LBL_1:-1
  0: %t_n_4 := copy(nil<>)
  1:   %v_3 := copy(%t_n_4)

basic_block #2: LBL_2:-1
  0:  %self := recv_self
  1:           check_arity(required: 0, opt: 1, rest: false, receivesKeywords: false, restKey: -1)
  2: %t_n_4 := recv_opt_arg(preArgs: 0, requiredArgs: 0, argIndex: 0)
  3:           bne(ipc<LBL_0:9>, %t_n_4, undef<>, jumpTarget: LBL_0:9, arg1: %t_n_4, arg2: %undefined)

basic_block #3: LBL_3:-1
  0: %t_n_4 := copy(%t_n_4)

basic_block #4: LBL_0:9
  0:           line_num(lineNumber: 0)
  1:   %v_3 := call_1o(self<%self>, %t_n_4, callType: FUNCTIONAL, name: p, potentiallyRefined: false)
  2:           return(%v_3)

basic_block #5: LBL_4:-1

And here we see the problem. recv_opt_arg produces UndefinedValue for the sole argument because no values were passed in. This is used as a marker for a subsequent bne to branch to the default value code, and that code proceeds to simply re-assign the same UndefinedValue.

Seems purely an IR problem, and it affects all tiers.

@headius
Copy link
Member

@headius headius commented Mar 4, 2016

Ok, I have a working patch that introduces another temporary variable for the intermediate "undefined" value from recv_opt_arg.

The new IR for the n = n method looks like this:

2016-03-03T21:50:08.240-06:00: InterpretedIRMethod: Printing simple IR for foo
begin INSTANCE_METHOD<foo>
signature(pre=0,opt=1,post=0,rest=NONE,kwargs=0,kwreq=0,kwrest=false)
declared variables
  n(0:0)
  00:           %self := recv_self
  01:            %v_0 := load_implicit_closure
  02:  %current_scope := copy(scope<0>)
  03: %current_module := copy(mod<0>)
  04:                    check_arity(required: 0, opt: 1, rest: false, receivesKeywords: false, restKey: -1)
  05:            %v_3 := recv_opt_arg(preArgs: 0, requiredArgs: 0, argIndex: 0)
  06:                    bne(ipc<LBL_0:9>, %v_3, undef<>, jumpTarget: LBL_0:9, arg1: %v_3, arg2: %undefined)
  07:            %v_3 := copy(*n)
  08:                    label(ipc<LBL_0:9>)
  09:              *n := copy(%v_3)
  10:                    line_num(lineNumber: 0)
  11:            %v_4 := call_1o(self<%self>, *n, callType: FUNCTIONAL, name: p, potentiallyRefined: false)
  12:                    return(%v_4)

Instructions 5 and 7 populate the temporary variable %v_3 along both paths, and then assign to the actual local variable afterwards.

Worth pointing out that my patch also fixes optional block arguments, which had a similar problem.

I'll be pushing this fix momentarily, but would appreciate review by @subbuss and @enebo.

@headius headius closed this in c9e46b7 Mar 4, 2016
headius added a commit that referenced this issue Mar 7, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants
You can’t perform that action at this time.