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

Apparent regression with NameError in 9.1.0.0 #3934

Closed
aviflax opened this Issue May 27, 2016 · 13 comments

Comments

Projects
None yet
4 participants
@aviflax

aviflax commented May 27, 2016

Environment

Darwin Avis-Prudence.local 15.4.0 Darwin Kernel Version 15.4.0: Fri Feb 26 22:08:05 PST 2016; root:xnu-3248.40.184~3/RELEASE_X86_64 x86_64

Expected Behavior

The 9.0.5.0 behavior when referencing an undefined name:

$ ruby -v -e 'puts FooBar'
jruby 9.0.5.0 (2.2.3) 2016-01-26 7bee00d Java HotSpot(TM) 64-Bit Server VM 25.77-b03 on 1.8.0_77-b03 +jit [darwin-x86_64]
NameError: uninitialized constant FooBar
  const_missing at org/jruby/RubyModule.java:3212
          <top> at -e:1

I can see that a NameError occurs, which symbol is uninitialized, and the specific location where it was referenced.

Actual Behavior

$ ruby -v -e 'puts FooBar'
jruby 9.1.0.0 (2.3.0) 2016-05-02 a633c63 Java HotSpot(TM) 64-Bit Server VM 25.77-b03 on 1.8.0_77-b03 +jit [darwin-x86_64]
ArgumentError: too many arguments for format string
   to_str at org/jruby/RubyNameError.java:130
     to_s at org/jruby/RubyNameError.java:224
  message at org/jruby/RubyException.java:149

The actual problem has been masked by this ArgumentError.

@enebo enebo added this to the JRuby 9.1.3.0 milestone May 27, 2016

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo May 27, 2016

Member

Just quickly tried this. The error is something wrong with warnings on via '-v' as you can see it works as expected without -v:

jruby -e 'puts FooBar'
NameError: uninitialized constant FooBar
  const_missing at org/jruby/RubyModule.java:3309
          <top> at -e:1

In 9.1.2.0 I get slightly different output than reporter:

jruby -v -e 'puts FooBar'
jruby 9.1.2.0 (2.3.0) 2016-05-26 34094ac Java HotSpot(TM) 64-Bit Server VM 25.60-b23 on 1.8.0_60-b27 +jit [darwin-x86_64]
(unknown):-1: warning: too many arguments for format string
NameError: uninitialized constant FooBar
  const_missing at org/jruby/RubyModule.java:3309
          <top> at -e:1

So it looks like the NameError is occuring and whatever is messing up in the warning is now not masking over the NameError. It is still clearly wrong though.

Member

enebo commented May 27, 2016

Just quickly tried this. The error is something wrong with warnings on via '-v' as you can see it works as expected without -v:

jruby -e 'puts FooBar'
NameError: uninitialized constant FooBar
  const_missing at org/jruby/RubyModule.java:3309
          <top> at -e:1

In 9.1.2.0 I get slightly different output than reporter:

jruby -v -e 'puts FooBar'
jruby 9.1.2.0 (2.3.0) 2016-05-26 34094ac Java HotSpot(TM) 64-Bit Server VM 25.60-b23 on 1.8.0_60-b27 +jit [darwin-x86_64]
(unknown):-1: warning: too many arguments for format string
NameError: uninitialized constant FooBar
  const_missing at org/jruby/RubyModule.java:3309
          <top> at -e:1

So it looks like the NameError is occuring and whatever is messing up in the warning is now not masking over the NameError. It is still clearly wrong though.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 27, 2016

Member

Hmm. NameError uses sprintf to format the message. Somewhere along the way we're passing too many args in for the format string. I'll have a look.

Member

headius commented May 27, 2016

Hmm. NameError uses sprintf to format the message. Somewhere along the way we're passing too many args in for the format string. I'll have a look.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 27, 2016

Member

I'm not sure why you didn't get a filename, but I did:

$ jruby -v -e 'puts FooBar'
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-26 eb8e2a5 OpenJDK 64-Bit JVMCI VM 25.66-b00-graal-vm-0.10 on 1.8.0_45-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: uninitialized constant FooBar
  const_missing at org/jruby/RubyModule.java:3309
          <top> at -e:1

The warning still appears to be ours, though, since I don't see DidYouMean doing any string formatting at that line.

Member

headius commented May 27, 2016

I'm not sure why you didn't get a filename, but I did:

