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=#<Contract:0x000000010e0c64a8 id: nil, ve..., value=nil, block=nil|} in make_lambda at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8/lib/active_support/callbacks.rb:400
 # and 92 frames (use `bt' command for all frames)
(rdbg) next
(rdbg) next
(rdbg) next
(rdbg) whereami
(rdbg) frame 0
(rdbg) bt
(rdbg) puts 'hello'
hello
nil
(rdbg) whereami
[94, 103] in ~/wk/mos/app/models/contract.rb
 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
 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 #=> #<ActiveModel::Error attribute=initiated_...
 #1	block {|target=#<Contract:0x000000010e0c64a8 id: nil, ve..., value=nil, block=nil|} in make_lambda at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.0.8/lib/active_support/callbacks.rb:400
 # and 92 frames (use `bt' command for all frames)

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
#<Facility:0x000000010f93b740 id: nil, name: "Slow Dock", created_at: nil, updated_at: nil, tenant_id: nil>
(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=[#<Vessel:0x000000012617c088 id: 750, nam..., search_term="pending_activity:winterize") at ~/wk/mos/app/controllers/dashboard/vessels_controller.rb:49
 #1	Administrate::ApplicationController#index at ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/administrate-0.19.0/app/controllers/administrate/application_controller.rb:8
 # and 77 frames (use `bt' command for all frames)
(rdbg) next
(rdbg) step
(rdbg) puts
(rdbg) ;
(rdbg) whereami
(rdbg) puts '';

nil
(rdbg) whereami
[174, 183] in ~/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/administrate-0.19.0/app/controllers/administrate/application_controller.rb
 174| def sorting_params
 175| Hash.try_convert(request.query_parameters[resource_name]) || {}
 176| end
 177|
 178| def dashboard
=> 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.