Multi-thread Backtrace for Silently Hanging Tests

Aji Slater

Scenario: You’re running your test suite. There are hundreds, if not thousands, of tests and assertions running in a new random order. Green dots fill your screen until… they don’t.

No new red dots, but no new green dots either.

Your tests are hanging. No amount of waiting sees them finish.

But without any feedback, how are you to know what to debug? How will you know what test is even causing the problem?

Solution: Put this snippet from @myronmarston into your test/test_helper.rb or spec/spec_helper.rb.

puts "test run pid: #{Process.pid}"

trap 'USR1' do
  threads = Thread.list

  puts
  puts "=" * 80
  puts "Received USR1 signal; printing all #{threads.count} thread backtraces."

  threads.each do |thr|
    description = thr == Thread.main ? "Main thread" : thr.inspect
    puts
    puts "#{description} backtrace: "
    puts thr.backtrace.join("\n")
  end

  puts "=" * 80
end

(original appearance of snippet: April 14, 2015 (Github))

Then when the tests hang, kill the process with kill -USR1 <pid> and voila! Backtraces (for every thread if it’s parallelized)!

Your terminal should look something like this. (filepaths truncated for legibility)

================================================================================
Received USR1 signal; printing all 14 thread backtraces.

Main thread backtrace:
...dev/project/test/test_helper.rb:348:in `backtrace'
...dev/project/test/test_helper.rb:348:in `block (2 levels) in <main>'
...project/test/test_helper.rb:344:in `each'
...project/test/test_helper.rb:344:in `block in <main>'
.../active_support/testing/parallelization/server.rb:59:in `sleep'
.../active_support/testing/parallelization/server.rb:59:in `shutdown'
.../active_support/testing/parallelization.rb:50:in `shutdown'
.../active_support/testing/parallelize_executor.rb:26:in `shutdown'
.../minitest-5.18.0/lib/minitest.rb:163:in `run'
.../minitest-5.18.0/lib/minitest.rb:83:in `block in autorun'

#<Thread:0x000000010a3953e0@DEBUGGER__::SESSION@server \
   .../debug/session.rb:154 sleep_forever> backtrace:
<internal:thread_sync>:18:in `pop'
.../gems/debug-1.6.3/lib/debug/session.rb:199:in `pop_event'
.../gems/debug-1.6.3/lib/debug/session.rb:203:in `session_server_main'
.../gems/debug-1.6.3/lib/debug/session.rb:174:in `block in activate'

#<Thread:0x000000010c6f9db8 .../connection_pool/reaper.rb:40 sleep> backtrace:
.../abstract/connection_pool/reaper.rb:46:in `help! I'm stuck in some ruby code`
.../abstract/connection_pool/reaper.rb:46:in `sleep'
.../abstract/connection_pool/reaper.rb:46:in `block in spawn_thread'

#<Thread:0x000000010e530db8 .../drb/drb.rb:1555 sleep> backtrace:
.../lib/ruby/3.2.0/drb/drb.rb:986:in `select'
.../lib/ruby/3.2.0/drb/drb.rb:986:in `accept_or_shutdown'
.../lib/ruby/3.2.0/drb/unix.rb:106:in `accept'
.../lib/ruby/3.2.0/drb/drb.rb:1714:in `main_loop'
.../lib/ruby/3.2.0/drb/drb.rb:1557:in `block in run'

For me, this helped me to realize the test runner wasn’t closing a connection to the DB properly. A quick brew services restart postgresql@14 fixed everything, a solution I never would have fathomed to attempt without a backtrace.