Skip to content

binding.b(do: ...) hangs Rails with puma web server #248

Closed

Description

@st0012

Update: it doesn't happen when used with thin server

I just noticed that binding.b(do: "") hangs the Rails on puma server. But to be more clear, it doesn't hang the request that runs the command. It stops the next one from starting.

An example:

class PostsController < ApplicationController
  def index
    binding.b(do: "pp 123")
    @posts = Post.all
    # binding.b(do: "trace off")
  end
Started GET "/posts" for 127.0.0.1 at 2021-09-04 13:59:30 +0800
   (0.5ms)  SELECT sqlite_version(*)
   (0.1ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Processing by PostsController#index as HTML
[2, 11] in ~/projects/sentry-ruby/sentry-rails/examples/rails-6.0/app/controllers/posts_controller.rb
     2|   before_action :set_post, only: [:show, :edit, :update, :destroy]
     3|
     4|   # GET /posts
     5|   # GET /posts.json
     6|   def index
=>   7|     binding.b(do: "pp 123")
     8|     @posts = Post.all
     9|     # binding.b(do: "trace off")
    10|   end
    11|
=>#0    PostsController#index at ~/projects/sentry-ruby/sentry-rails/examples/rails-6.0/app/controllers/posts_controller.rb:7
  #1    ActionController::BasicImplicitRender#send_action(method="index", args=[]) at ~/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/actionpack-6.0.4/lib/action_controller/metal/basic_implicit_render.rb:6
  # and 73 frames (use `bt' command for all frames)
(rdbg:binding.break) pp 123
123
  Rendering posts/index.html.erb within layouts/application
  Post Load (0.2ms)  SELECT "posts".* FROM "posts"
  ↳ app/views/posts/index.html.erb:15
  Rendered posts/index.html.erb within layouts/application (Duration: 63.1ms | Allocations: 46972)
[Webpacker] Everything's up-to-date. Nothing to do
Completed 200 OK in 1575ms (Views: 1495.7ms | ActiveRecord: 1.6ms | Allocations: 1510204)

As you can see, it finishes the request. But when I make a second request, it seems never reach the Rails server at all (no logs).

What's worse is that the process also doesn't accept any Ctrl-c (SIGINT) exit.

However, this is not the case for binding.b or binding.b(pre: ...).

Started GET "/posts" for 127.0.0.1 at 2021-09-04 14:06:48 +0800
   (0.5ms)  SELECT sqlite_version(*)
   (0.1ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Processing by PostsController#index as HTML
[2, 11] in ~/projects/sentry-ruby/sentry-rails/examples/rails-6.0/app/controllers/posts_controller.rb
     2|   before_action :set_post, only: [:show, :edit, :update, :destroy]
     3|
     4|   # GET /posts
     5|   # GET /posts.json
     6|   def index
=>   7|     binding.b(pre: "pp 123")
     8|     @posts = Post.all
     9|     # binding.b(do: "trace off")
    10|   end
    11|
=>#0    PostsController#index at ~/projects/sentry-ruby/sentry-rails/examples/rails-6.0/app/controllers/posts_controller.rb:7
  #1    ActionController::BasicImplicitRender#send_action(method="index", args=[]) at ~/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/actionpack-6.0.4/lib/action_controller/metal/basic_implicit_render.rb:6
  # and 73 frames (use `bt' command for all frames)
(rdbg:binding.break) pp 123
123
(rdbg) c    # continue command
  Rendering posts/index.html.erb within layouts/application
  Post Load (0.2ms)  SELECT "posts".* FROM "posts"
  ↳ app/views/posts/index.html.erb:15
  Rendered posts/index.html.erb within layouts/application (Duration: 26.0ms | Allocations: 49588)
[Webpacker] Everything's up-to-date. Nothing to do
Completed 200 OK in 3522ms (Views: 1039.9ms | ActiveRecord: 0.7ms | Allocations: 1543430)


Started GET "/posts" for 127.0.0.1 at 2021-09-04 14:06:52 +0800
Processing by PostsController#index as HTML
[2, 11] in ~/projects/sentry-ruby/sentry-rails/examples/rails-6.0/app/controllers/posts_controller.rb
     2|   before_action :set_post, only: [:show, :edit, :update, :destroy]
     3|
     4|   # GET /posts
     5|   # GET /posts.json
     6|   def index
=>   7|     binding.b(pre: "pp 123")
     8|     @posts = Post.all
     9|     # binding.b(do: "trace off")
    10|   end
    11|
=>#0    PostsController#index at ~/projects/sentry-ruby/sentry-rails/examples/rails-6.0/app/controllers/posts_controller.rb:7
  #1    ActionController::BasicImplicitRender#send_action(method="index", args=[]) at ~/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/actionpack-6.0.4/lib/action_controller/metal/basic_implicit_render.rb:6
  # and 73 frames (use `bt' command for all frames)
(rdbg:binding.break) pp 123
123
(rdbg) c    # continue command
  Rendering posts/index.html.erb within layouts/application
  Post Load (0.1ms)  SELECT "posts".* FROM "posts"
  ↳ app/views/posts/index.html.erb:15
  Rendered posts/index.html.erb within layouts/application (Duration: 2.0ms | Allocations: 1513)
[Webpacker] Everything's up-to-date. Nothing to do
Completed 200 OK in 1120ms (Views: 16.9ms | ActiveRecord: 0.1ms | Allocations: 61312)

So I suspect it has something to do with the present commands' auto continue mechanism.

Activity

  1. changed the title [-]binding.b(do: ...) hangs Rails server[/-] [+]binding.b(do: ...) hangs Rails with puma web server[/+] on Sep 4, 2021
  2. st0012 commented on Sep 4, 2021

    @st0012
    MemberAuthor

    This may be related: calling binding.b(do: ..) in threads seems to cause lock.

    DEBUGGER: Session start (pid: 89938)
    [1, 8] in line_tracer.rb
         1| Thread.new do
    =>   2|   binding.b(do: "p 123")
         3| end.join
         4|
         5| Thread.new do
         6|   binding.b(do: "p 123")
         7| end.join
         8|
    =>#0    block in <main> at line_tracer.rb:2
    (rdbg:binding.break) p 123
    => 123
    ["DEBUGGER Exception: /Users/st0012/projects/debug/lib/debug/thread_client.rb:956",
     #<fatal: No live threads left. Deadlock?
    2 threads, 2 sleeps current:0x00007f9c98c0a360 main thread:0x00007f9c98c0a360
    * #<Thread:0x00007f9c99063a50 sleep_forever>
       rb_thread_t:0x00007f9c98c0a360 native:0x000000010dc3ce00 int:0
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `pop'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `wait_next_action_'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:655:in `wait_next_action'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:276:in `suspend'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:226:in `on_pause'
       /Users/st0012/projects/debug/lib/debug/session.rb:1251:in `block in thread_stopper'
       line_tracer.rb:5:in `<main>'
    * #<Thread:0x00007f9c79084f18@DEBUGGER__::SESSION@server /Users/st0012/projects/debug/lib/debug/session.rb:110 sleep_forever>
       rb_thread_t:0x00007f9c78c84db0 native:0x0000700005e68000 int:0
       /Users/st0012/projects/debug/lib/debug/session.rb:157:in `pop'
       /Users/st0012/projects/debug/lib/debug/session.rb:157:in `pop_event'
       /Users/st0012/projects/debug/lib/debug/session.rb:161:in `session_server_main'
       /Users/st0012/projects/debug/lib/debug/session.rb:113:in `block in activate'
    >,
     ["/Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `pop'",
      "/Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `wait_next_action_'",
      "/Users/st0012/projects/debug/lib/debug/thread_client.rb:655:in `wait_next_action'",
      "/Users/st0012/projects/debug/lib/debug/thread_client.rb:276:in `suspend'",
      "/Users/st0012/projects/debug/lib/debug/thread_client.rb:226:in `on_pause'",
      "/Users/st0012/projects/debug/lib/debug/session.rb:1251:in `block in thread_stopper'",
      "line_tracer.rb:5:in `<main>'"]]
    Traceback (most recent call last):
            6: from line_tracer.rb:5:in `<main>'
            5: from /Users/st0012/projects/debug/lib/debug/session.rb:1251:in `block in thread_stopper'
            4: from /Users/st0012/projects/debug/lib/debug/thread_client.rb:226:in `on_pause'
            3: from /Users/st0012/projects/debug/lib/debug/thread_client.rb:276:in `suspend'
            2: from /Users/st0012/projects/debug/lib/debug/thread_client.rb:655:in `wait_next_action'
            1: from /Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `wait_next_action_'
    /Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `pop': No live threads left. Deadlock? (fatal)
    2 threads, 2 sleeps current:0x00007f9c98c0a360 main thread:0x00007f9c98c0a360
    * #<Thread:0x00007f9c99063a50 sleep_forever>
       rb_thread_t:0x00007f9c98c0a360 native:0x000000010dc3ce00 int:0
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `pop'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:674:in `wait_next_action_'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:655:in `wait_next_action'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:276:in `suspend'
       /Users/st0012/projects/debug/lib/debug/thread_client.rb:226:in `on_pause'
       /Users/st0012/projects/debug/lib/debug/session.rb:1251:in `block in thread_stopper'
       line_tracer.rb:5:in `<main>'
    * #<Thread:0x00007f9c79084f18@DEBUGGER__::SESSION@server /Users/st0012/projects/debug/lib/debug/session.rb:110 sleep_forever>
       rb_thread_t:0x00007f9c78c84db0 native:0x0000700005e68000 int:0
       /Users/st0012/projects/debug/lib/debug/session.rb:157:in `pop'
       /Users/st0012/projects/debug/lib/debug/session.rb:157:in `pop_event'
       /Users/st0012/projects/debug/lib/debug/session.rb:161:in `session_server_main'
       /Users/st0012/projects/debug/lib/debug/session.rb:113:in `block in activate'
    

    But not binding.b(pre: ...)

    DEBUGGER: Session start (pid: 90059)
    [1, 8] in line_tracer.rb
         1| Thread.new do
    =>   2|   binding.b(pre: "p 123")
         3| end.join
         4|
         5| Thread.new do
         6|   binding.b(pre: "p 123")
         7| end.join
         8|
    =>#0    block in <main> at line_tracer.rb:2
    (rdbg:binding.break) p 123
    => 123
    (rdbg) c    # continue command
    [1, 8] in line_tracer.rb
         1| Thread.new do
         2|   binding.b(pre: "p 123")
         3| end.join
         4|
         5| Thread.new do
    =>   6|   binding.b(pre: "p 123")
         7| end.join
         8|
    =>#0    block in <main> at line_tracer.rb:6
    (rdbg:binding.break) p 123
    => 123
    (rdbg) c    # continue command
    
  3. ko1 commented on Sep 6, 2021

    @ko1
    Collaborator
    diff --git a/lib/debug/session.rb b/lib/debug/session.rb
    index 977773e..25d5f29 100644
    --- a/lib/debug/session.rb
    +++ b/lib/debug/session.rb
    @@ -304,6 +304,7 @@ module DEBUGGER__
               if @preset_command.auto_continue
                 @preset_command = nil
                 @tc << :continue
    +            restart_all_threads
                 return
               else
                 @preset_command = nil
    

    could you try it? the issue of simple thread example was solved with this patch.

  4. ko1 commented on Sep 6, 2021

    @ko1
    Collaborator

    ah, I missed your PR.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions