ruby-core@ruby-lang.org archive (unofficial mirror)
 help / color / mirror / Atom feed
* [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
@ 2022-04-14 14:50 hurricup (Alexandr Evstigneev)
  2022-04-26 20:40 ` [ruby-core:108408] " jeremyevans0 (Jeremy Evans)
                   ` (6 more replies)
  0 siblings, 7 replies; 8+ messages in thread
From: hurricup (Alexandr Evstigneev) @ 2022-04-14 14:50 UTC (permalink / raw
  To: ruby-core

Issue #18730 has been reported by hurricup (Alexandr Evstigneev).

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

* Author: hurricup (Alexandr Evstigneev)
* Status: Open
* 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

      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 question is: why return triggered on the second tracepoint, when we already handeled it?




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

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [ruby-core:108408] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
  2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
@ 2022-04-26 20:40 ` jeremyevans0 (Jeremy Evans)
  2022-04-28 22:37 ` [ruby-core:108437] " jeremyevans0 (Jeremy Evans)
                   ` (5 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: jeremyevans0 (Jeremy Evans) @ 2022-04-26 20:40 UTC (permalink / raw
  To: ruby-core

Issue #18730 has been updated by jeremyevans0 (Jeremy Evans).


hurricup (Alexandr Evstigneev) wrote:
> The questions are: 
> 1. why return triggered on the second tracepoint, when we already handeled it?

You are adding and enabling a separate return event tracepoint (`tp_multi2`) on the same method before the method returns, while it is still in the process of handling the first return event tracepoint (`tp_multi1`).  I don't think it is unexpected that this tracepoint (`tp_multi2`) would also be called.  Note that if you add a `tp_multi2.disable` call directly after the `tp_multi2.enable` call, you don't get the second return event printed.

> 2. why disabling line tracepoint changes behavior?

On the master branch, if I uncomment the `tp0.disable` call, I get a segfault with the following backtrace:

```
Thread 1 received signal SIGSEGV, Segmentation fault.
0x00000885cb83e9eb in exec_hooks_body (ec=0x884de217650, list=0x8859bf5fd20,
    trace_arg=0x7f7ffffdfd68) at vm_trace.c:325
325             if (!(hook->hook_flags & RUBY_EVENT_HOOK_FLAG_DELETED) &&
(gdb) bt
#0  0x00000885cb83e9eb in exec_hooks_body (ec=0x884de217650, list=0x8859bf5fd20,
    trace_arg=0x7f7ffffdfd68) at vm_trace.c:325
#1  0x00000885cb839f60 in exec_hooks_protected (ec=0x884de217650, list=0x8859bf5fd20,
    trace_arg=0x7f7ffffdfd68) at vm_trace.c:380
#2  0x00000885cb839cb7 in rb_exec_event_hooks (trace_arg=0x7f7ffffdfd68, hooks=0x8859bf5fd20,
    pop_p=0) at vm_trace.c:424
#3  0x00000885cb7fff11 in rb_exec_event_hook_orig (ec=0x884de217650, hooks=0x8859bf5fd20,
    flag=16, self=9368423812640, id=0, called_id=0, klass=0, data=85, pop_p=0)
    at ./vm_core.h:2030
#4  0x00000885cb826d8a in vm_trace_hook (ec=0x884de217650, reg_cfp=0x8854a7fdf40,
    pc=0x8859bf78330, pc_events=16, target_event=532, global_hooks=0x884de24f410,
    local_hooks=0x8859bf5fd20, val=85) at ./vm_insnhelper.c:5646
#5  0x00000885cb822dd4 in vm_trace (ec=0x884de217650, reg_cfp=0x8854a7fdf40)
    at ./vm_insnhelper.c:5749
#6  0x00000885cb7f0cec in vm_exec_core (ec=0x884de217650, initial=0) at vm.inc:5100
#7  0x00000885cb803ac3 in rb_vm_exec (ec=0x884de217650, mjit_enable_p=true) at vm.c:2287
#8  0x00000885cb804a42 in rb_iseq_eval_main (iseq=0x884e4ec4b60) at vm.c:2546
#9  0x00000885cb57f9e6 in rb_ec_exec_node (ec=0x884de217650, n=0x884e4ec4b60) at eval.c:280
#10 0x00000885cb57f8a1 in ruby_run_node (n=0x884e4ec4b60) at eval.c:321
#11 0x00000882cf893db0 in rb_main (argc=3, argv=0x7f7ffffe18d8) at ./main.c:47
#12 0x00000882cf893dff in main (argc=3, argv=0x7f7ffffe18d8) at ./main.c:56
(gdb) p hook
$1 = (rb_event_hook_t *) 0xdfdfdfdfdfdfdfdf
```

`0xdfdfdfdfdfdfdfdf` is the pattern OpenBSD's memory allocator uses for freed data, so this is almost definitely a use-after-free bug.

I was able to simplify the reproducer:

```ruby
def bar
  42 #bp here
