Debugger freezes when triggering timeout inside a timeout block with Puma server

[st0012]

Your environment

• ruby -v: 3.1.3
• rdbg -v: 1.7.1

Describe the bug

When the following conditions all match, the debugger has a high possibility to freeze:

• Inside a Rails app with Puma web server

• The breakpoint is inside a timeout call, like

   def hello
   Timeout.timeout(3600) do
   binding.b
   end
   end

• From the breakpoint, executes something that calls Timeout.timeout underneath

To Reproduce

I've documented reproduction steps in this repo.

Expected behavior

The debugger doesn't freeze.

Additional context

It may not be the root cause, but Timeout's thread being stopped by the debugger plays a major role here.

If we somehow modify this method to skip pausing the Timeout thread, like

 private def thread_stopper
 TracePoint.new(:line) do
 # run on each thread
 tc = ThreadClient.current
 next if tc.management?
 next unless tc.running?
 next if tc == @tc
 next if tc.thread.name && tc.thread.name.match?(/Timeout/)

 tc.on_pause
 end
 end

Then the issue doesn't occur.

[ko1]

Thank you for the report.

• Is it difficult to repro within a single file? (without puma)
• Can you show the backtrace when thread_stopper's TP stoppes?

by modifying like that:

 private def thread_stopper
 TracePoint.new(:line) do
 # run on each thread
 tc = ThreadClient.current
 next if tc.management?
 next unless tc.running?
 next if tc == @tc
 STDERR.puts caller.inspect if tc.thread.name.match?(/Timeout/)

 tc.on_pause
 end
 end

[ko1]

Anyway, I assume that it is difficult to fix in theory.

[st0012]

Is it difficult to repro within a single file? (without puma)

I tried it but didn't succeed. I suspect running it from a thread pool is one criteria and will experiment it later.

Can you show the backtrace when thread_stopper's TP stoppes?

"/Users/hung-wulo/.gem/ruby/3.1.2/gems/timeout-0.3.1/lib/timeout.rb:112:in `block (2 levels) in create_timeout_thread'", 
"/Users/hung-wulo/.gem/ruby/3.1.2/gems/timeout-0.3.1/lib/timeout.rb:111:in `synchronize'", 
"/Users/hung-wulo/.gem/ruby/3.1.2/gems/timeout-0.3.1/lib/timeout.rb:111:in `block in create_timeout_thread'"

Anyway, I assume that it is difficult to fix in theory.

Yeah I assumed that to be the case.

In the short-term I'll try to skip the Timeout thread pause to workaround it. Because many code paths in our app is wrapped inside a timeout block (from libs), and our devs constantly hang in those code paths.

[st0012]

Sorry for the delay, I managed to reproduce this with a single Ruby file:

# test.rb
def timeout
 Timeout.timeout(3) do
 puts "Something that needs timeout"
 end
end

Thread.new do
 Timeout.timeout(100) do
 binding.b
 end
end

# just to prevent the main thread from existing too early
sleep 100

$ rdbg -n test.rb

[4, 13] in test.rb
 4| end
 5| end
 6| 
 7| Thread.new do
 8| Timeout.timeout(100) do
=> 9| binding.b
 10| end
 11| end
 12| 
 13| # just to prevent the main thread from existing too early
=>#0 block in <main> (2 levels) at test.rb:9
 #1 block {|exc=#<Timeout::Error: Timeout::Error>|} in timeout at ~/.gem/ruby/3.1.2/gems/timeout-0.3.1/lib/timeout.rb:199
 # and 5 frames (use `bt' command for all frames)
(rdbg) timeout
Something that needs timeout
nil
(rdbg) timeout
# hangs

It produces like 9 out of 10 times.

And if it helps, here's the output with some debugging messages from my patch in timeout:

$ rdbg -n test.rb
QUEUE_MUTEX locked? false
[Timeout.timeout] acquiring QUEUE_MUTEX
[Timeout.timeout] released QUEUE_MUTEX
QUEUE_MUTEX locked? false
[Timeout thread] acquiring QUEUE_MUTEX
[4, 13] in test.rb
 4| end
 5| end
 6| 
 7| Thread.new do
 8| Timeout.timeout(100) do
=> 9| binding.b
 10| end
 11| end
 12| 
 13| # just to prevent the main thread from existing too early
=>#0 block in <main> (2 levels) at test.rb:9
 #1 block {|exc=#<Timeout::Error: Timeout::Error>|} in timeout at ~/.gem/ruby/3.1.2/gems/timeout-0.3.1/lib/timeout.rb:199
 # and 5 frames (use `bt' command for all frames)
(rdbg) timeout
QUEUE_MUTEX locked? false
[Timeout.timeout] acquiring QUEUE_MUTEX
[Timeout.timeout] released QUEUE_MUTEX
QUEUE_MUTEX locked? false
Something that needs timeout
nil
(rdbg) timeout
QUEUE_MUTEX locked? true
[Timeout.timeout] acquiring QUEUE_MUTEX

I think the main cause is that the timeout thread would acquire the QUEUE_MUTEX and never let go, likely because the thread would be frozen by then. So the later Timeout.timeout calls wouldn't be able to acquire the lock for synchronize.

But I don't understand why the first timeout call can still acquire the lock and it only deadlocks in the second call 🤔

[st0012]

The same problem doesn't seem to happen to byebug, even though it stops all threads as well.
It seems to use C-level APIs like rb_thread_stop for thread-control. I wonder if that'll be the solution for debug too?

[ko1]

Now I understand the problem.

Simplified code:

th0 = Thread.new{sleep}
m = Mutex.new
th1 = Thread.new do
 m.lock
 sleep 1
 m.unlock
end

sleep 0.5
debugger do: 'm.lock'

In this case,

(1) m is locked by th1
(2) main thread entered the REPL
(3) REPL runs m.lock but th1 doesn't resumed, and m.unlock is not called forever.
(*) Because of th0, deadlock detector doesn't raise an error because th0 can make progress.

---

• Solution 1: Restart all threads for the evaluation on REPL.
• Solution 2: Do not stop all threads except the running thread (in this case, main thread).
• Solution 3: Make timeout thread exceptional (do not stop)

(Solution 3) doesn't make sense because there are many similar cases.
(Solution 2) maybe make it difficult to debug thread programs.

So Solution 1? In fact the earlier versions restart all threads.

[st0012]

@ko1 I think the problem was not fully resolved with #947:

• In console, if you type Arrow-Up it would still hang. This is because when doing so, reline uses Timeout.timeout underneath.
  • For this problem we probably need a different solution? I'm not sure if we can detect the special keystrokes here to restart threads.
• In VS Code, evaluating local variables could also cause hanging. I'm not able to reproduce it as reliably, but I've seen it happened a few times.

Would you consider making Solution 2 a configurable option?