Deadlock on executing commands from binding.b in Rails app #725

ianterrell · 2022-07-21T14:50:55Z

Your environment

❯ ruby -v
ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [x86_64-darwin20]
❯ rdbg -v
rdbg 1.6.1

Describe the bug

When using binding.b in our Rails app — in various places: code run from test suites, code run from serving web requests — the debug REPL will hang.

Here is an example session entering the debugger from unit tests:

.[5, 14] in ~/src/debug_hang/app/models/concerns/debug_hang/sample_concern.rb
     5|     def respond_to_missing?(method, include_private = false)
     6|       method.to_s.start_with?("test_") || super
     7|     end
     8|
     9|     def method_missing(method, *args, &block)
=>  10|       binding.b
    11|
    12|       if method.to_s =~ /^test_/
    13|         puts "Running test: #{method}"
    14|         super
=>#0	DebugHang::SampleConcern#method_missing(method=:hang_the_debugger, args=[], block=nil) at ~/src/debug_hang/app/models/concerns/debug_hang/sample_concern.rb:10
  #1	block in <class:ExampleTest> at ~/src/debug_hang/test/models/example_test.rb:5
  # and 25 frames (use `bt' command for all frames)
(ruby) false == true
false
(ruby) false == true
["DEBUGGER Exception: /Users/ian/.rbenv/versions/3.1.2/lib/ruby/gems/3.1.0/gems/debug-1.6.1/lib/debug/thread_client.rb:1108",
 #<fatal: No live threads left. Deadlock?
20 threads, 20 sleeps current:0x00007f8590c458b0 main thread:0x00007f85f6c06d30
* #<Thread:0x0000000105c30ce8 sleep_forever>
   rb_thread_t:0x00007f85f6c06d30 native:0x0000000106beae00 int:0

full logfile

To Reproduce

git clone [email protected]:ianterrell/debug_hang.git
cd debug_hang
bundle install
rails db:create db:migrate
rails t

From debugger, repeatedly enter false == true.

Expected behavior

No deadlock.

Additional context

This looks like it could be related to binding.b(do: ...) hangs Rails with puma web server #248

The text was updated successfully, but these errors were encountered:

yshmarov · 2022-07-21T18:10:38Z

I'm experiencing the same issue right at this moment. When running some console commands the binding just dies out

rdbg 1.6.1
ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [arm64-darwin21]

I tried downgrading the gem to gem 'debug', '~> 1.5.0', '<= 1.6.0' => no deadlock

ianterrell · 2022-07-21T19:54:41Z

@yshmarov Thanks for noting the downgrade suggestion. My reproduction case succeeds on 1.5.0. Running against a local copy of debug and bisecting I get the first bad commit as 00ec229. That's a threading related commit, so it seems plausible.

❯ git bisect log
git bisect start
# bad: [4b50fc669e0c96284bfeb7f69f4ce0b5ddf19659] Fix rdbg's RUBYOPT handling logic
git bisect bad 4b50fc669e0c96284bfeb7f69f4ce0b5ddf19659
# good: [32eba515549eaf5f3eb841b19e3d339fe916c880] v1.5.0
git bisect good 32eba515549eaf5f3eb841b19e3d339fe916c880
# bad: [50763033fc661d5e72b5a3d470558e76a8f47dec] Centralize configuration defaults (#642)
git bisect bad 50763033fc661d5e72b5a3d470558e76a8f47dec
# good: [a2c95efc8722000e5cf89460c04e037008447b2c] Update CONTRIBUTING.md
git bisect good a2c95efc8722000e5cf89460c04e037008447b2c
# bad: [39f21d90c68856cc3ee7cd7cf77a7b73ba9959ec] Add debug logging
git bisect bad 39f21d90c68856cc3ee7cd7cf77a7b73ba9959ec
# bad: [f4b267d6d3b33ab16e9f9e7de526bd13b326d92f] Rename WebSocketClient#cleanup to #close because it's all it does
git bisect bad f4b267d6d3b33ab16e9f9e7de526bd13b326d92f
# bad: [b0d34c629047375290c4d5f8f0f3c243bdc79e67] restart_all_threads should send cmd to all tcs instead of @tc
git bisect bad b0d34c629047375290c4d5f8f0f3c243bdc79e67
# bad: [00ec229cb46e5c9059c0285a4a4de5f6ac322292] Use Session#request_tc to replace manual 'tc <<' calls
git bisect bad 00ec229cb46e5c9059c0285a4a4de5f6ac322292
# good: [49514f6bee91eeb1a5113a872d072ece3f62cce6] Extract get_src method
git bisect good 49514f6bee91eeb1a5113a872d072ece3f62cce6
# first bad commit: [00ec229cb46e5c9059c0285a4a4de5f6ac322292] Use Session#request_tc to replace manual 'tc <<' calls

st0012 · 2022-07-21T20:51:14Z

I haven't located the cause, but I found that we can reproduce it just by using these:

require "test_helper"

class ExampleTest < ActiveSupport::TestCase
  test "the truth" do
    debugger
  end
end

And it seems that there's a thread created before things hang:

(ruby) 1 == 2
DEBUGGER (DEBUG): #<DBG:TC 1:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> receives Cmd { type: :eval, args: [":pp", "\"1 == 2\""] } from Session
DEBUGGER (DEBUG): #<DBG:TC 1:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> changes mode (waiting -> running)
DEBUGGER (DEBUG): #<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> changes mode (running -> waiting)
DEBUGGER (DEBUG): #<DBG:TC 1:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> sends Event { type: :load, args: ["<RubyVM::InstructionSequence:block in <class:ExampleTest>@(rdbg)//Users/st0012/projects/debug_hang/test/models/example_test.rb:1>", "\"1 == 2\""] } to Session
DEBUGGER (INFO): Load (rdbg)//Users/st0012/projects/debug_hang/test/models/example_test.rb
DEBUGGER (DEBUG): #<DBG:TC 1:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> receives Cmd { type: :continue, args: [] } from Session
DEBUGGER (DEBUG): #<DBG:TC 1:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> changes mode (waiting -> running)
DEBUGGER (DEBUG): #<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> sends Event { type: :result, args: ["nil", "false"] } to Session
DEBUGGER (DEBUG): #<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> changes mode (running -> waiting)
false
(ruby) 1 == 2
DEBUGGER (DEBUG): #<DBG:TC 1:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> receives Cmd { type: :eval, args: [":pp", "\"1 == 2\""] } from Session
DEBUGGER (DEBUG): #<DBG:TC 12:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/debug-1.6.1/lib/debug/session.rb:167:in `block (2 levels) in activate'> changes mode (waiting -> running)
DEBUGGER (DEBUG): #<DBG:TC 1:waiting@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> changes mode (waiting -> running)
DEBUGGER (INFO): Thread #12 is created.
DEBUGGER (DEBUG): #<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> is suspended for :pause
DEBUGGER (DEBUG): #<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'> changes mode (running -> waiting)
DEBUGGER (DEBUG): #<DBG:TC 12:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/timeout-0.3.0/lib/timeout.rb:102:in `block in create_timeout_thread'> is suspended for :pause
DEBUGGER (DEBUG): #<DBG:TC 12:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/timeout-0.3.0/lib/timeout.rb:102:in `block in create_timeout_thread'> changes mode (running -> waiting)

It's the thread's suspension caused the hang and deadlock.

(ruby) 1 == 2
#<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'>
#<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'>
#<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'>
false
(ruby) 1 == 2
#<DBG:TC 1:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/minitest-5.16.2/lib/minitest.rb:83:in `block in autorun'>
#<DBG:TC 12:running@/Users/st0012/.rbenv/versions/3.1.0/lib/ruby/gems/3.1.0/gems/timeout-0.3.0/lib/timeout.rb:102:in `block in create_timeout_thread'>

But I'm still figuring out:

Why is it a new issue
How does the commit you pointed out affect this case
Why isn't it happen in other use cases

@yshmarov Can you briefly describe the way you encountered this problem? Is it also in minitest?

Update: repro steps can be further reduced to just type Timeout.send :create_timeout_thread when entering the console.

ianterrell · 2022-07-21T21:05:52Z

@st0012 I've noticed the issue is happening if I use my up key to go through the history. That appears to be what triggers queuing the :thread_begin event.

st0012 · 2022-07-21T21:39:53Z

I've created #727 for this. Can you give my branch a try and let me know if the issue still persists or something else occurs? You can do it with:

gem "debug", github: "st0012/debug", branch: "fix-#725"

Thanks

ianterrell · 2022-07-22T13:26:11Z

@st0012 So far that fix looks good! 🎉

It fixes my reproduction case and the similar one in our actual codebase.

My colleague had a different reproduction case that occurred outside of MiniTest while simply running the app. We think that one may have been occurring even on the 1.5.0 release. But so far that appears fixed on this branch, too.

st0012 · 2022-07-22T16:00:41Z

Thank you for the feedback ❤️

Petercopter · 2022-07-29T04:21:42Z

@st0012 Works for me as well. Doing a lot of debugging right now and it was driving me crazy! Thanks 👍

st0012 mentioned this issue Jul 21, 2022

Avoid setting @tc in thread_begin event #727

Merged

ko1 closed this as completed in #727 Aug 10, 2022

st0012 mentioned this issue Aug 12, 2022

why my debugger always hang? #735

Closed

jordanstephens mentioned this issue Jul 24, 2023

Deadlock on I/O #1000

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Deadlock on executing commands from binding.b in Rails app #725

Deadlock on executing commands from binding.b in Rails app #725

ianterrell commented Jul 21, 2022 •

edited

Loading

yshmarov commented Jul 21, 2022 •

edited

Loading

ianterrell commented Jul 21, 2022

st0012 commented Jul 21, 2022 •

edited

Loading

ianterrell commented Jul 21, 2022

st0012 commented Jul 21, 2022

ianterrell commented Jul 22, 2022 •

edited

Loading

st0012 commented Jul 22, 2022

Petercopter commented Jul 29, 2022

Deadlock on executing commands from binding.b in Rails app #725

Deadlock on executing commands from binding.b in Rails app #725

Comments

ianterrell commented Jul 21, 2022 • edited Loading

yshmarov commented Jul 21, 2022 • edited Loading

ianterrell commented Jul 21, 2022

st0012 commented Jul 21, 2022 • edited Loading

ianterrell commented Jul 21, 2022

st0012 commented Jul 21, 2022

ianterrell commented Jul 22, 2022 • edited Loading

st0012 commented Jul 22, 2022

Petercopter commented Jul 29, 2022

ianterrell commented Jul 21, 2022 •

edited

Loading

yshmarov commented Jul 21, 2022 •

edited

Loading

st0012 commented Jul 21, 2022 •

edited

Loading

ianterrell commented Jul 22, 2022 •

edited

Loading