end

tp_line = TracePoint.new(:line) do |tp0|
  tp_multi1 = TracePoint.new(:return, :b_return, :line) do |tp|
    tp0.disable
  end
  tp_multi1.enable
end

# Removing the target for this enable call fixes the segfault
tp_line.enable(target: RubyVM::InstructionSequence.of(method :bar))

bar
```

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

* Author: hurricup (Alexandr Evstigneev)
* Status: Open
* 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/

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [ruby-core:108437] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
  2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
  2022-04-26 20:40 ` [ruby-core:108408] " jeremyevans0 (Jeremy Evans)
@ 2022-04-28 22:37 ` jeremyevans0 (Jeremy Evans)
  2022-04-29 11:05 ` [ruby-core:108444] " hurricup (Alexandr Evstigneev)
                   ` (4 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: jeremyevans0 (Jeremy Evans) @ 2022-04-28 22:37 UTC (permalink / raw
  To: ruby-core

Issue #18730 has been updated by jeremyevans0 (Jeremy Evans).


I've submitted a pull request to fix the use-after-free bug: https://github.com/ruby/ruby/pull/5862

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

* Author: hurricup (Alexandr Evstigneev)
* Status: Open
* 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/

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [ruby-core:108444] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
  2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
  2022-04-26 20:40 ` [ruby-core:108408] " jeremyevans0 (Jeremy Evans)
  2022-04-28 22:37 ` [ruby-core:108437] " jeremyevans0 (Jeremy Evans)
@ 2022-04-29 11:05 ` hurricup (Alexandr Evstigneev)
  2022-04-30  0:50 ` [ruby-core:108449] " alanwu (Alan Wu)
                   ` (3 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: hurricup (Alexandr Evstigneev) @ 2022-04-29 11:05 UTC (permalink / raw
  To: ruby-core

Issue #18730 has been updated by hurricup (Alexandr Evstigneev).


jeremyevans0 (Jeremy Evans) wrote in #note-4:
> I've submitted a pull request to fix the use-after-free bug: https://github.com/ruby/ruby/pull/5862

I can confirm that with this patch, behavior is consistent and do not depend on `tp0` state. Return event is always handled by both handlers. 
But it still feels strange and inconsistent.
E.g. this code should stuck in infinite loop, but it passes 2 times and that's it:
```
def bar
  42 #bp here
end

def set_return_tp
  TracePoint.new(:return) do |tp|
    puts 'Return hit'
    tp.disable
    set_return_tp
  end.enable
end

set_return_tp
bar
```

Or: 
```
def bar
  42 #bp here
end

def set_return_tp1
  TracePoint.new(:return) do |tp|
    puts 'Return hit 1'
    tp.disable
    set_return_tp2
  end.enable
end

def set_return_tp2
  TracePoint.new(:return) do |tp|
    puts 'Return hit 2'
    tp.disable
    set_return_tp1
  end.enable(target: RubyVM::InstructionSequence.of(method :bar))
end

set_return_tp1
#set_return_tp2
bar
```
This hits twice. 

And
```
def bar
  42 #bp here
end

def set_return_tp1
  TracePoint.new(:return) do |tp|
    puts 'Return hit 1'
    tp.disable
    set_return_tp2
  end.enable
end

def set_return_tp2
  TracePoint.new(:return) do |tp|
    puts 'Return hit 2'
    tp.disable
    set_return_tp1
  end.enable(target: RubyVM::InstructionSequence.of(method :bar))
end

#set_return_tp1
set_return_tp2
bar
```
This hits once.

So something is definitely wrong there. 


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

* Author: hurricup (Alexandr Evstigneev)
* Status: Open
* 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/

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [ruby-core:108449] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
  2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
                   ` (2 preceding siblings ...)
  2022-04-29 11:05 ` [ruby-core:108444] " hurricup (Alexandr Evstigneev)
@ 2022-04-30  0:50 ` alanwu (Alan Wu)
  2022-04-30  5:32 ` [ruby-core:108450] " hurricup (Alexandr Evstigneev)
                   ` (2 subsequent siblings)
  6 siblings, 0 replies; 8+ messages in thread
From: alanwu (Alan Wu) @ 2022-04-30  0:50 UTC (permalink / raw
  To: ruby-core

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


So having just read the code, I understand why you are seeing this behavior.
We run global handlers before local handlers, so if you have a global
handler G and a local handler L, and G enables L, they both run. It is weird
because this seems to be the only situation where two handlers interact.

Here is a script to show all 4 possible choices for global versus local for
the two interacting handlers:

```ruby
(0..0b11).each do |mode|
  Class.new do
    def foo
      1
    end
    me = instance_method(:foo)

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

    two = TracePoint.new(:return) do
      two_ran = true
      two.disable
    end

    one = TracePoint.new(:return) do
      one_ran = true
      two.enable(**two_enable)
      one.disable
    end

    one.enable(**one_enable)

    new.foo

    p [mode, one_ran, two_ran]
  end
end
```

The output has evolved over time:
```
ruby 2.6.6p146 (2020-03-31 revision 67876) [x86_64-darwin19]
[0, true, true]
[1, true, false]
[2, true, true]
[3, true, false]
ruby 2.7.3p183 (2021-04-05 revision 6847ee089d) [x86_64-darwin19]
[0, true, false]
[1, true, false]
[2, true, false]
[3, true, false]
ruby 3.0.0p0 (2020-12-25 revision 95aff21468) [x86_64-darwin19]
[0, true, false]
[1, true, false]
[2, true, true]
[3, true, false]
# 3.1 same as 3.0
```

I suppose 2.7 behavior is the most consistent.

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

* Author: hurricup (Alexandr Evstigneev)
* Status: Open
* 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/

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [ruby-core:108450] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
  2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
                   ` (3 preceding siblings ...)
  2022-04-30  0:50 ` [ruby-core:108449] " alanwu (Alan Wu)
@ 2022-04-30  5:32 ` hurricup (Alexandr Evstigneev)
  2022-05-02 18:33 ` [ruby-core:108459] " alanwu (Alan Wu)
  2022-06-01 16:36 ` [ruby-core:108748] " alanwu (Alan Wu)
  6 siblings, 0 replies; 8+ messages in thread
From: hurricup (Alexandr Evstigneev) @ 2022-04-30  5:32 UTC (permalink / raw
  To: ruby-core

Issue #18730 has been updated by hurricup (Alexandr Evstigneev).


alanwu (Alan Wu) wrote in #note-6:
> So having just read the code, I understand why you are seeing this behavior.
> We run global handlers before local handlers, so if you have a global
> handler G and a local handler L, and G enables L, they both run. It is weird
> because this seems to be the only situation where two handlers interact.

Aren't both handlers same (global) in my first example? 
```
def bar
  42 #bp here
end

def set_return_tp
  TracePoint.new(:return) do |tp|
    puts 'Return hit'
    tp.disable
    set_return_tp
  end.enable
end

set_return_tp
bar
```

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

* Author: hurricup (Alexandr Evstigneev)
* Status: Open
* 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/

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [ruby-core:108459] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
  2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
                   ` (4 preceding siblings ...)
  2022-04-30  5:32 ` [ruby-core:108450] " hurricup (Alexandr Evstigneev)
@ 2022-05-02 18:33 ` alanwu (Alan Wu)
  2022-06-01 16:36 ` [ruby-core:108748] " alanwu (Alan Wu)
  6 siblings, 0 replies; 8+ messages in thread
From: alanwu (Alan Wu) @ 2022-05-02 18:33 UTC (permalink / raw
  To: ruby-core

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


> Aren't both handlers same (global) in my first example?

They are, but the two invocations are coming from two
separate events while my script is concerned with handling
within one event. You can see this from a slightly modified
version of your script:

```ruby
def bar
  42 #bp here
end

def set_return_tp
  TracePoint.new(:return) do |tp|
    puts "Return hit #{tp.method_id}"
    tp.disable
    set_return_tp
  end.enable
end

set_return_tp
p :gap
bar
```

```
Return hit set_return_tp
:gap
Return hit bar
```


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

* Author: hurricup (Alexandr Evstigneev)
* Status: Open
* 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/

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [ruby-core:108748] [Ruby master Bug#18730] Double `return` event handling with different tracepoints
  2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
                   ` (5 preceding siblings ...)
  2022-05-02 18:33 ` [ruby-core:108459] " alanwu (Alan Wu)
@ 2022-06-01 16:36 ` alanwu (Alan Wu)
  6 siblings, 0 replies; 8+ messages in thread
From: alanwu (Alan Wu) @ 2022-06-01 16:36 UTC (permalink / raw
  To: ruby-core

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/

^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2022-06-01 16:37 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-04-14 14:50 [ruby-core:108237] [Ruby master Bug#18730] Double `return` event handling with different tracepoints hurricup (Alexandr Evstigneev)
2022-04-26 20:40 ` [ruby-core:108408] " jeremyevans0 (Jeremy Evans)
2022-04-28 22:37 ` [ruby-core:108437] " jeremyevans0 (Jeremy Evans)
2022-04-29 11:05 ` [ruby-core:108444] " hurricup (Alexandr Evstigneev)
2022-04-30  0:50 ` [ruby-core:108449] " alanwu (Alan Wu)
2022-04-30  5:32 ` [ruby-core:108450] " hurricup (Alexandr Evstigneev)
2022-05-02 18:33 ` [ruby-core:108459] " alanwu (Alan Wu)
2022-06-01 16:36 ` [ruby-core:108748] " alanwu (Alan Wu)

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).