Parallel tests sometimes get locked when the same file is loaded via active_support/dependencies/autoload, causing test timeout

[henrahmagix]

I'm not sure if this is an issue in Concurrent, or Zeitwerk, or both together, so I'm wondering if there's anything this library can do about this situation 🤔

To debug this, I've edited this gem's source: I changed WIPTest to take in the current thread, and Runner so when the 1.8 second process exit happens it prints the current trace of the test thread to see where it's gotten hung up.

This doesn't happen all the time, like ~30% based on my bunch of runs. It was happening in a project of mine, and I've been able to reduce it down to the following repo: https://github.com/henrahmagix/tldr-require-lock-test/tree/e9a5e45c02949c0773c47797e2beaab734589c5b. This is the smallest reproduction of my own project, which is a Railtie, hence require "rails/all" which I believe brings in Zeitwerk.

What do y'all think? Is this something that can be solved by TLDR? Or is it an unsolvable concurrency problem?

---

Here's a script to edit the tldr source to get the "WIP TRACE" output:

$ wip_test_file=$(bundle exec ruby -e 'require "tldr"; puts TLDR.const_source_location(:WIPTest)[0]')
$ runner_file=$(bundle exec ruby -e 'require "tldr"; puts TLDR.const_source_location(:Runner)[0]')
$ perl -p -i -e 's/:start_time/:start_time, :thread/' $wip_test_file
$ perl -p -i -e 's/WIPTest.new\(test, start_time\)/WIPTest.new(test, start_time, Thread.current)/' $runner_file
$ perl -p -i -e 's/( *)(\@run_aborted.make_true)/$1$2\n$1\@wip.each { |wip_test| puts "-----\\nWIP TRACE\\n  #{wip_test.thread.backtrace_locations&.join("\\n  ")}" }/' $runner_file

Here's the patch:

# lib/tldr/value/wip_test.rb
@@ -1,3 +1,3 @@
 class TLDR
-  WIPTest = Struct.new(:test, :start_time)
+  WIPTest = Struct.new(:test, :start_time, :thread)
 end

# lib/tldr/runner.rb
@@ -20,6 +20,7 @@
           next if ENV["CI"] && !$stderr.tty?
           next if @run_aborted.true?
           @run_aborted.make_true
+          @wip.each { |wip_test| puts "-----\nWIP TRACE\n  #{wip_test.thread.backtrace_locations&.join("\n  ")}" }
           reporter.after_tldr(plan.tests, @wip.dup, @results.dup)
           exit!(3)
         end
@@ -51,7 +52,7 @@
     def run_test test, config, plan, reporter
       e = nil
       start_time = Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
-      wip_test = WIPTest.new(test, start_time)
+      wip_test = WIPTest.new(test, start_time, Thread.current)
       @wip << wip_test
       runtime = time_it(start_time) do
         instance = test.test_class.new

Here's a failing run with the stack trace of each test thread: it can be seen that the lines each test is getting hung up on are at the point that the same constant, ActionView::Base, is being autoloaded either by referencing the constant and it gets autoloaded (via a call to t() as defined in another file, ActionView::Helpers::TranslationHelper), or it's directly required (via the require line in the test).

$ bin/tldr test.rb
Command: bundle exec tldr --no-warnings "test.rb"
🌱 --seed 1042

🏃 Running:

-----
WIP TRACE
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/actionview-7.1.2/lib/action_view/base.rb:141:in `<module:ActionView>'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/actionview-7.1.2/lib/action_view/base.rb:12:in `<top (required)>'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:38:in `require'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:38:in `require'
  /me/tldr-require-lock-test/test.rb:11:in `test_one'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:68:in `block in run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:100:in `time_it'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:57:in `run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:39:in `block in run'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `map'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `block (2 levels) in run_in_parallel'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1583:in `evaluate_to'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1766:in `block in on_resolvable'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'
-----
WIP TRACE
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:38:in `require'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:38:in `require'
  /me/tldr-require-lock-test/test.rb:15:in `test_two'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:68:in `block in run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:100:in `time_it'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:57:in `run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:39:in `block in run'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `map'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `block (2 levels) in run_in_parallel'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1583:in `evaluate_to'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1766:in `block in on_resolvable'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'
-----
WIP TRACE
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/actionview-7.1.2/lib/action_view/helpers/translation_helper.rb:153:in `missing_translation'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/actionview-7.1.2/lib/action_view/helpers/translation_helper.rb:104:in `translate'
  /me/tldr-require-lock-test/test.rb:23:in `test_three'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:68:in `block in run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:100:in `time_it'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:57:in `run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:39:in `block in run'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `map'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `block (2 levels) in run_in_parallel'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1583:in `evaluate_to'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1766:in `block in on_resolvable'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'
-----
WIP TRACE
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:38:in `require'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:38:in `require'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/actionview-7.1.2/lib/action_view/helpers/translation_helper.rb:153:in `missing_translation'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/actionview-7.1.2/lib/action_view/helpers/translation_helper.rb:104:in `translate'
  /me/tldr-require-lock-test/test.rb:31:in `test_four'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:68:in `block in run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:100:in `time_it'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:57:in `run_test'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/runner.rb:39:in `block in run'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `map'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/tldr-0.9.5/lib/tldr/executor.rb:36:in `block (2 levels) in run_in_parallel'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1583:in `evaluate_to'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/promises.rb:1766:in `block in on_resolvable'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'
  /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'
🥵

🚨==================== ABORTED RUN ====================🚨

too long; didn't run!

🏃 Completed 0 of 4 tests (0%) before running out of time.

🙅 4 tests were cancelled in progress:
  1812ms - Test#test_one [test.rb:10]
  1812ms - Test#test_two [test.rb:14]
  1812ms - Test#test_three [test.rb:18]
  1811ms - Test#test_four [test.rb:26]

🤘 Run the 4 tests that didn't finish:
  bundle exec tldr  "test.rb:10:14:18:26"


🙈 Suppress this summary with --yes-i-know

🚨==================== ABORTED RUN ====================🚨

Finished in 1814ms.

0 test classes, 0 test methods, 0 failures, 0 errors, 0 skips

$ sed -n -e '153p;' /me/.rbenv/versions/3.2.2/gemsets/tldr-require-lock-test/gems/actionview-7.1.2/lib/action_view/helpers/translation_helper.rb
          if ActionView::Base.debug_missing_translation

Sometimes I get uninitialised constant instead, which is perhaps the same parallelisation problem? I'm not sure 🤔

$ bin/tldr test.rb
Command: bundle exec tldr --no-warnings "test.rb"
🌱 --seed 407

🏃 Running:

🤬🤬😁😁

Failing tests:

1) Test#test_three [test.rb:20] errored:
uninitialized constant ActionView::Helpers::TranslationHelper

  Re-run this test:
    bundle exec tldr "test.rb:18"

2) Test#test_four [test.rb:28] errored:
uninitialized constant ActionView::Helpers::TranslationHelper

  Re-run this test:
    bundle exec tldr "test.rb:26"

Finished in 34ms.

1 test class, 4 test methods, 0 failures, 2 errors, 0 skips