Getting `Rubinius::ToolSet::Runtime::CompileError` from some of rspec-expectations files #2934

Open
myronmarston opened this Issue Feb 10, 2014 · 37 comments

Projects

None yet

10 participants

@myronmarston

For RSpec's travis builds we've started getting Rubinius::ToolSet::Runtime::CompileError errors for some files from rspec-expectations. It's inconsistent, though; originally it happened once or twice and appeared to be purely transient because the build would pass on retry, but now it's happening much more consistently.

Note that it varies which file in rspec-expectations triggers the compile error; for example, in this build it's match.rb but in this build it's contain_exactly.rb.

These files are loaded lazily via autoload so the failure happens the first time the named matcher is used. After that, the constant remains undefined so the build gets "Missing or uninitialized constant: ..." NameErrors for any later use of the matcher that failed to compile.

For both of these specific build failure examples, travis reports this rubinius version:

rubinius 2.2.5 (2.1.0 e543ba32 2014-02-08 JI) [x86_64-linux-gnu]
@myronmarston myronmarston added a commit to rspec/rspec-dev that referenced this issue Feb 10, 2014
@myronmarston myronmarston Add rbx to list of allowed failures.
We're getting odd compile errors from rubinius:

rubinius/rubinius#2934
fca371b
kiela commented Feb 13, 2014

It also does not work with have.rb in this build. Also tried with eq.rb and eql.rb and got very the same error.

@kiela kiela added a commit to kiela/guard-migrate that referenced this issue Feb 13, 2014
@kiela kiela Fix Rubinius issue with autoloading while running tests
The issue is described in: rubinius/rubinius#2934
b868a12
sikachu commented Feb 28, 2014

I can confirm I'm getting this error on 2.2.5 as well: https://gist.github.com/sikachu/ff4ab66b900290ceea64

@sikachu sikachu added a commit to thoughtbot/appraisal that referenced this issue Feb 28, 2014
@sikachu sikachu Fix build error on Rubinius by requiring matcher
There was some problem with class autoloading in Rubinius, which can be
workaround by just requiring that missing file.

See rubinius/rubinius#2934
33775b4
sikachu commented Feb 28, 2014

I managed to get the test pass by explicitly requiring that file in the test. See thoughtbot/appraisal@33775b4 and https://travis-ci.org/thoughtbot/appraisal/jobs/19821160

Is autoload not supported on rubinius?

BTW, thanks @sikachu. It's nice in rspec-expectations to be able to use autoload so that it boots faster and doesn't bother loading matchers the user doesn't use, but we may have to switch it to not autoload on rubinius.

Owner

@myronmarston It is as far as I'm aware of. It could be a race condition with the autoloading system, but it's hard to tell without some digging around.

Owner

I did some digging around and it seems that autoloading is not thread-safe under Rubinius. Although I could not get rspec to fail I managed to whip together the following script:

require 'rspec'

threads = []

100.times do
  threads << Thread.new { sleep(rand); RSpec::Matchers::BuiltIn::Match }
end

threads.each(&:join)

Running this script under Rubinius will work most of the time. However, once in a while the following error occurs:

An exception occurred running /tmp/repro.rb:

    Missing or uninitialized constant: RSpec::Matchers::BuiltIn::Match (NameError)

Backtrace:

      Module#const_missing at kernel/common/module.rb:667
  { } in Object#__script__ at /tmp/repro.rb:6
                 Proc#call at kernel/bootstrap/proc.rb:20
            Thread#__run__ at kernel/bootstrap/thread.rb:391

I suspect that a similar problem is causing the compiler to break. That is, N threads try to autoload the same file with slightly different timings. As a result the compiler might think that everything it needs is there when in reality it's not there yet. This is however just a theory, I'm not very familiar with the autoloading system (yet) so I can't tell for certain.

Thanks for looking into this.

We don't do any multithreading in RSpec (or in our test suite), though, so I doubt this is the root cause of our issue.

Owner

The following is mostly a personal note / note for other contributors.


I did some poking around in https://github.com/rubinius/rubinius/blob/master/kernel/common/autoload.rb as it looks prone to potential race conditions. For example, the #resolve method has a check to see if something loaded. However, there's nothing put in place to ensure this check works as intended when this method is called by multiple threads. That is, there's no locking going on anywhere.

