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

DougEverly · 2015-06-30T14:23:28Z

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’

The text was updated successfully, but these errors were encountered:

enebo · 2015-06-30T14:34:42Z

@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 · 2015-06-30T14:45:50Z

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 · 2015-06-30T14:56:03Z

@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 · 2015-07-01T18:26:29Z

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 · 2015-07-02T00:19:24Z

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 · 2015-07-02T16:14:03Z

@DougEverly Thanks for giving it a go!

atambo · 2016-02-03T03:41:49Z

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

headius · 2016-02-13T18:21:17Z

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

headius · 2016-02-13T18:38:09Z

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 · 2016-02-13T18:38:51Z

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

atambo · 2016-02-14T01:01:49Z

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 · 2016-02-14T05:15:59Z

@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 · 2016-02-15T02:13:45Z

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 · 2016-03-04T02:35:22Z

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 · 2016-03-04T02:58:54Z

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 · 2016-03-04T03:22:11Z

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 · 2016-03-04T03:52:59Z

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.

enebo added this to the JRuby 9.0.0.0.rc2 milestone Jun 30, 2015

enebo added ir JRuby 9000 labels Jun 30, 2015

headius closed this as completed Jul 2, 2015

headius modified the milestones: Invalid or Duplicate, JRuby 9.0.0.0.rc2 Jul 2, 2015

atambo reopened this Feb 3, 2016

headius modified the milestones: JRuby 9.1.0.0, Invalid or Duplicate Feb 13, 2016

PragTob mentioned this issue Feb 28, 2016

JRuby 9.0.5.0: uninitialized variables assigned to self as default method argument cause org.jruby.ir.operands.UndefinedValue #3703

Closed

headius closed this as completed in c9e46b7 Mar 4, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

GitHub Sponsors

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

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

DougEverly commented Jun 30, 2015

enebo commented Jun 30, 2015

DougEverly commented Jun 30, 2015

enebo commented Jun 30, 2015

headius commented Jul 1, 2015

DougEverly commented Jul 2, 2015

headius commented Jul 2, 2015

atambo commented Feb 3, 2016

headius commented Feb 13, 2016

headius commented Feb 13, 2016

headius commented Feb 13, 2016

atambo commented Feb 14, 2016

headius commented Feb 14, 2016

atambo commented Feb 15, 2016

headius commented Mar 4, 2016

headius commented Mar 4, 2016

headius commented Mar 4, 2016

headius commented Mar 4, 2016

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

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

Comments

DougEverly commented Jun 30, 2015

enebo commented Jun 30, 2015

DougEverly commented Jun 30, 2015

enebo commented Jun 30, 2015

headius commented Jul 1, 2015

DougEverly commented Jul 2, 2015

headius commented Jul 2, 2015

atambo commented Feb 3, 2016

headius commented Feb 13, 2016

headius commented Feb 13, 2016

headius commented Feb 13, 2016

atambo commented Feb 14, 2016

headius commented Feb 14, 2016

atambo commented Feb 15, 2016

headius commented Mar 4, 2016

headius commented Mar 4, 2016

headius commented Mar 4, 2016

headius commented Mar 4, 2016