Deadlock on I/O #1000

jordanstephens · 2023-07-24T21:32:47Z

Your environment

ruby -v: ruby 3.2.2 (2023-03-30 revision e51014f9c0) [arm64-darwin22]
rdbg -v: rdbg 1.8.0

Describe the bug

rdbg hangs intermittently after (during?) I/O operations. I've noticed this most often when running code that executes a database query, reads a file, or makes a network request in the repl during a debugging session. No result is returned, and the console accepts no input until eventually it crashes with an exception report that includes No live threads left. Deadlock? (Full exception report below).

I suspect this has something to do with resuming suspended threads, but I don't know enough about ruby's threading or I/O models (or how rdbg works) to debug this further. All I can offer is the stacktrace I get upon crash, and a process snapshots taken from Activity Monitor before and after the deadlock. I'll try to enable dtruss later to see if I can gain any further insight with that tool. Let me know if you have any specific recommendations for troubleshooting this further.

I looked at #725 and tried to downgrade to version 1.5.0, but I saw deadlocks there as well. I don't suspect this is related to readline, but I could try to disable it if you think it's worth it.

Thanks,

Exception Report (formatted manually for legibility)

[
  "DEBUGGER Exception: /Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/thread_client.rb:1251",
  "#<fatal:\"No live threads left. Deadlock?
  4 threads, 4 sleeps current:0x00000001341841a0 main thread:0x0000000153e04b00
  * #<Thread:0x000000010258b0f8 sleep_forever>
     rb_thread_t:0x0000000153e04b00 native:0x00000001f0f7a500 int:0

  * #<Thread:0x0000000106707950@DEBUGGER__::SESSION@server /Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/session.rb:179 sleep_forever>
     rb_thread_t:0x0000000153ee4870 native:0x000000016dc63000 int:0 mutex:0x0000000143e3eb40 cond:1

  * #<Thread:0x0000000109396bd8 /Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.6/lib/active_record/connection_adapters/abstract/connection_pool/reaper.rb:40 sleep_forever>
     rb_thread_t:0x00000001341841a0 native:0x000000016de6f000 int:0
  * #<Thread:0x0000000107cf4498@Timeout stdlib thread /Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/timeout-0.4.0/lib/timeout.rb:98 sleep_forever>
     rb_thread_t:0x0000000143e24a10 native:0x000000016e07b000 int:0

\">",
  [
    "<internal:thread_sync>:18:in `pop'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/thread_client.rb:884:in `wait_next_action_'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/thread_client.rb:866:in `wait_next_action'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/thread_client.rb:321:in `suspend'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/thread_client.rb:252:in `on_breakpoint'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/breakpoint.rb:69:in `suspend'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/breakpoint.rb:170:in `block in setup'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/debug-1.8.0/lib/debug/session.rb:2616:in `debugger'",
    "/Users/jordan/wk/early/db/seeds.rb:12:in `<main>'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/engine.rb:557:in `load'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/engine.rb:557:in `block in load_seed'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.6/lib/active_support/callbacks.rb:118:in `block in run_callbacks'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.6/lib/active_support/execution_wrapper.rb:92:in `wrap'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/engine.rb:626:in `block (2 levels) in <class:Engine>'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.6/lib/active_support/callbacks.rb:127:in `instance_exec'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.6/lib/active_support/callbacks.rb:127:in `block in run_callbacks'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.6/lib/active_support/callbacks.rb:138:in `run_callbacks'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/engine.rb:557:in `load_seed'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.6/lib/active_record/tasks/database_tasks.rb:497:in `load_seed'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.6/lib/active_record/railties/databases.rake:397:in `block (2 levels) in <main>'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `each'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:160:in `invoke_task'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block (2 levels) in top_level'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `each'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block in top_level'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:125:in `run_with_threads'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:110:in `top_level'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/commands/rake/rake_command.rb:24:in `block (2 levels) in perform'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:186:in `standard_exception_handling'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/commands/rake/rake_command.rb:24:in `block in perform'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/rake_module.rb:59:in `with_application'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/commands/rake/rake_command.rb:18:in `perform'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/command.rb:51:in `invoke'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/railties-7.0.6/lib/rails/commands.rb:18:in `<main>'",
    "<internal:/Users/jordan/.rbenv/versions/3.2.2/lib/ruby/site_ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:37:in `require'",
    "<internal:/Users/jordan/.rbenv/versions/3.2.2/lib/ruby/site_ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:37:in `require'",
    "/Users/jordan/wk/early/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.16.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
    "bin/rails:4:in `<main>'"
  ]
]

To Reproduce

It's not deterministically reproducible, but seems to occur when i run commands which trigger database queries

Expected behavior
I expect the repl to execute a database query, return control back to the console, so that I may continue my debugging session.

Additional context
Add any other context about the problem here.

I also took a sample with activity monitor before and after a deadlock here:

Process Sample Before Deadlock [link]
Process Sample After Deadlock [link]

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

Urist-McUristurister · 2023-08-01T10:29:09Z

I'm having the same issue, but in my case it seems it's getting stuck when I'm using the arrow keys during debugging session.
FFIW, I'm using iTerm2 on Mac M1 (ARM).

Update 04.08.2023: when invoking debugger via debugger, it freezes in 100% of the cases. When invoking via binding.break, it froze only 2 times today, out of about 20-30 cases. I know it's just an alias, but nevertheless.

Petercopter · 2023-08-04T16:04:00Z

arrow keys cause hanging for me as well. If I press the up arrow to get a previous command, about 90% of the time it hangs.

st0012 · 2023-08-04T21:07:52Z

Update: Try updating Reline to 0.3.8+ before doing the following step.

I think this is the same us #934 which could be worked around by disabling Reline with: RUBY_DEBUG_NO_RELINE=1

Timeout's implementation relies on Thread, which would conflict with `ruby/debug`'s thread-freezing implementation and has casued issues like - ruby/debug#877 - ruby/debug#934 - ruby/debug#1000 This commit avoids the issue by completely removing the use of Timeout.

`ruby/debug`'s thread-freezing implementation and has casued issues like - ruby/debug#877 - ruby/debug#934 - ruby/debug#1000 This commit avoids the issue by completely removing the use of Timeout.

Timeout's implementation relies on Thread, which would conflict with `ruby/debug`'s thread-freezing implementation and has casued issues like - ruby/debug#877 - ruby/debug#934 - ruby/debug#1000 This commit avoids the issue by completely removing the use of Timeout.

(ruby/reline#580) Timeout's implementation relies on Thread, which would conflict with `ruby/debug`'s thread-freezing implementation and has casued issues like - ruby/debug#877 - ruby/debug#934 - ruby/debug#1000 This commit avoids the issue by completely removing the use of Timeout. ruby/reline@d4f0cd3fe1

ddoherty03 · 2023-09-14T10:19:25Z

This worked for me. I just want to say that this has been the most irritating issue of using the debug gem, which is otherwise fantastic. I was getting bit by this on nearly every invocation of debug from 'binding.break' calls in my code. So glad this got fixed. Great work. I hope this gets backported to all live releases and is part of version 3.3 ruby.

st0012 · 2023-09-14T10:21:33Z

@ddoherty03 I actually forgot to update that if you install Reline 0.3.8, the issue should also disappear without setting RUBY_DEBUG_NO_RELINE=1.

ddoherty03 · 2023-09-14T10:22:35Z

@st0012. Yes, that is my experience. Many thanks. You're my hero!

ko1 · 2023-09-25T08:18:54Z

Can we close it?

ddoherty03 · 2023-09-25T14:54:23Z

@ko1, as far as I can tell, it’s fixed. Would be interested whether @jordanstephens agrees.

jordanstephens · 2023-09-25T22:23:58Z

Thanks for the tip! I'll point our gemfile to 3d0f4e3 for now. I'll report back if I continue experiencing this issue. 👍

jordanstephens · 2023-09-28T20:18:31Z

I haven't encountered the deadlock issue since upgrading reline. Thank you!

I am still encountering an issue where the repl will intermittently fail to print the results of the previous command. I'll open a new issue to track that (#1021), and I'll await a new release of debug with the updated dependency constraint on reline in 3d0f4e3.

Feel free to close this 👍

st0012 mentioned this issue Aug 14, 2023

Remove Timeout usage ruby/reline#580

Merged

st0012 mentioned this issue Sep 14, 2023

Require Reline 0.3.8+ to avoid frozen issue #1020

Merged

jordanstephens mentioned this issue Sep 28, 2023

REPL prints next prompt without printing result of previous command #1021

Open

ko1 closed this as completed Oct 2, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Deadlock on I/O #1000

Deadlock on I/O #1000

jordanstephens commented Jul 24, 2023 •

edited

Loading

Urist-McUristurister commented Aug 1, 2023 •

edited

Loading

Petercopter commented Aug 4, 2023

st0012 commented Aug 4, 2023 •

edited

Loading

ddoherty03 commented Sep 14, 2023 •

edited

Loading

st0012 commented Sep 14, 2023

ddoherty03 commented Sep 14, 2023 •

edited

Loading

ko1 commented Sep 25, 2023

ddoherty03 commented Sep 25, 2023

jordanstephens commented Sep 25, 2023

jordanstephens commented Sep 28, 2023 •

edited

Loading

Deadlock on I/O #1000

Deadlock on I/O #1000

Comments

jordanstephens commented Jul 24, 2023 • edited Loading

Urist-McUristurister commented Aug 1, 2023 • edited Loading

Petercopter commented Aug 4, 2023

st0012 commented Aug 4, 2023 • edited Loading

ddoherty03 commented Sep 14, 2023 • edited Loading

st0012 commented Sep 14, 2023

ddoherty03 commented Sep 14, 2023 • edited Loading

ko1 commented Sep 25, 2023

ddoherty03 commented Sep 25, 2023

jordanstephens commented Sep 25, 2023

jordanstephens commented Sep 28, 2023 • edited Loading

jordanstephens commented Jul 24, 2023 •

edited

Loading

Urist-McUristurister commented Aug 1, 2023 •

edited

Loading

st0012 commented Aug 4, 2023 •

edited

Loading

ddoherty03 commented Sep 14, 2023 •

edited

Loading

ddoherty03 commented Sep 14, 2023 •

edited

Loading

jordanstephens commented Sep 28, 2023 •

edited

Loading