I messed around with putting locks in place, both instance and class wide locks, but to no avail. I suspect that the actual race condition in rspec occurs earlier somewhere in the Rbx chain. It's also interesting that there are multiple Autoload instances present in the average Rbx process. The details are not clear to me so I'll assume this is intended.

Either way, looking at this autoloading code I strongly feel it's not thead-safe and thus, sometimes, might cause problems. For example, two threads try to autoload a file and one sets something like @loaded to true. Next comes in the second thread, which thinks the file is loaded (when it's not yet) and goes to the compiler. The compiler then tries to compile a non existing block of code and promptly fails.

Note that this is merely a theory. It could very well be something else, but it just has "autoloading" and "thread safety" written all over it.

Owner
dbussink commented Mar 6, 2014

There are actually specs for autoload thread safety that we're passing and issues in this have been fixed before. It's not a simple / trivial case here. The locking logic happens around require requests here: https://github.com/rubinius/rubinius/blob/master/kernel/common/code_loader.rb#L31-L91.

The spec for this can be found here: https://github.com/rubinius/rubinius/blob/master/spec/ruby/core/module/autoload_spec.rb#L457-L503

Also if RSpec runs single threaded, this is very like a different problem and not a concurrent autoload issue.

@kiela kiela referenced this issue in guard/guard Mar 6, 2014
Merged

Delete specifying RSpec dependency twice #567

Hi getting the "uninitialized constant Rubinius::ToolSets" error when building:

I also installed the "rubinius-toolset" gem manually to make it work.

"rake --trace" output:
https://gist.github.com/brixen/9530938

Owner

@ali-bugdayci That is a separate issue that should be resolved in 2.2.6. Please try said version and report it as a separate issue if the problem persists.

@YorickPeterse I had a different problem with 2.2.6, hence tried 2.2.5,

I am getting "Error libc not found" error on 2.2.6 build. I already have build-essentials package on ubuntu 12.10.

By the way, the requirements section might need a change, since I apply them all: http://rubini.us/doc/en/getting-started/requirements/

Owner

@all-bugdayci Please report this problem in a separate issue as it's not related (from what I can tell) to the issue experienced by OP.

We're getting this error in another spot which is not using autoload so it appears to be a general code loading issue and not just an autoload issue. This travis build (of rspec-core's 2-14-maintenance branch) got this failure:

  1) autotest/discover.rb with ./.rspec present adds 'rspec2' to the list of discoveries
     Failure/Error: load File.expand_path("../../../lib/autotest/discover.rb", __FILE__)
     Rubinius::ToolSets::Runtime::CompileError:
       Error trying to compile /home/travis/build/rspec/rspec-core/lib/autotest/discover.rb
     # /home/travis/.rvm/rubies/rbx-2.2.6/runtime/gems/rubinius-compiler-2.1.0/lib/rubinius/compiler/compiler.rbc:13:in `compiler_error'
     # /home/travis/.rvm/rubies/rbx-2.2.6/runtime/gems/rubinius-compiler-2.1.0/lib/rubinius/compiler/compiler.rbc:95:in `compile'
     # kernel/delta/code_loader.rb:217:in `compile_file'
     # kernel/delta/code_loader.rb:190:in `load_file'
     # kernel/common/code_loader.rb:153:in `load'
     # kernel/common/kernel.rb:445:in `load'
     # ./spec/autotest/discover_spec.rb:8:in `__script__'
     # kernel/common/eval.rb:43:in `instance_eval'
     # ./lib/rspec/core/example.rb:114:in `run'
     # kernel/bootstrap/proc.rb:20:in `call'
     # ./lib/rspec/core/example.rb:179:in `run'
     # ./spec/spec_helper.rb:102:in `__script__'
     # kernel/common/eval.rb:43:in `instance_eval'
     # ./spec/spec_helper.rb:57:in `sandboxed'
     # ./spec/support/sandboxed_mock_space.rb:38:in `sandboxed'
     # ./spec/spec_helper.rb:56:in `sandboxed'
     # ./spec/spec_helper.rb:102:in `__script__'
     # kernel/common/eval.rb:101:in `instance_exec'
     # ./lib/rspec/core/extensions/instance_eval_with_args.rb:16:in `instance_eval_with_args'
     # ./lib/rspec/core/example.rb:247:in `instance_eval_with_args'
     # ./lib/rspec/core/hooks.rb:106:in `run'
     # kernel/bootstrap/proc.rb:20:in `call'
     # ./lib/rspec/core/hooks.rb:104:in `run'
     # ./lib/rspec/core/hooks.rb:446:in `run_hook'
     # ./lib/rspec/core/example_group.rb:340:in `run_around_each_hooks'
     # ./lib/rspec/core/example.rb:256:in `with_around_each_hooks'
     # ./lib/rspec/core/example.rb:111:in `run'
     # ./lib/rspec/core/example_group.rb:390:in `run_examples'
     # kernel/bootstrap/array.rb:87:in `map'
     # ./lib/rspec/core/example_group.rb:386:in `run_examples'
     # ./lib/rspec/core/example_group.rb:371:in `run'
     # ./lib/rspec/core/example_group.rb:372:in `run'
     # kernel/bootstrap/array.rb:87:in `map'
     # ./lib/rspec/core/example_group.rb:372:in `run'
     # ./lib/rspec/core/command_line.rb:28:in `run'
     # kernel/bootstrap/array.rb:87:in `map'
     # ./lib/rspec/core/command_line.rb:28:in `run'
     # ./lib/rspec/core/reporter.rb:58:in `report'
     # ./lib/rspec/core/command_line.rb:25:in `run'
     # ./lib/rspec/core/runner.rb:80:in `run'
     # ./lib/rspec/core/runner.rb:17:in `autorun'
     # kernel/bootstrap/proc.rb:20:in `call'
     # kernel/loader.rb:710:in `run_at_exits'
     # kernel/loader.rb:730:in `epilogue'
     # kernel/loader.rb:866:in `main'

Notice that it's failing when using load, not autoload:

https://github.com/rspec/rspec-core/blob/a5eee8fe3b2a0a0abd71061fbc4292b7d21fa2b4/spec/autotest/discover_spec.rb#L8

The file being loaded is quite small:

https://github.com/rspec/rspec-core/blob/a5eee8fe3b2a0a0abd71061fbc4292b7d21fa2b4/lib/autotest/discover.rb

Owner

Experienced the same problem while trying to run an application in our staging environment: https://gist.github.com/YorickPeterse/95bf9eeef16f0b417f4e

Similar to the issue described by @myronmarston it does not seem to occur every time but instead semi-randomly.

Owner

Digging into this again, I'm pretty darn sure this is a thread-safety problem. To help debug I patched kernel/common/module.rb using the following patch:

diff --git a/kernel/common/module.rb b/kernel/common/module.rb
index 0d0e6a8..3d2152a 100644
--- a/kernel/common/module.rb
+++ b/kernel/common/module.rb
@@ -664,6 +664,9 @@ class Module
       msg = "Missing or uninitialized constant: #{mod_name}#{name}"
     end

+    puts "NameError: #{name}: #{msg} | Thread: #{Thread.current.instance_variable_get(:@thread_id)}"
+    puts caller
+
     raise NameError.new(msg, name)
   end

Running the script pasted above I sometimes (not always) get the following output:

NameError: Test: Missing or uninitialized constant: RSpec::Core::Pending::Test | Thread: 1
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:15:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:3:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:2:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:1:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core.rb:3:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core.rb:30:in `__script__'
/home/yorickpeterse/.rubies/rbx-git/library/rubygems/core_ext/kernel_require.rb:73:in `require'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-3.0.0.beta2/lib/rspec.rb:1:in `__script__'
/home/yorickpeterse/.rubies/rbx-git/library/rubygems/core_ext/kernel_require.rb:135:in `require'
/tmp/test.rb:1:in `__script__'
NameError: BuiltIn: Missing or uninitialized constant: RSpec::Matchers::BuiltIn | Thread: 40
/tmp/test.rb:6:in `__script__'
NameError: Match: Missing or uninitialized constant: RSpec::Matchers::BuiltIn::Match | Thread: 12
/tmp/test.rb:6:in `__script__'
An exception occurred running /tmp/test.rb:

    Missing or uninitialized constant: RSpec::Matchers::BuiltIn::Match (NameError)

Backtrace:

      Module#const_missing at kernel/common/module.rb:670
  { } in Object#__script__ at /tmp/test.rb:6
                 Proc#call at kernel/bootstrap/proc.rb:20
            Thread#__run__ at kernel/bootstrap/thread.rb:391

The first NameError is always there and doesn't break anything by the looks of it. The NameErrors after that one are only sometimes present. The amount of errors also varies, sometimes only 2, sometimes 5, etc.

Owner

Another output sample where the script fails:

NameError: Test: Missing or uninitialized constant: RSpec::Core::Pending::Test | Thread: 1
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:15:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:3:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:2:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:1:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core.rb:3:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core.rb:30:in `__script__'
/home/yorickpeterse/.rubies/rbx-git/library/rubygems/core_ext/kernel_require.rb:73:in `require'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-3.0.0.beta2/lib/rspec.rb:1:in `__script__'
/home/yorickpeterse/.rubies/rbx-git/library/rubygems/core_ext/kernel_require.rb:135:in `require'
/tmp/test.rb:1:in `__script__'
NameError: BuiltIn: Missing or uninitialized constant: RSpec::Matchers::BuiltIn | Thread: 27
/tmp/test.rb:6:in `__script__'
An exception occurred running /tmp/test.rb:

    Missing or uninitialized constant: RSpec::Matchers::BuiltIn (NameError)

Backtrace:

      Module#const_missing at kernel/common/module.rb:670
  { } in Object#__script__ at /tmp/test.rb:6
                 Proc#call at kernel/bootstrap/proc.rb:20
            Thread#__run__ at kernel/bootstrap/thread.rb:391
Owner

And the last one:

NameError: Test: Missing or uninitialized constant: RSpec::Core::Pending::Test | Thread: 1
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:15:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:3:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:2:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core/pending.rb:1:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core.rb:3:in `__script__'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-core-3.0.0.beta2/lib/rspec/core.rb:30:in `__script__'
/home/yorickpeterse/.rubies/rbx-git/library/rubygems/core_ext/kernel_require.rb:73:in `require'
/home/yorickpeterse/.gem/rbx/2.1.0/gems/rspec-3.0.0.beta2/lib/rspec.rb:1:in `__script__'
/home/yorickpeterse/.rubies/rbx-git/library/rubygems/core_ext/kernel_require.rb:135:in `require'
/tmp/test.rb:1:in `__script__'
NameError: BuiltIn: Missing or uninitialized constant: RSpec::Matchers::BuiltIn | Thread: 91
/tmp/test.rb:6:in `__script__'
NameError: BuiltIn: Missing or uninitialized constant: RSpec::Matchers::BuiltIn | Thread: 49
/tmp/test.rb:6:in `__script__'
NameError: BuiltIn: Missing or uninitialized constant: RSpec::Matchers::BuiltIn | Thread: 46
/tmp/test.rb:6:in `__script__'
An exception occurred running /tmp/test.rb:

    Missing or uninitialized constant: RSpec::Matchers::BuiltIn (NameError)

Backtrace:

      Module#const_missing at kernel/common/module.rb:670
  { } in Object#__script__ at /tmp/test.rb:6
                 Proc#call at kernel/bootstrap/proc.rb:20
            Thread#__run__ at kernel/bootstrap/thread.rb:391

Hmm, is Thread.current.instance_variable_get(:@thread_id) a rubinius thing that assigns ascending integers to threads? Never seen that before....

Anyhow, I searched through rspec-core, rspec-expectations, and rspec-mocks for Thread and found only two uses of that constant:

https://github.com/rspec/rspec-core/blob/77cc21e97a6e4c66acb21c8a89e8e45bffade820/lib/rspec/core.rb#L116

https://github.com/rspec/rspec-core/blob/77cc21e97a6e4c66acb21c8a89e8e45bffade820/spec/support/helper_methods.rb#L15

The first one isn't spawning threads; it's simply using thread local storage to be safe.

For the second, I think it's using a thread there because I believe $SAFE, while appearing to be a global, is scoped to the current thread and thus doing that prevents mutation of it from leaking to the main thread. Note that we immediately join on the thread there so I'm not sure how we could hit a race condition. On top of that, there are only 4 places in the spec suite that use that safely method, and looking at the failing builds, I'm seeing the compile error happen in other specs that don't use the safely method and thus aren't doing any multi-threading.

Could rubinius be doing some extra multi-threading under the covers as an implementation detail that could be causing this?

Owner

@myronmarston The @thread_id instance variable indeed is Rbx specific.

I'm not yet sure if the autoloading error is causing the compilation error, I'll need to do some further digging. At the moment I have two theories:

  1. Rubinius' autoloading in itself is not thread-safe
  2. Module#autoload is not thread-safe and registers multiple autoloaders for the same constant/path, I've yet to verify or rule this out. This could be problematic for nested autoload calls (e.g. an autoload for Foo and one for Foo::Bar).

Could rubinius be doing some extra multi-threading under the covers as an implementation detail that could be causing this?

Rubinius does use threads for a bunch of things, e.g. the JIT runs in its own thread and so does part of the GC I believe.

Owner

Patched Rubinius' Autoload class with the following:

diff --git a/kernel/common/autoload.rb b/kernel/common/autoload.rb
index d0ac53f..6ba95c4 100644
--- a/kernel/common/autoload.rb
+++ b/kernel/common/autoload.rb
@@ -14,6 +14,10 @@ class Autoload
   attr_reader :thread

   def initialize(name, scope, path)
+    if path.include?('rspec')
+      puts "Autoload.new(#{name.inspect}, #{scope.inspect}, #{path.inspect})"
+    end
+
     @name = name
     @scope = scope
     @path = path

This would display all the autoloading actions triggered in Rspec. The output is now as following:

Autoload.new(:DocumentationFormatter, RSpec::Core::Formatters, "rspec/core/formatters/documentation_formatter")
Autoload.new(:HtmlFormatter, RSpec::Core::Formatters, "rspec/core/formatters/html_formatter")
Autoload.new(:ProgressFormatter, RSpec::Core::Formatters, "rspec/core/formatters/progress_formatter")
Autoload.new(:JsonFormatter, RSpec::Core::Formatters, "rspec/core/formatters/json_formatter")
Autoload.new(:SharedContext, RSpec, "rspec/core/shared_context")
Autoload.new(:BeAKindOf, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be_kind_of")
Autoload.new(:BeAnInstanceOf, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be_instance_of")
Autoload.new(:BeBetween, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be_between")
Autoload.new(:Be, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be")
Autoload.new(:BeComparedTo, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be")
Autoload.new(:BeFalsey, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be")
Autoload.new(:BeNil, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be")
Autoload.new(:BePredicate, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be")
Autoload.new(:BeTruthy, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be")
Autoload.new(:BeWithin, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/be_within")
Autoload.new(:Change, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/change")
Autoload.new(:Compound, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/compound")
Autoload.new(:ContainExactly, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/contain_exactly")
Autoload.new(:Cover, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/cover")
Autoload.new(:EndWith, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/start_and_end_with")
Autoload.new(:Eq, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/eq")
Autoload.new(:Eql, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/eql")
Autoload.new(:Equal, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/equal")
Autoload.new(:Exist, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/exist")
Autoload.new(:Has, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/has")
Autoload.new(:Include, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/include")
Autoload.new(:Match, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/match")
Autoload.new(:NegativeOperatorMatcher, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/operators")
Autoload.new(:OperatorMatcher, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/operators")
Autoload.new(:Output, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/output")
Autoload.new(:PositiveOperatorMatcher, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/operators")
Autoload.new(:RaiseError, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/raise_error")
Autoload.new(:RespondTo, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/respond_to")
Autoload.new(:Satisfy, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/satisfy")
Autoload.new(:StartWith, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/start_and_end_with")
Autoload.new(:ThrowSymbol, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/throw_symbol")
Autoload.new(:YieldControl, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/yield")
Autoload.new(:YieldSuccessiveArgs, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/yield")
Autoload.new(:YieldWithArgs, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/yield")
Autoload.new(:YieldWithNoArgs, RSpec::Matchers::BuiltIn, "rspec/matchers/built_in/yield")
An exception occurred running /tmp/test.rb:

    Missing or uninitialized constant: RSpec::Matchers::BuiltIn::Match (NameError)

Backtrace:

      Module#const_missing at kernel/common/module.rb:667
  { } in Object#__script__ at /tmp/test.rb:6
                 Proc#call at kernel/bootstrap/proc.rb:20
            Thread#__run__ at kernel/bootstrap/thread.rb:391

Seeing how the same constant is not autoloaded twice (unless I missed something) I'll assume that the actual registering of constants is thread-safe. One other possibility is that the order in which constants are loaded messes things up somehow. Note that the output above is the order in which constants are registered opposed to the load order.

Locking in Autoload using Rubinius.synchronize(self) so far doesn't seem to have any effect.

Owner

Using the following patch:

diff --git a/kernel/common/autoload.rb b/kernel/common/autoload.rb
index d0ac53f..07f1778 100644
--- a/kernel/common/autoload.rb
+++ b/kernel/common/autoload.rb
@@ -31,6 +31,10 @@ class Autoload
   # When any code that finds a constant sees an instance of Autoload as its match,
   # it calls this method on us
   def call(under, honor_require=false)
+    if path.include?('rspec')
+      puts "Autoloading#call with #{name} in #{scope} from #{path} under #{under}"
+    end
+
     # We leave the Autoload object in the constant table so that if another
     # thread hits this while we're mid require they'll be come in here and
     # be held by require until @path is available, at which time they'll
@@ -49,6 +53,10 @@ class Autoload
   end

   def resolve
+    if path.include?('rspec')
+      puts "Autoloading#resolve with #{name} in #{scope} from #{path}"
+    end
+
     unless @loaded && @thread == Thread.current
       @loaded = true
       @thread = Thread.current

The output is now as following:

Autoloading#resolve with Match in RSpec::Matchers::BuiltIn from rspec/matchers/built_in/match
Autoloading#call with Match in RSpec::Matchers::BuiltIn from rspec/matchers/built_in/match under RSpec::Matchers::BuiltIn
Autoloading#resolve with Match in RSpec::Matchers::BuiltIn from rspec/matchers/built_in/match
An exception occurred running /tmp/test.rb:

    Missing or uninitialized constant: RSpec::Matchers::BuiltIn (NameError)

Backtrace:

      Module#const_missing at kernel/common/module.rb:667
  { } in Object#__script__ at /tmp/test.rb:6
                 Proc#call at kernel/bootstrap/proc.rb:20
            Thread#__run__ at kernel/bootstrap/thread.rb:391

Ran the script a few times and it seems that the amount of Autoload#resolve calls for the Match constant varies. However, it doesn't always fail if there are multiple calls.

Contributor

Hi there!

I don't know if it's due to the same bug (at least we don't have the same exception raised) but we also have a thread-safety issue with autoloading. At the moment, Action Pack's test suite runs in parallel with Minitest's parallelize_me! method.

The problem is that most constants are autoloaded and we have a ActionDispatch::Session constant (a module) and a ActionDispatch::Request::Session constant (a class which is autoloaded). When we are calling a method on the latter within ActionDispatch::Request, it is trying to call the method on the former (which doesn't respond to it). Here's a minimal reproduction gist to showcase the problem:

require 'minitest'
require 'minitest/autorun'

module A
  module C; end

  autoload :B, 'fake_file'

  class B
    autoload :C, 'c'

    def self.bar
      C.foo
    end
  end
end

class B < A::B; end

class FooTest < Minitest::Test
  def self.run_one_method(klass, method_name, reporter)
    Minitest.parallel_executor << [klass, method_name, reporter]
  end

  def test_b
    B.bar
  end
end

The self.run_one_method is pasted from Minitest ; it mimics a paralellize_me! call which will run tests inside separate threads. Here fake_file.rb is just an empty file and the c.rb file contains:

module A
  class B
    class C
      def self.foo; end
    end
  end
end

The interesting thing is that if we remove the autoload call on B or if we simply write the definition of C like class A::B::C, the problem goes away. Hoping it can help to track down the problem here.

Owner

@robin850 Hm, interesting. In my own experience autoload is definitely not thread-safe, even if we might claim otherwise.

Contributor
robin850 commented Mar 1, 2015

@YorickPeterse : Yep, it looks like. I don't know whether it could be useful but here's a more "ruby-ish" example that doesn't rely on Minitest to showcase the problem: https://gist.github.com/robin850/3eeaed2538f50a9887c2 ; you just need to run ruby -I"." foo.rb once the gist is cloned.

@robin850 robin850 added a commit to rails/rails that referenced this issue Mar 2, 2015
@robin850 robin850 Avoid parallelizing Action Pack's tests on Rubinius
Since the `ForkingExecutor` class seems to be pretty slow on Rubinius
due to DRb (c.f. http://git.io/xIVg), let's avoid running tests with
it on this platform.

Also, the `parallelize_me!` call make the suite to output a bunch of
errors due to rubinius/rubinius#2934 since there are thread-safety
problems with autoloading.
022c8be
Member
jemc commented Apr 24, 2015

@robin850 - can you verify that your repro still fails on rbx-master and open a new issue with a link to your repro so we can track work there?

Owner

The script @robin850 wrote still reproduces for me using rbx master.

Owner

In commit b57399f I made some changes to hopefully finally make autoloading fully thread-safe (famous last words). @myronmarston and @robin850: could you try to run your scripts using said commit and see if the issue still persists?

Owner

Hm, apparently the script discussed in #2934 (comment) still triggers a constant error. It appears this hydra grew a few extra heads.

I would try if I had such a script but I was never able to repro locally. The errors I saw only happened on travis.

@headius headius referenced this issue in jruby/jruby Apr 24, 2015
Closed

Possible autoload issue #2874

Contributor
headius commented Apr 24, 2015

As far as I can tell, RSpec::Matchers::Builtin contains no autoloads, and that's the constant that's going missing. I can even remove the last element and it still fails on JRuby and Rubinius. I'm not sure the script from #2934 (comment) is actually hitting any autoload-related bugs.

Contributor
headius commented Apr 27, 2015

I'm not sure if it explains the original issue, which is in a deeper namespace, but the logic for autoloading RSpec::Matcher is not thread-safe. See rspec/rspec-dev#121. It may not explain the original issue, but it does relieve Rubinius of any culpability in the RSpec::Matchers::BuiltIn error.

Owner

@headius Hm, interesting. I spent some time looking at Rubinius' find_const_fast instruction (used to retrieve the RSpec constant in the above script) but couldn't figure out what could be causing this error in said instruction. I hadn't realized RSpec uses a custom const_get.

I hadn't realized RSpec uses a custom const_get.

Yeah, it would be nice not to, but we haven't been able to come up with an alternate solution that both allows users to configure RSpec to use an alternates to rspec-expectations/rspec-mocks, while still making it "just work" for users who use the default stack. See my response on rspec/rspec-dev#121 for more detail.

If you want to test the RSpec::Matchers::BuiltIn autoloads like you originally intended to, I think you can just change the require in your script:

require 'rspec/matchers'

threads = []

100.times do
  threads << Thread.new { sleep(rand); RSpec::Matchers::BuiltIn::Match }
end

threads.each(&:join)

That'll avoid the const_missing/const_get piece @headius pointed out.

It may not explain the original issue, but it does relieve Rubinius of any culpability in the RSpec::Matchers::BuiltIn error.

Yep, I don't think it explains the Rubinius::ToolSet::Runtime::CompileError error I was originally reporting. In that case, the error is happening long after rspec/matchers has been loaded, when one of the RSpec::Matchers::BuiltIn constants is accessed for the first time.

Contributor
robin850 commented May 4, 2015

could you try to run your scripts using said commit and see if the issue still persists?

With current master (as of fbb3f1e), the given scripts are still failing unfortunately.

@ahmadsherif ahmadsherif added a commit that referenced this issue Feb 22, 2016
@ahmadsherif ahmadsherif Consider an autoload resolved if #resolve didn't return nil in Autolo…
…ad#call

This fixes cases of autoload "errors" mentioned by @robin850 in
#2934 (comment)
and https://gist.github.com/robin850/3eeaed2538f50a9887c2

This is an explanation of the issue:
We already have A::B been autoloaded by the main thread. When c.rb (see
any of the previous links) is being autoloaded in another thread, class
A::B is being opened using Rubinius.open_class_under (through
Rubinius.open_class).
Since module A has an Autoload entry for B in its constant_table,
open_class_under tries to call #call on this Autload object, which returns nil
because #resolve returns false (CodeLoader.require returns false
if a feature is already been loaded).
With nil returned, open_class_under decided to create a new Class object
for B, which means the autoload entry it already had for :C is lost,
resulting in constant A::B::C not being found.
01a7c2f
Member

After some digging, it may be not related to autoload. In one of the failing examples File.exist? is stubbed to return false, the parser uses this method to check for file existence, so it fails. I'm not sure what Rubinius can do for such cases.

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