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

ActiveSupport EventedFileUpdateChecker wrong number of arguments in JRuby #3733

Closed
brianbroderick opened this issue Mar 14, 2016 · 9 comments

Comments

@brianbroderick
Copy link

Steps to reproduce

rails _5.0.0.beta3_ new rails_5_test --api

Entire Gemfile:
source 'https://rubygems.org'
ruby "2.2.3", { :engine => "jruby", :engine_version => "9.0.5.0" }
gem 'rails', '>= 5.0.0.beta3', '< 5.1'

Bundle and Console:
bundle install
rails c

Actual behavior

Get this error:

`ArgumentError: wrong number of arguments calling `sub` (0 for 1)
                         normalize_extension at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:97
                         block in initialize at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:13
                                         map at org/jruby/RubyArray.java:2300
                         block in initialize at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:13
                                        each at org/jruby/RubyHash.java:1339
                                  initialize at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:12
                             initialize_i18n at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/i18n_railtie.rb:59
                            block in Railtie at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/i18n_railtie.rb:15
                                        call at org/jruby/RubyProc.java:318
                                execute_hook at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/lazy_load_hooks.rb:36
                     block in run_load_hooks at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/lazy_load_hooks.rb:45
                                        each at org/jruby/RubyArray.java:1560
                              run_load_hooks at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/activesupport-5.0.0.beta3/lib/active_support/lazy_load_hooks.rb:44
                           block in Finisher at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/application/finisher.rb:62
                               instance_exec at org/jruby/RubyBasicObject.java:1670
                                         run at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/initializable.rb:30
                   block in run_initializers at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/initializable.rb:55
                         block in tsort_each at /Users/mymac/.rvm/rubies/jruby-9.0.5.0/lib/ruby/stdlib/tsort.rb:226
  block in each_strongly_connected_component at /Users/mymac/.rvm/rubies/jruby-9.0.5.0/lib/ruby/stdlib/tsort.rb:348
      each_strongly_connected_component_from at /Users/mymac/.rvm/rubies/jruby-9.0.5.0/lib/ruby/stdlib/tsort.rb:429
  block in each_strongly_connected_component at /Users/mymac/.rvm/rubies/jruby-9.0.5.0/lib/ruby/stdlib/tsort.rb:347
                                        each at org/jruby/RubyArray.java:1560
                                        call at org/jruby/RubyMethod.java:127
           each_strongly_connected_component at /Users/mymac/.rvm/rubies/jruby-9.0.5.0/lib/ruby/stdlib/tsort.rb:345
                                  tsort_each at /Users/mymac/.rvm/rubies/jruby-9.0.5.0/lib/ruby/stdlib/tsort.rb:224
                                  tsort_each at /Users/mymac/.rvm/rubies/jruby-9.0.5.0/lib/ruby/stdlib/tsort.rb:203
                            run_initializers at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/initializable.rb:54
                                 initialize! at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/application.rb:350
                                       <top> at /projects/rails_5_test/config/environment.rb:5
                                     require at org/jruby/RubyKernel.java:937
                                      (root) at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/application.rb:1
                        require_environment! at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/application.rb:326
        require_application_and_environment! at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/commands/commands_tasks.rb:157
                                     console at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/commands/commands_tasks.rb:77
                                run_command! at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/commands/commands_tasks.rb:49
                                       <top> at /Users/mymac/.rvm/gems/jruby-9.0.5.0@rails-5-test/gems/railties-5.0.0.beta3/lib/rails/command.rb:20
                                     require at org/jruby/RubyKernel.java:937
                                       <top> at bin/rails:9`

System configuration

Rails version: 5.0.0.beta3

Ruby version: JRuby 9.0.5.0

Additional Info

This bug is also shown here: rails/rails#23975

I'm reporting this bug here because of the comment left by @jensnockert who said:

If you replace the 'offending' code with some string manipulation you get the following stacktrace which is probably closer to revealing the JRuby bug behind this.

