From: "alanwu (Alan Wu)" <noreply@...>
Date: 2022-06-01T16:36:50+00:00
Subject: [ruby-core:108748] [Ruby master Bug#18730] Double `return` event handling with different tracepoints

Issue #18730 has been updated by alanwu (Alan Wu).


Here's some more information to round out this thread. I was a bit sloppy
in [ruby-core:108449] and the output I posted was misleading. The script
was observing return events from `tp.enable`. Tracing is tricky!
Here is an updated version of the script:

```ruby
# Script intended to observe handling of TracePoint hooks
# within one firing of a particular event.
(0..0b11).each do |mode|
  Class.new do
    def foo
      1
    end
    me = instance_method(:foo)

    # Unrelated targeting TracePoint. Its presence changes the output of mode 2
    # (global enables local) before a687756284187887835aa345adc89b2718054e4a.
    if false
      tp = TracePoint.new(:return) {}
      tp.enable(target: me)
    end

    one_enable = mode[0] == 1 ? { target: me } : {}
    two_enable = mode[1] == 1 ? { target: me } : {}
    one_ran = 0
    two_ran = 0

    two = TracePoint.new(:return) do |tp|
      next p tp unless tp.method_id == :foo
      two_ran += 1
      tp.disable
    end

    one = TracePoint.new(:return) do |tp|
      next p tp unless tp.method_id == :foo
      one_ran += 1
      two.enable(**two_enable)
      tp.disable
    end

    one.enable(**one_enable) do
      new.foo
    end

    p [mode, one_ran, two_ran]
  ensure
    two&.disable
  end
end

=begin
ruby 2.6.6p146 (2020-03-31 revision 67876) [x86_64-darwin19]
#<TracePoint:return `enable'@<internal:prelude>:138>
[0, 1, 0]
#<TracePoint:return `enable'@<internal:prelude>:138>
[1, 1, 0]
[2, 1, 0]
[3, 1, 0]

ruby 2.7.0p0 (2019-12-25 revision 647ee6f091) [x86_64-darwin19]
[0, 1, 0]
[1, 1, 0]
[2, 1, 0]
[3, 1, 0]

ruby 3.0.0p0 (2020-12-25 revision 95aff21468) [x86_64-darwin19]
[0, 1, 0]
#<TracePoint:return `enable' <internal:trace_point>:197>
[1, 1, 0]
[2, 1, 0]
[3, 1, 0]

ruby 3.1.0p0 (2021-12-25 revision fb4df44d16) [x86_64-darwin20]
[0, 1, 0]
#<TracePoint:return `enable' <internal:trace_point>:213>
[1, 1, 0]
[2, 1, 0]
[3, 1, 0]
=end
```

(the inconsistent prints _might_ be coming from the
tracing setup for `opt_invokebuiltin_delegate_leave`)

[ruby-core:108449]: https://bugs.ruby-lang.org/issues/18730#note-6

----------------------------------------
Bug #18730: Double `return` event handling with different tracepoints
https://bugs.ruby-lang.org/issues/18730#change-97807

* Author: hurricup (Alexandr Evstigneev)
* Status: Closed
* Priority: Normal
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN
----------------------------------------
I'm not sure if this is a bug or intentional behavior, but feels a bit unexpected. Ruby 3.0.x, 3.1.x affected.

Here is the script demonstrating the issue:
```
def bar
  42 #bp here
end

tp_line = TracePoint.new(:line) do |tp0|
  puts "Got line event from #{tp0.path}:#{tp0.lineno}"

  tp_multi1 = TracePoint.new(:return, :b_return, :line) do |tp|
    if tp.lineno == 3
      puts "Got first return `#{tp.event}` from #{tp.path}:#{tp.lineno}"
      tp.disable
      # tp0.disable # uncommenting this line changes things to the more expected 


      tp_multi2 = TracePoint.new(:return, :b_return, :line) do |tps|
        puts "Got second return `#{tps.event}` from #{tps.path}:#{tps.lineno}"
      end
      tp_multi2.enable(target: RubyVM::InstructionSequence.of(method :bar))
    end
  end
  tp_multi1.enable
end

tp_line.enable(target: RubyVM::InstructionSequence.of(method :bar))

bar
```
1. We set a line TP to the `bar` method `iseq` (consider it a line breakpoint)
2. When line event is triggered we setting another untargeted tracepoint for the same method, to catch `line`, `return` and `b_return` events (consider it attempt to step into something)
3. When return event of the `bar` method is triggered, we disabling second tracepoint and setting another one, targeted to the same method and multiple events.

Output i get:
```
Got line event from /home/hurricup/test.rb:2
Got first return `return` from /home/hurricup/test.rb:3
Got second return `return` from /home/hurricup/test.rb:3
```
The questions are: 
1. why return triggered on the second tracepoint, when we already handeled it?
2. why disabling line tracepoint changes behavior?




-- 
https://bugs.ruby-lang.org/

Unsubscribe: <mailto:ruby-core-request@ruby-lang.org?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>