next stops in the wrong place when blocks are called

[marianosimone]

Your environment

• ruby -v: 2.7.2p137
• rdbg -v: 1.6.2

To Reproduce
For a simple case:

1. Create a file like:

def with_block
    yield
end
   
with_block do
    1
end
puts("`next` should stop here")

2. Add a breakpoint in line 5
3. Try to move to next
4. See the debugger stop at line 6 (and then 7, and 3)

For more complex cases:

1. Create a file like:

class Bar
  define_method("dynamic") do
    true
  end

  def regular; false; end
end

def foo(a, b, c); end

bar = Bar.new
foo(
  bar.regular,
  bar.dynamic, # `next` stops here
  bar.regular
)
puts("`next` should stop here")

2. Add a breakpoint in line 12 (where the call to foo is)
3. Try to move to next
4. See the debugger stop at line 14

Expected behavior
The debugger should stop at line 8 in the simple example, and 17 in the complex one

Additional context
I included non-dynamically-defined methods, to show that next only behaves incorrectly for the dynamically-defined ones (as it doesn't stop at line 13 nor 15)

[marianosimone]

Here's a protocol test that should pass when the issue is fixed:

# frozen_string_literal: true

require_relative '../support/protocol_test_case'

module DEBUGGER__
  class NextDynamicMethodTest < ProtocolTestCase
    PROGRAM = <<~RUBY
       1| class Bar
       2|   define_method("dynamic") do
       3|     "dynamic"
       4|   end
       5|   
       6|   def regular
       7|     "regular"
       8|   end
       9| end
      10|   
      11| def foo(a, b, c); end
      12|   
      13| bar = Bar.new
      14| foo(
      15|   bar.regular,
      16|   bar.dynamic,
      17|   bar.regular
      18| )
      19| bar
    RUBY

    def test_next_goes_to_the_next_statement
      run_protocol_scenario PROGRAM do
        req_next
        assert_line_num 2

        assert_locals_result(
          [
            { name: "%self", value: "Bar", type: "Class" },
          ]
        )
        req_next
        assert_line_num 6

        assert_locals_result(
          [
            { name: "%self", value: "Bar", type: "Class" },
          ]
        )
        req_next
        assert_line_num 11

        assert_locals_result(
          [
            { name: "%self", value: "main", type: "Object" },
            { name: "bar", value: "nil", type: "NilClass" }
          ]
        )
        req_next
        assert_line_num 13

        assert_locals_result(
          [
            { name: "%self", value: "main", type: "Object" },
            { name: "bar", value: "nil", type: "NilClass" }
          ]
        )

        req_next
        assert_line_num 14

        assert_locals_result(
          [
            { name: "%self", value: "main", type: "Object" },
            { name: "bar", value: /#<Bar/, type: "Bar" }
          ]
        )

        req_next
        assert_line_num 19

        assert_locals_result(
          [
            { name: "%self", value: "main", type: "Object" },
            { name: "bar", value: /#<Bar/, type: "Bar" }
          ]
        )
        req_terminate_debuggee
      end
    end
  end
end

[marianosimone]

cc @WillHalto. Just a heads up that #743 doesn't seem to make this worse, but given that you are already there and have some context, you might find it interesting.

[st0012]

A small tip: you can write the reproduction steps down like:

debugger(do: "b 6 ;; c ;; n ;; n ;; n")

def with_block
    yield
end

with_block do
    1
end

puts("`next` should stop here")

In this case, we only need to run

$ rdbg -n target.rb

And the reproduction steps can be executed automatically.

If you don't want to modify the script directly, you can achieve it with rdbg -e too:

def with_block
    yield
end

with_block do
    1
end

puts("`next` should stop here")

$ rdbg -e "b 5 ;; c ;; n ;; n ;; n" target.rb

[st0012]

After some investigation, I think the simple and complicated examples have different causes.

I can't really tell the cause of the simple case yet. But for the complicated example, I think it's caused by a bug in older Ruby versions.

Example

TracePoint.new(:b_return, :return) do |tp|
  puts [tp.event, caller_locations(1, 1).first].to_s
end.enable

class Bar
  define_method("dynamic") do
    true
  end # line 8
end

Bar.new.dynamic # line 11

If you execute this script with Ruby < 3.1, you'll get

❯ ruby test.rb
[:b_return, "test.rb:8:in `block in <class:Bar>'"]
[:return, "test.rb:11:in `<main>'"]

And you can see that b_return and return events' line numbers don't match. Ideally, they should both be 8.

However, if you run it with Ruby 3.1, they do match

❯ ruby test.rb
[:b_return, "test.rb:8:in `block in <class:Bar>'"]
[:return, "test.rb:8:in `block in <class:Bar>'"]

If you run the complicated case with Ruby 3.1, it actually works as expected:

❯ exe/rdbg -e "b 12 ;; c ;; n ;; n ;; n" target.rb
[1, 10] in target.rb
=>   1| class Bar
     2|   define_method("dynamic") do
     3|     true
     4|   end
     5|
     6|   def regular; false; end
     7| end
     8|
     9| def foo(a, b, c); end
    10|
=>#0    <main> at target.rb:1
(rdbg:commands) b 12
#0  BP - Line  /Users/st0012/projects/debug/target.rb:12 (line)
(rdbg:commands) c
[7, 16] in target.rb
     7| end
     8|
     9| def foo(a, b, c); end
    10|
    11| bar = Bar.new
=>  12| foo(
    13|   bar.regular,
    14|   bar.dynamic, # `next` stops here
    15|   bar.regular
    16| )
=>#0    <main> at target.rb:12

Stop by #0  BP - Line  /Users/st0012/projects/debug/target.rb:12 (line)
(rdbg:commands) n
[12, 17] in target.rb
    12| foo(
    13|   bar.regular,
    14|   bar.dynamic, # `next` stops here
    15|   bar.regular
    16| )
=>  17| puts("`next` should stop here")
=>#0    <main> at target.rb:17
(rdbg:commands) n
`next` should stop here

So I think it's more like a bug in older Ruby versions, but we may workaround it in debug.

[ko1]

It solved on Ruby 3.1.0 and later.
I agree it is an issue, but not so big problem I think so I left it.
Please reopen it if it is so important issue.

[marianosimone]

I don't know what your policy is in supporting Ruby < 3.1.0... but, as it is, with this issue and #760, the debugger has a really poor experience.

Given that we still have 6 months until the end of life of Ruby 2.6 (and no date for 2.7), I'd argue for at least keeping this open, and try to fix it.

[st0012]

Last time I tested, the simple case's issue also happened with Ruby 3.1+ so it needs more investigation.

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

❯ be exe/rdbg target.rb
[1, 8] in target.rb
=>   1| def with_block
     2|     yield
     3| end
     4|
     5| with_block do
     6|     1
     7| end
     8| puts("`next` should stop here")
=>#0    <main> at target.rb:1
(rdbg) b 5    # break command
#0  BP - Line  /Users/st0012/projects/debug/target.rb:5 (line)
(rdbg) c    # continue command
[1, 8] in target.rb
     1| def with_block
     2|     yield
     3| end
     4|
=>   5| with_block do
     6|     1
     7| end
     8| puts("`next` should stop here")
=>#0    <main> at target.rb:5

Stop by #0  BP - Line  /Users/st0012/projects/debug/target.rb:5 (line)
(rdbg) n    # next command
[1, 8] in target.rb
     1| def with_block
     2|     yield
     3| end
     4|
     5| with_block do
=>   6|     1
     7| end
     8| puts("`next` should stop here")
=>#0    block in <main> at target.rb:6
  #1    Object#with_block at target.rb:2
  # and 1 frames (use `bt' command for all frames)
(rdbg) n    # next command
[2, 8] in target.rb
     2|     yield
     3| end
     4|
     5| with_block do
     6|     1
=>   7| end
     8| puts("`next` should stop here")
=>#0    block in <main> at target.rb:7 #=> 1
  #1    Object#with_block at target.rb:2
  # and 1 frames (use `bt' command for all frames)

<===== Ideally this step shouldn't happen =====>

(rdbg) n    # next command 
[1, 8] in target.rb
     1| def with_block
     2|     yield
=>   3| end
     4|
     5| with_block do
     6|     1
     7| end
     8| puts("`next` should stop here")
=>#0    Object#with_block at target.rb:3 #=> 1
  #1    <main> at target.rb:5
(rdbg) n    # next command
[3, 8] in target.rb
     3| end
     4|
     5| with_block do
     6|     1
     7| end
=>   8| puts("`next` should stop here")
=>#0    <main> at target.rb:8
(rdbg) n    # next command
`next` should stop here

So based on that I think we should keep this issue opened until we're clear on both cases' causes.

[marianosimone]

It's also worth mentioning that, for anyone using Sorbet, trying to step with next always requires two steps. This is because Sorbet signatures are essentially wrapping methods in a block. Take the following example:

sig {returns(T::Boolean)}
def does_it_work?
  false
end

value = does_it_work?
puts("Does it work? #{value}")

Trying to step over 6 requires two next

[ko1]

I think additional next is not big problem but you think it is a big problem?

[marianosimone]

There are actually 2 problems (as identified by @st0012 above):

1. Extra steps when a block is involved (as in Sorbet). This might not seem like much, but if you are debugging a codebase where everything has a signature, it's essentially 2 nexts for each line you want to step over
2. next going to the wrong place

They are definitely a very bad experience when debugging anything but a trivial codebase

[ko1]

I understand the issue.

def iter
  yield
end # (iter/end)

iter do
  1
end # (*) Now stopping here

puts("`next` should stop here") # (putline)

• For a person who think the block is function, the next line of (*) should be (iter/end). They have interest how iter is implemented.
• For a person who think the block is a loop (or code block) of caller context (top on this case), the next line should be (putline). They don't have interest how iter is implemented.

Options:

1. next should ignore the iter internal and jump to (putline) (maybe the author of this issue wants)
2. next should not ignore iter internal and jump to (iter/end) (current behavior)

Now, next command consider the block is literally next, so option 1 seems preferable.

[marianosimone]

In the case above, 2 (at the line with end) is never what I'd expect to happen.

What I would expect is 1 (thus this ticket), but I'd be OK (as in: "I don't like this much, but at least doesn't surprise me") with either stopping inside the iter function (the line with yield) or inside the block (the line with 1).

[ko1]

with either stopping inside the iter function (the line with yield) or inside the block (the line with 1).

When stopping at line (*), it never stop at yield or 1 because they are passed lines.

[ko1]

ah, I see on the original issue:

The debugger should stop at line 8

You want to skip block call at all.

• (1) The first version of debug.gem skips the block.
• (2) However, Ruby's block is considered as program lines and it is natural to stop inside the block literally. This is why I can't accept your request ("stop at line 8 from line 5 with next").
• (3) However, I found that the next at the end of block is inconsistent with (2) because (2) skips iter method but next from the end of the block jump to inside iter method as described in next stops in the wrong place when blocks are called #763 (comment)

(3) seems valuable to reconsidered. But now I don't have correct way to fix...

[ko1]

v1.7.0 may fix this issue.

[marianosimone]

I can confirm that, at least in ruby 2.7, this is still not fixed. I've simplified the test enough to this:

class NextDynamicMethodTest < ProtocolTestCase
    PROGRAM = <<~RUBY
       1| class Bar
       2|   define_method("dynamic") do
       3|     "dynamic"
       4|   end
       5|
       6|   def regular
       7|     "regular"
       8|   end
       9| end
      10|
      11| def foo(a, b, c); end
      12|
      13| bar = Bar.new
      14| foo(
      15|   bar.regular,
      16|   bar.dynamic,
      17|   bar.regular
      18| )
      19| bar
    RUBY

    def test_next_goes_to_the_next_statement
      run_protocol_scenario PROGRAM do
        req_add_breakpoint 14
        req_continue
        assert_line_num 14
        req_next
        assert_line_num 19 # When `TracePoint` returns the wrong number for :return after :b_return, this is 16

        req_terminate_debuggee
      end
    end
end

[ko1]

Thank you I verified

• 3.0 -> failed
• 3.1, 3.2 (released soon) -> success

[marianosimone]

Thank you I verified

• 3.0 -> failed
• 3.1, 3.2 (released soon) -> success

Coming back to this after I'm using Ruby 3.1, and I can verify that the issue is solved