$ jruby -v -e 'puts FooBar'
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-26 eb8e2a5 OpenJDK 64-Bit JVMCI VM 25.66-b00-graal-vm-0.10 on 1.8.0_45-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: uninitialized constant FooBar
  const_missing at org/jruby/RubyModule.java:3309
          <top> at -e:1

The warning still appears to be ours, though, since I don't see DidYouMean doing any string formatting at that line.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax May 27, 2016

Hmm well I am using 9.1.0.0 and I do have debug mode enabled in my project via .jrubyrc so maybe that partly explains why I keep seeing this. It’s a bit frustrating, because I need debug mode enabled so I can get test coverage via SimpleCov.

My .jrubyrc:

cli.debug=true
debug.fullTrace=true

If I upgrade to 9.1.2.0 will that help?

Thanks!

aviflax commented May 27, 2016

Hmm well I am using 9.1.0.0 and I do have debug mode enabled in my project via .jrubyrc so maybe that partly explains why I keep seeing this. It’s a bit frustrating, because I need debug mode enabled so I can get test coverage via SimpleCov.

My .jrubyrc:

cli.debug=true
debug.fullTrace=true

If I upgrade to 9.1.2.0 will that help?

Thanks!

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 27, 2016

Member

You don't need cli.debug to be set. That is the equivalent of -d at the command line, which prints out internal debugging messages from JRuby itself. It also causes this sprintf warning to be an error.

I think you should be ok with just debug.fullTrace setting or --debug command line, though you might see the warning.

Member

headius commented May 27, 2016

You don't need cli.debug to be set. That is the equivalent of -d at the command line, which prints out internal debugging messages from JRuby itself. It also causes this sprintf warning to be an error.

I think you should be ok with just debug.fullTrace setting or --debug command line, though you might see the warning.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 27, 2016

Member

I have a fix for the warning. MRI uses positional arguments in its NameError messages because it always passes four arguments to sprintf: the name that failed, the inspect of the target object, a possibly-blank : separator, and a possibly-blank "real class" name. Our NameError for const_missing did not have any formatting in it.

I will audit other places we do NameError and try to ensure we're always using the formatting logic as in MRI.

Member

headius commented May 27, 2016

I have a fix for the warning. MRI uses positional arguments in its NameError messages because it always passes four arguments to sprintf: the name that failed, the inspect of the target object, a possibly-blank : separator, and a possibly-blank "real class" name. Our NameError for const_missing did not have any formatting in it.

I will audit other places we do NameError and try to ensure we're always using the formatting logic as in MRI.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax May 27, 2016

I think you should be ok with just debug.fullTrace setting or --debug command line, though you might see the warning.

Thanks for the tip! But when I comment out cli.debug=true and then run my tests, SimpleCov (I think) prints this:

Coverage may be inaccurate; set "cli.debug=true" ("-Xcli.debug=true") in your .jrubyrc or do JRUBY_OPTS="-d"

aviflax commented May 27, 2016

I think you should be ok with just debug.fullTrace setting or --debug command line, though you might see the warning.

Thanks for the tip! But when I comment out cli.debug=true and then run my tests, SimpleCov (I think) prints this:

Coverage may be inaccurate; set "cli.debug=true" ("-Xcli.debug=true") in your .jrubyrc or do JRUBY_OPTS="-d"
@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax May 27, 2016

I have a fix for the warning. … I will audit other places we do NameError and try to ensure we're always using the formatting logic as in MRI.

Wow, that was fast! Impressive!

aviflax commented May 27, 2016

I have a fix for the warning. … I will audit other places we do NameError and try to ensure we're always using the formatting logic as in MRI.

Wow, that was fast! Impressive!

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 27, 2016

Member

Hmm...let me double check on the debug thing. I thought cli.debug was for -d debug mode.

Member

headius commented May 27, 2016

Hmm...let me double check on the debug thing. I thought cli.debug was for -d debug mode.

@headius headius closed this in 6ca6f1f May 27, 2016

headius added a commit that referenced this issue May 27, 2016

Document and reorg new{Name,NoMethod}Error methods.
Some of these use the format string, some don't. See #3934.

headius added a commit that referenced this issue May 27, 2016

Ensure all formatted new{Name,NoMethod}Error callers format right.
Several cases were formatting the string ahead of time rather
than allowing the formatting mechanism to work. Relates to #3934.
@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 27, 2016

Member

I found a few more cases that had this problem:

[] ~/projects/jruby $ jruby -v -e "remove_instance_variable :@foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: instance variable @foo not defined
  remove_instance_variable at org/jruby/RubyKernel.java:2037
                     <top> at -e:1

[] ~/projects/jruby $ jruby -v -e "remove_instance_variable :foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: `foo' is not allowable as an instance variable name
  remove_instance_variable at org/jruby/RubyKernel.java:2037
                     <top> at -e:1

[] ~/projects/jruby $ jruby -v -e "Object.class_variable_get :@@foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: uninitialized class variable @@foo in Object
Did you mean?  fork
  class_variable_get at org/jruby/RubyModule.java:3075
               <top> at -e:1

[] ~/projects/jruby $ jruby -v -e "Object.class_variable_get :foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: `foo' is not allowed as a class variable name
  class_variable_get at org/jruby/RubyModule.java:3075
               <top> at -e:1

I've audited all consumers of the formatted newNameError and newNoMethodError methods and fixed any that were not actually using format strings. See eb7e1fc.

@eregon I'm not sure if there's a good way to test these. We'd have to test that verbose mode does not display anything on MRI, and of course it does not do a bunch of things. For now I'm planning to just add some JRuby regression specs that check this issue.

Member

headius commented May 27, 2016

I found a few more cases that had this problem:

[] ~/projects/jruby $ jruby -v -e "remove_instance_variable :@foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: instance variable @foo not defined
  remove_instance_variable at org/jruby/RubyKernel.java:2037
                     <top> at -e:1

[] ~/projects/jruby $ jruby -v -e "remove_instance_variable :foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: `foo' is not allowable as an instance variable name
  remove_instance_variable at org/jruby/RubyKernel.java:2037
                     <top> at -e:1

[] ~/projects/jruby $ jruby -v -e "Object.class_variable_get :@@foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: uninitialized class variable @@foo in Object
Did you mean?  fork
  class_variable_get at org/jruby/RubyModule.java:3075
               <top> at -e:1

[] ~/projects/jruby $ jruby -v -e "Object.class_variable_get :foo"
jruby 9.1.3.0-SNAPSHOT (2.3.0) 2016-05-27 a643175 Java HotSpot(TM) 64-Bit Server VM 25.92-b14 on 1.8.0_92-b14 +jit [darwin-x86_64]
/Users/headius/projects/jruby/lib/ruby/stdlib/did_you_mean/core_ext/name_error.rb:10: warning: too many arguments for format string
NameError: `foo' is not allowed as a class variable name
  class_variable_get at org/jruby/RubyModule.java:3075
               <top> at -e:1

I've audited all consumers of the formatted newNameError and newNoMethodError methods and fixed any that were not actually using format strings. See eb7e1fc.

@eregon I'm not sure if there's a good way to test these. We'd have to test that verbose mode does not display anything on MRI, and of course it does not do a bunch of things. For now I'm planning to just add some JRuby regression specs that check this issue.

headius added a commit that referenced this issue May 27, 2016

Add spec to test for rogue verbose/debug output from NameError.
See #3934 for some cases that were either warning or erroring
incorrectly.

headius added a commit that referenced this issue May 27, 2016

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jun 1, 2016

Hmm...let me double check on the debug thing. I thought cli.debug was for -d debug mode.

@headius just curious if you maybe had a chance to look into this? I’d love to be able to run my tests with accurate coverage but without all the extra output in my console. Thanks!

aviflax commented Jun 1, 2016

Hmm...let me double check on the debug thing. I thought cli.debug was for -d debug mode.

@headius just curious if you maybe had a chance to look into this? I’d love to be able to run my tests with accurate coverage but without all the extra output in my console. Thanks!

@donv

This comment has been minimized.

Show comment
Hide comment
@donv

donv Jun 2, 2016

Member

@aviflax @headius SimpleCov reports the wrong warning for turning on coverage events. This has been fixed on SimpleCov master, but not released, yet.

colszowka/simplecov#473
colszowka/simplecov#477

Member

donv commented Jun 2, 2016

@aviflax @headius SimpleCov reports the wrong warning for turning on coverage events. This has been fixed on SimpleCov master, but not released, yet.

colszowka/simplecov#473
colszowka/simplecov#477

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jun 2, 2016

@donv great, thank you!!

aviflax commented Jun 2, 2016

@donv great, thank you!!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment