REPL prints next prompt without printing result of previous command

[jordanstephens]

Your environment

• ruby -v:

~/wk/mos % ruby -v
ruby 3.2.2 (2023-03-30 revision e51014f9c0) [arm64-darwin22]

• rdbg -v:

  ~/wk/mos % rdbg -v
  rdbg 1.8.0
  {:mode=>:start, :no_color=>nil, :no_reline=>true}

  I should point out that I am loading debug from the github repo at revision 3d0f4e3225c4 after the discussion in #1000:

  ~/wk/mos % bundle show debug
  ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/bundler/gems/debug-3d0f4e3225c4

Describe the bug The REPL intermittently gets stuck in a state where it will not print the result of commands, even though it seems that they are continuing to be processed.

To Reproduce

I don't have a reliable repro process, but I will note that I have noticed this behaviour after sending the next command, and also after trying to evaluate an instance method at a breakpoint. Examples in the Additional context section below. Sending puts '' to the repl sometimes seems to help bring it back to the expected behaviour, but not always.

Expected behavior I expect the REPL to print the result of each command before printing the next prompt.

Additional context

Here's an example where I tried to run `next` multiple times, and I encountered this behaviour. I was eventually able to shake it loose by running `puts 'hello'`, and it appears that the debugger had advanced forward in the background, even though it had not provided feedback.

``` [90, 99] in ~/wk/mos/app/models/contract.rb 90| end 91| 92| private 93| 94| def validate_initiated_to_profile_role => 95| debugger 96| return unless initiated_to_profile.has_role?(:owner) 97| 98| errors.add(:initiated_to_profile, "cannot be an owner") 99| end =>#0 Contract#validate_initiated_to_profile_role at ~/wk/mos/app/models/contract.rb:95 #1 block {|target=# 99| end 100| 101| def invalid_activity_groups 102| Activity::Kind::Groups::Invalid.new(contract: self).result 103| end =>#0 Contract#validate_initiated_to_profile_role at ~/wk/mos/app/models/contract.rb:99 #=> #

Here's another case where using `puts` was able to break me out:

``` [231, 240] in ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/administrate-0.19.0/app/controllers/administrate/application_controller.rb 231| @resource_resolver ||= 232| Administrate::ResourceResolver.new(controller_path) 233| end 234| 235| def translate_with_resource(key) => 236| t( 237| "administrate.controller.#{key}", 238| resource: resource_resolver.resource_title, 239| ) 240| end =>#0 Administrate::ApplicationController#translate_with_resource(key="create.success") at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/administrate-0.19.0/app/controllers/administrate/application_controller.rb:236 #1 Dashboard::ApplicationController#create at ~/wk/mos/app/controllers/dashboard/application_controller.rb:36 # and 74 frames (use `bt' command for all frames) (rdbg) key "create.success" (rdbg) "administrate.controller.#{key}" (rdbg) next (rdbg) whereami (rdbg) puts '' nil (rdbg) whereami [235, 244] in ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/administrate-0.19.0/app/controllers/administrate/application_controller.rb 235| def translate_with_resource(key) 236| t( 237| "administrate.controller.#{key}", 238| resource: resource_resolver.resource_title, 239| ) => 240| end 241| 242| def show_search_bar? 243| dashboard.attribute_types_for( 244| dashboard.all_attributes, =>#0 Administrate::ApplicationController#translate_with_resource(key="create.success") at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/administrate-0.19.0/app/controllers/administrate/application_controller.rb:240 #=> "Contract was successfully created." #1 Dashboard::ApplicationController#create at ~/wk/mos/app/controllers/dashboard/application_controller.rb:36 # and 74 frames (use `bt' command for all frames) ```

Here's another example where using `puts` did not help, but it did finally shake loose when i sent only `;`.

``` [22, 31] in ~/wk/mos/app/controllers/dashboard/application_controller.rb 22| end 23| 24| def handle_create 25| resource = new_resource(resource_params) 26| authorize_resource(resource) => 27| debugger 28| resource.save 29| end 30| 31| def create =>#0 Dashboard::ApplicationController#handle_create at ~/wk/mos/app/controllers/dashboard/application_controller.rb:27 #1 Dashboard::ApplicationController#create at ~/wk/mos/app/controllers/dashboard/application_controller.rb:32 # and 74 frames (use `bt' command for all frames) (rdbg) resource # (rdbg) resource.save true (rdbg) resource.tap(&:save) (rdbg) puts (rdbg) puts; (rdbg) puts '' (rdbg) whereami (rdbg) ; nil ```

Another case where `puts` didn't work once, but seemed to work later

``` [44, 53] in ~/wk/mos/app/controllers/dashboard/vessels_controller.rb | ETA: 00:01:37 44| # for more information 45| 46| private 47| 48| def filter_resources(resources, search_term:) => 49| debugger if search_term.present? 50| Administrate::Search.new( 51| resources, 52| dashboard, 53| search_term =>#0 Dashboard::VesselsController#filter_resources(resources=[# 179| @dashboard ||= dashboard_class.new 180| end 181| 182| def requested_resource 183| @requested_resource ||= find_resource(params[:id]).tap do |resource| ```

I suspect this is a race condition of some kind. If I notice any more patterns, I'll update this issue. If anyone has any troubleshooting or reproduction suggestions, let me know.

Thanks

[jordanstephens]

I've noticed lately that often the easiest way to un-stick the REPL is to run a sleep from the prompt.

[58, 67] in ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activemodel-7.0.8/lib/active_model/error.rb
    58|
    59|       I18n.t(defaults.shift,
    60|         default:  defaults,
    61|         attribute: attr_name,
    62|         message:   message)
=>  63|     end
    64|
    65|     def self.generate_message(attribute, type, base, options) # :nodoc:
    66|       type = options.delete(:message) if options[:message].is_a?(Symbol)
    67|       value = (attribute != :base ? base.read_attribute_for_validation(attribute) : nil)
=>#0    ActiveModel::Error.full_message(attribute="name", message="can't be blank", base=#<Vessel:0x000000012d2b19b0 id: nil, name...) at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activemodel-7.0.8/lib/active_model/error.rb:63 #=> "Name can't be blank"
  #1    ActiveModel::Error#full_message at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activemodel-7.0.8/lib/active_model/error.rb:160
  # and 89 frames (use `bt' command for all frames)
(rdbg) c                # <--- NOTE prompt failed to print the frame here
(rdbg) sleep 5
5                       # <--- NOTE prompt _did_ print the result after sleep
(rdbg) whereami
[48, 57] in ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activemodel-7.0.8/lib/active_model/error.rb
    48|
    49|       defaults << :"errors.format"
    50|       defaults << "%{attribute} %{message}"
    51|
    52|       attr_name = attribute.remove(/\.base\z/).tr(".", "_").humanize
=>  53|       debugger
    54|       attr_name = base_class.human_attribute_name(attribute, {
    55|         default: attr_name,
    56|         base: base,
    57|       })
=>#0    ActiveModel::Error.full_message(attribute="drive", message="must be power or sail", base=#<Vessel:0x000000012d2b19b0 id: nil, name...) at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activemodel-7.0.8/lib/active_model/error.rb:53
  #1    ActiveModel::Error#full_message at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activemodel-7.0.8/lib/active_model/error.rb:160
  # and 89 frames (use `bt' command for all frames)

I still don't have a reliable repro, but it does seem to happen very often intermittently. Maybe this offers a clue?

[st0012]

Does it always happen when you debug inside a live Rails server, or it happens when you debug tests too?

Also, could you try setting RUBY_DEBUG_SHOW_FRAMES=0 in your project for a while, which will stop displaying frames when you move forward, and see if the issue still occurs?

I don't have much proof atm, but I suspect it could be caused by inspecting frame arguments causing a livelock due to the thread-freezing mechanism. And evaluating input now temporarily unfreezes threads, which could resolve the locking as a side-effect.

[jordanstephens]

Does it always happen when you debug inside a live Rails server, or it happens when you debug tests too?

Now I'm wondering if I see it on a live development server—it may just be while debugging specs. And I'm usually debugging system specs that are driving a chrome browser with cuprite. So I wonder if that is related. I tried setting RUBY_DEBUG_SHOW_FRAMES=0 but I'm still seeing the same behaviour.

I've started running sleep 1 when it happens and it always unlocks it.

If you have any diagnostic ideas, let me know. I'm just not sure what to look for.