Rubygems.org: Flaky parallel pusher test

Created on 18 Jun 2019  路  5Comments  路  Source: rubygems/rubygems.org

I don't have way to reproduce this reliably.
Running just this one test always fails, however running with complete test suite passes.
Following is output from failied build on travis.

$ rails test test/unit/parallel_pusher_test.rb
<Thread:0x00000000063b9650@/home/travis/build/rubygems/rubygems.org/test/unit/parallel_pusher_test.rb:30 run> terminated with exception (report_on_exception is true):
/home/travis/build/rubygems/rubygems.org/app/models/pusher.rb:60:in `find': uninitialized constant Pusher::Rubygem (NameError)
    from /home/travis/build/rubygems/rubygems.org/app/models/pusher.rb:14:in `process'
    from /home/travis/build/rubygems/rubygems.org/test/unit/parallel_pusher_test.rb:31:in `block (3 levels) in <class:ParallelPusherTest>'

simi had suggested using Latch to simulate the exact order of critical operations resulting in race condition.

help wanted

Most helpful comment

I'm taking a look how to write this spec better. Now it is still random and now also broken :/ Feel free to assign this issue to me.

All 5 comments

I'm taking a look how to write this spec better. Now it is still random and now also broken :/ Feel free to assign this issue to me.

I tried reproducing this and got a different error

$ rails test test/unit/parallel_pusher_test.rb
/home/deivid/Code/rubygems.org/config/initializers/kaminari_config.rb:16: warning: already initialized constant Kaminari::Helpers::PARAM_KEY_EXCEPT_LIST
/home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/kaminari-core-1.2.0/lib/kaminari/helpers/tags.rb:5: warning: previous definition of PARAM_KEY_EXCEPT_LIST was here
Coverage report generated for Minitest, Unit Tests to /home/deivid/Code/rubygems.org/coverage. 71 / 3675 LOC (1.93%) covered.
Run options: --seed 57873

# Running:

#<Thread:0x0000561fd1289280@/home/deivid/Code/rubygems.org/test/unit/parallel_pusher_test.rb:30 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
    12: from /home/deivid/Code/rubygems.org/test/unit/parallel_pusher_test.rb:31:in `block (3 levels) in <class:ParallelPusherTest>'
    11: from /home/deivid/Code/rubygems.org/app/models/pusher.rb:15:in `process'
    10: from /home/deivid/Code/rubygems.org/app/models/pusher.rb:61:in `find'
     9: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.2/lib/active_support/dependencies.rb:214:in `const_missing'
     8: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/active_support.rb:60:in `load_missing_constant'
     7: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/active_support.rb:17:in `allow_bootsnap_retry'
     6: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/active_support.rb:61:in `block in load_missing_constant'
     5: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.2/lib/active_support/dependencies.rb:582:in `load_missing_constant'
     4: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.2/lib/active_support/dependencies.rb:214:in `const_missing'
     3: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/active_support.rb:60:in `load_missing_constant'
     2: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/active_support.rb:17:in `allow_bootsnap_retry'
     1: from /home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/active_support.rb:61:in `block in load_missing_constant'
/home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2.2/lib/active_support/dependencies.rb:543:in `load_missing_constant': Circular dependency detected while autoloading constant Rubygem (RuntimeError)
^CInterrupted. Exiting...


Finished in 5.021421s, 0.0000 runs/s, 0.0000 assertions/s.
0 runs, 0 assertions, 0 failures, 0 errors, 0 skips

As workarounds, both eagerly loading the relevant model:

diff --git a/test/unit/parallel_pusher_test.rb b/test/unit/parallel_pusher_test.rb
index 448e9ec7..d72a9429 100644
--- a/test/unit/parallel_pusher_test.rb
+++ b/test/unit/parallel_pusher_test.rb
@@ -1,6 +1,9 @@
 require "test_helper"
 require "concurrent/atomics"

+# Eager load version model to prevent autoloading race conditions
+require "version"
+
 class ParallelPusherTest < ActiveSupport::TestCase
   self.use_transactional_tests = false

or enabling zeitwerk reloading mode:

diff --git a/config/application.rb b/config/application.rb
index f4441431..3b9172a3 100644
--- a/config/application.rb
+++ b/config/application.rb
@@ -25,6 +25,9 @@ module Gemcutter
     # Initialize configuration defaults for originally generated Rails version.
     config.load_defaults 5.2

+    # Use new code reloading method.
+    config.autoloader = :zeitwerk
+
     # Settings in config/environments/* take precedence over those specified here.
     # Application configuration can go into files in config/initializers
     # -- all .rb files in that directory are automatically loaded after loading

fix the issue.

FWIW, I tried bin/rake zeitwerk:check and currently fails

$ bin/rake zeitwerk:check
/home/deivid/Code/rubygems.org/config/initializers/kaminari_config.rb:16: warning: already initialized constant Kaminari::Helpers::PARAM_KEY_EXCEPT_LIST
/home/deivid/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/kaminari-core-1.2.0/lib/kaminari/helpers/tags.rb:5: warning: previous definition of PARAM_KEY_EXCEPT_LIST was here
Hold on, I am eager loading the application.
rake aborted!
NameError: uninitialized constant Middleware::Hostess

Tasks: TOP => zeitwerk:check
(See full trace by running task with --trace)

So enabling zeitwerk will require some extra tweaks. So perhaps we could go with the first option for now.

Circular dependency detected while autoloading constant Rubygem (RuntimeError)

I am getting the same error as this now. I suppose this changed with rails update or something.
@simi had messaged me a patch which improves the ordering/latch part. I haven't verified if that fixes it as well.

I have spent some time around pusher recently, since it is still not bulletproof in parallel. I did some refactoring. I can try to find out my branch and push somewhere.

Was this page helpful?
0 / 5 - 0 ratings

Related issues

localhostdotdev picture localhostdotdev  路  8Comments

m1kit picture m1kit  路  5Comments

forced-request picture forced-request  路  6Comments

nicolasleger picture nicolasleger  路  10Comments

radar picture radar  路  5Comments