From 0478b45fd369d0bf4b418d7424275bd27cab4320 Mon Sep 17 00:00:00 2001 From: Alan Guo Xiang Tan Date: Tue, 23 Jan 2024 06:55:49 +0800 Subject: [PATCH] DEV: Print out backtraces of all threads when spec times out on CI (#25356) Why this change? We have been seeing specs time out on GitHub CI but the problem is that we are unable to debug those timeouts due to a lack of information. This change seeks to print out the backtraces of all threads right before a spec times out on CI. What does this change do? 1. Starts a thread on CI which will wait for a spec to start running. 1. Once a spec starts running, the thread will sleep for `PER_SPEC_TIMEOUT_SECONDS -1` seconds. 1. After sleeping, the thread checks if the spec is still running and prints out the backtraces of all threads if it is. Otherwise, the thread does nothing and runs the next loop. 1. At the end of each spec run, we ensure that the thread is in a waiting state for the next spec run to start. Note that there is no need for us to teardown or cleanup the thread since the process terminates after running all the tests. --- spec/rails_helper.rb | 41 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 41 insertions(+) diff --git a/spec/rails_helper.rb b/spec/rails_helper.rb index 1674214dde4..fb976945605 100644 --- a/spec/rails_helper.rb +++ b/spec/rails_helper.rb @@ -458,14 +458,55 @@ RSpec.configure do |config| class SpecTimeoutError < StandardError end + mutex = Mutex.new + condition_variable = ConditionVariable.new + test_running = false + is_waiting = false + + backtrace_logger = + Thread.new do + loop do + mutex.synchronize do + is_waiting = true + condition_variable.wait(mutex) + is_waiting = false + end + + sleep PER_SPEC_TIMEOUT_SECONDS - 1 + + if mutex.synchronize { test_running } + puts "::group::[#{Process.pid}] Threads backtraces 1 second before timeout" + + Thread.list.each do |thread| + puts "\n" + thread.backtrace.each { |line| puts line } + puts "\n" + end + + puts "::endgroup::" + end + rescue StandardError => e + puts "Error in backtrace logger: #{e}" + end + end + config.around do |example| Timeout.timeout( PER_SPEC_TIMEOUT_SECONDS, SpecTimeoutError, "Spec timed out after #{PER_SPEC_TIMEOUT_SECONDS} seconds", ) do + mutex.synchronize do + test_running = true + condition_variable.signal + end + example.run rescue SpecTimeoutError + ensure + mutex.synchronize { test_running = false } + backtrace_logger.wakeup + sleep 0.01 while !mutex.synchronize { is_waiting } end end end