LocalJumpError: yield called out of block
/Users/Jens/.rvm/gems/jruby-9.0.5.0/gems/activesupport-5.0.0.beta2/lib/active_support/evented_file_update_checker.rb:130:in `existing_parent'
/Users/Jens/.rvm/gems/jruby-9.0.5.0/gems/activesupport-5.0.0.beta2/lib/active_support/evented_file_update_checker.rb:74:in `block in directories_to_watch'
/Users/Jens/.rvm/gems/jruby-9.0.5.0/gems/activesupport-5.0.0.beta2/lib/active_support/evented_file_update_checker.rb:74:in `directories_to_watch'
@enebo enebo added this to the JRuby 9.1.0.0 milestone Mar 14, 2016
@kares kares added the Rails label Mar 21, 2016
@headius
Copy link
Member

headius commented Apr 19, 2016

I get a different error for this now. I'm not sure if we're getting farther or not as far:

[] ~/projects/jruby/rails_5_test $ rails c
DEPRECATION WARNING: alias_method_chain is deprecated. Please, use Module#prepend instead. From module, you can access the original method using super. (called from <top> at /Users/headius/projects/jruby/rails_5_test/config/application.rb:17)
Bundler::GemRequireError: There was an error while trying to load the gem 'activerecord-jdbcsqlite3-adapter'.
                      block in require at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.11.2/lib/bundler/runtime.rb:81
                                  each at org/jruby/RubyArray.java:1593
                      block in require at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.11.2/lib/bundler/runtime.rb:72
                                  each at org/jruby/RubyArray.java:1593
                               require at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.11.2/lib/bundler/runtime.rb:61
                               require at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.11.2/lib/bundler.rb:99
                                 <top> at /Users/headius/projects/jruby/rails_5_test/config/application.rb:17
                               require at org/jruby/RubyKernel.java:944
                                (root) at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/railties-5.0.0.beta3/lib/rails/commands/commands_tasks.rb:1
  require_application_and_environment! at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/railties-5.0.0.beta3/lib/rails/commands/commands_tasks.rb:156
                               console at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/railties-5.0.0.beta3/lib/rails/commands/commands_tasks.rb:77
                          run_command! at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/railties-5.0.0.beta3/lib/rails/commands/commands_tasks.rb:49
                                 <top> at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/railties-5.0.0.beta3/lib/rails/command.rb:20
                               require at org/jruby/RubyKernel.java:944
                                 <top> at bin/rails:4

@headius
Copy link
Member

headius commented Apr 22, 2016

Ok wow, when I actually try this with 9.0.5 I can even get a weird error with a simple case taken directly from the code:

$ jruby -e '"foo".sub(/\A\./, '')'
ArgumentError: wrong number of arguments (1 for 2)
   sub! at org/jruby/RubyString.java:2217
    sub at org/jruby/RubyString.java:2195
  <top> at -e:1

Something's getting routed weird in sub.

@brianbroderick
Copy link
Author

I think that is an issue with the apostrophes.
Changing it to this works:

jruby -e '"foo".sub(/\A\./,"")'

@headius
Copy link
Member

headius commented Apr 22, 2016

Oh nice catch...continuing to investigate.

@headius
Copy link
Member

headius commented Apr 22, 2016

I can reproduce with rails c and get the following for a "full" stacktrace:

$ JRUBY_OPTS=-Xbacktrace.style=full rails c
ArgumentError: wrong number of arguments calling `sub` (0 for 1)
                               getStackTrace at java/lang/Thread.java:1552
                            getBacktraceData at org/jruby/runtime/backtrace/TraceType.java:215
                                getBacktrace at org/jruby/runtime/backtrace/TraceType.java:47
                            prepareBacktrace at org/jruby/RubyException.java:225
                                    preRaise at org/jruby/exceptions/RaiseException.java:229
                                    preRaise at org/jruby/exceptions/RaiseException.java:196
                                      <init> at org/jruby/exceptions/RaiseException.java:111
                           newRaiseException at org/jruby/Ruby.java:4066
                            newArgumentError at org/jruby/Ruby.java:3548
                          raiseArgumentError at org/jruby/runtime/Arity.java:274
                          raiseArgumentError at org/jruby/internal/runtime/methods/JavaMethod.java:267
                                        call at org/jruby/internal/runtime/methods/JavaMethod.java:604
                                        call at org/jruby/internal/runtime/methods/DynamicMethod.java:193
                                        call at org/jruby/internal/runtime/methods/DynamicMethod.java:189
                                cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:293
                                        call at org/jruby/runtime/callsite/CachingCallSite.java:131
                                        call at org/jruby/runtime/callsite/RefinedCachingCallSite.java:67
                                   interpret at org/jruby/ir/instructions/CallBase.java:414
                                 processCall at org/jruby/ir/interpreter/InterpreterEngine.java:348
                                   interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
                                   interpret at org/jruby/ir/interpreter/InterpreterEngine.java:86
                            INTERPRET_METHOD at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:210
                         normalize_extension at /Users/headius/.rvm/gems/jruby-9.0.5.0/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:97
                                        call at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:196
                                        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
                                 processCall at org/jruby/ir/interpreter/InterpreterEngine.java:316
                                   interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
                             INTERPRET_BLOCK at org/jruby/ir/interpreter/Interpreter.java:132
                         block in initialize at /Users/headius/.rvm/gems/jruby-9.0.5.0/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:13

So it seems like it's having some trouble with the incoming argument list actually not matching the method's arity. The JavaMethod line 604 here is basically the error case when a 1 or 2-argument target does not receive 1 or 2 arguments.

The line of code triggering this obviously does pass two arguments, so we have a conundrum.

@headius
Copy link
Member

headius commented Apr 22, 2016

Ok, the main issue here is actually caused by our poor support for refinements.

Earlier in the PathHelper class, where this method normalize_extension lives, there's a refinement of Pathname to add one method:

    class PathHelper
      using Module.new {
        refine Pathname do
          def ascendant_of?(other)
            self != other && other.ascend do |ascendant|
              break true if self == ascendant
            end
          end
        end
      }

      def xpath(path)
        Pathname.new(path).expand_path
      end

      def normalize_extension(ext)
        ext.to_s.sub(/\A\./, '')
      end

As a result of this using call, all methods in this scope become "potentially refined" and go through different logic, which currently is known to have bugs.

I modified it to just directly monkey-patch, and @tenderlove is working on a patch to just remove the gratuitous use of refinements here. Either way I can get past this point. Here's my change:

    class PathHelper
      class ::Pathname
        def ascendant_of?(other)
          self != other && other.ascend do |ascendant|
            break true if self == ascendant
          end
        end
      end

This leads to a new error that seems to be an issue in dependency resolution:

$ JRUBY_OPTS='-X-C -Xbacktrace.style=full' rails c
LoadError: no such file to load -- listen
                               getStackTrace at java/lang/Thread.java:1552
                            getBacktraceData at org/jruby/runtime/backtrace/TraceType.java:215
                                getBacktrace at org/jruby/runtime/backtrace/TraceType.java:47
                            prepareBacktrace at org/jruby/RubyException.java:225
                                    preRaise at org/jruby/exceptions/RaiseException.java:229
                                    preRaise at org/jruby/exceptions/RaiseException.java:196
                                      <init> at org/jruby/exceptions/RaiseException.java:111
                           newRaiseException at org/jruby/Ruby.java:4066
                                newLoadError at org/jruby/Ruby.java:3916
                               requireCommon at org/jruby/runtime/load/LoadService.java:414
                                     require at org/jruby/runtime/load/LoadService.java:392
                               requireCommon at org/jruby/RubyKernel.java:944
                                   require19 at org/jruby/RubyKernel.java:937
                                        call at org/jruby/internal/runtime/methods/JavaMethod.java:579
                                        call at org/jruby/internal/runtime/methods/AliasMethod.java:101
                                        call at org/jruby/internal/runtime/methods/AliasMethod.java:101
                             unresolvedSuper at org/jruby/ir/runtime/IRRuntimeHelpers.java:965
                                   interpret at org/jruby/ir/instructions/ZSuperInstr.java:71
                                 processCall at org/jruby/ir/interpreter/InterpreterEngine.java:348
                                   interpret at org/jruby/ir/interpreter/InterpreterEngine.java:161
                             INTERPRET_BLOCK at org/jruby/ir/interpreter/Interpreter.java:132
                            block in require at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/activesupport-5.0.0.beta3/lib/active_support/dependencies.rb:302
                                 yieldDirect at org/jruby/runtime/InterpretedIRBlockBody.java:109
                               yieldSpecific at org/jruby/runtime/IRBlockBody.java:73
                               yieldSpecific at org/jruby/runtime/Block.java:135
                               yieldSpecific at org/jruby/ir/runtime/IRRuntimeHelpers.java:480
                                   interpret at org/jruby/ir/instructions/YieldInstr.java:73
                              processOtherOp at org/jruby/ir/interpreter/InterpreterEngine.java:550
                                   interpret at org/jruby/ir/interpreter/InterpreterEngine.java:203
                                   interpret at org/jruby/ir/interpreter/InterpreterEngine.java:86
                            INTERPRET_METHOD at org/jruby/internal/runtime/methods/InterpretedIRMethod.java:189
                             load_dependency at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/activesupport-5.0.0.beta3/lib/active_support/dependencies.rb:268
                                        call at org/jruby/internal/runtime/methods/InterpretedIRMethod.java:180
                                cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:323
                                   callBlock at org/jruby/runtime/callsite/CachingCallSite.java:173
                                        call at org/jruby/runtime/callsite/CachingCallSite.java:177
                                 processCall at org/jruby/ir/interpreter/InterpreterEngine.java:325
                                   interpret at org/jruby/ir/interpreter/InterpreterEngine.java:161
                                   interpret at org/jruby/ir/interpreter/InterpreterEngine.java:86
                            INTERPRET_METHOD at org/jruby/internal/runtime/methods/InterpretedIRMethod.java:189
                                     require at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/activesupport-5.0.0.beta3/lib/active_support/dependencies.rb:302
                                        call at org/jruby/internal/runtime/methods/InterpretedIRMethod.java:180
                                        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
                                 processCall at org/jruby/ir/interpreter/InterpreterEngine.java:316
                                   interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
                             INTERPRET_BLOCK at org/jruby/ir/interpreter/Interpreter.java:132
                         block in initialize at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:24

The line that triggers the eventual require of "listen" appears to be a super inside a block, which may be the same issue as #3643 (in that bug, a super method seems to "disappear" at runtime).

Because this will get fixed for Rails 5 final (assuming @tenderlove's fix is not reverted), this is now just a refinements bug and may be punted to 9.1.1.

@headius
Copy link
Member

headius commented Apr 22, 2016

Ok, I figured out the weird arity error...RefinedCachingCallSite was failing to pass on varargs when dispatching to the original method.

We still have refinements issues that prevent this code from working, but that's one fix at least!

headius added a commit that referenced this issue Apr 22, 2016
This fixes the arity issue in #3733, but there's other refinement
bugs preventing the referenced code from working.
@headius
Copy link
Member

headius commented Apr 22, 2016

After fixing the arity issue, we are back to a more standard refinement bug, where it can't see the added method at call sites where it should.

Here's the error:

$ JRUBY_OPTS='-X-C -Xbacktrace.style=full' rails c
NoMethodError: undefined method `ascendant_of?' for #<Pathname:0x1f2d2181>
                               getStackTrace at java/lang/Thread.java:1552
                            getBacktraceData at org/jruby/runtime/backtrace/TraceType.java:215
                                getBacktrace at org/jruby/runtime/backtrace/TraceType.java:47
                            prepareBacktrace at org/jruby/RubyException.java:225
                                    preRaise at org/jruby/exceptions/RaiseException.java:229
                                    preRaise at org/jruby/exceptions/RaiseException.java:196
                                      <init> at org/jruby/exceptions/RaiseException.java:141
                                      <init> at org/jruby/exceptions/RaiseException.java:72
                               methodMissing at org/jruby/RubyKernel.java:265
                                        call at org/jruby/RubyKernel.java:114
                                        call at org/jruby/internal/runtime/methods/DynamicMethod.java:201
                           callMethodMissing at org/jruby/runtime/callsite/CachingCallSite.java:388
                                cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:310
                                        call at org/jruby/runtime/callsite/CachingCallSite.java:163
                                        call at org/jruby/runtime/callsite/RefinedCachingCallSite.java:136
                                 processCall at org/jruby/ir/interpreter/InterpreterEngine.java:316
                                   interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:77
                             INTERPRET_BLOCK at org/jruby/ir/interpreter/Interpreter.java:132
             block in longest_common_subpath at /Users/headius/projects/jruby/lib/ruby/gems/shared/gems/activesupport-5.0.0.beta3/lib/active_support/evented_file_update_checker.rb:108

And the code that triggers it (with Pathname refined as shown in my earlier comment):

      # Given a collection of Pathname objects returns the longest subpath
      # common to all of them, or +nil+ if there is none.
      def longest_common_subpath(paths)
        return if paths.empty?

        lcsp = Pathname.new(paths[0])

        paths[1..-1].each do |path|
          until lcsp.ascendant_of?(path)
            if lcsp.root?
              # If we get here a root directory is not an ascendant of path.
              # This may happen if there are paths in different drives on
              # Windows.
              return
            else
              lcsp = lcsp.parent
            end
          end
        end

        lcsp
      end

This remaining bug may be duplicated by other refinement issues, like #3548.

headius added a commit that referenced this issue Apr 22, 2016
@headius
Copy link
Member

headius commented Apr 22, 2016

The additional refinement issue is now fixed via 745654f.

Testing against 9.1 shows none of the refinement-related errors, and goes straight to the issue in #3823. I consider this particular bug fixed.

@headius headius closed this as completed Apr 22, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants