Bug #8538: c method not pushed into the callstack when called, but popped when returned

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: 2.1.0
• ruby -v: ruby 2.0.0p195 (2013-05-14) [i686-linux]
• Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

[deivid (David Rodríguez)]

See the following example:

trace = TracePoint.new do |tp|
  puts "Event: #{tp.event}, Method: #{tp.method_id}\n"
  puts "Stack: #{caller}\n\n"
end

trace.enable

fail "bang!"

The output shows:

Event: c_return, Method: enable
Stack: ["trace.rb:6:in `<main>'"]

Event: line, Method: 
Stack: ["trace.rb:8:in `<main>'"]

Event: c_call, Method: fail
Stack: ["trace.rb:8:in `<main>'"]

Event: c_call, Method: new
Stack: ["trace.rb:8:in `fail'", "trace.rb:8:in `<main>'"]

Event: c_call, Method: initialize
Stack: ["trace.rb:8:in `new'", "trace.rb:8:in `fail'", "trace.rb:8:in `<main>'"]

Event: c_return, Method: initialize
Stack: ["trace.rb:8:in `new'", "trace.rb:8:in `fail'", "trace.rb:8:in `<main>'"]

Event: c_return, Method: new
Stack: ["trace.rb:8:in `fail'", "trace.rb:8:in `<main>'"]

Event: c_call, Method: backtrace
Stack: ["trace.rb:8:in `<main>'"]

Event: c_return, Method: backtrace
Stack: ["trace.rb:8:in `<main>'"]

Event: raise, Method: 
Stack: ["trace.rb:8:in `<main>'"]

Event: c_return, Method: fail
Stack: ["trace.rb:8:in `<main>'"]

trace.rb:8:in `<main>': bang! (RuntimeError)

It looks like the method "initialize" is not pushed into the stack when called, but something (the previous method call) is popped when returning from it.

Thanks a lot.

[deivid (David Rodríguez)]

"no replies after 10 days" reminder. This is affecting https://github.com/deivid-rodriguez/byebug, I can easily make it crash by doing:

davidr@pantani:~/Proyectos/byebug$ ruby -Ilib -rbyebug -e 'byebug; fail "Bang!"'
-e @ 1
(byebug) catch Exception
Catch exception Exception.
(byebug) c
Catchpoint at -e:1: `Bang!' (RuntimeError)
        from /home/davidr/Proyectos/byebug/lib/byebug/context.rb:44:in `at_catchpoint'
    from -e:1:in `<main>'
-e @ 1
(byebug) bt
--> #0  <main> at -e:1
INTERNAL ERROR!!! That frame doesn't exist!
        /home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:90:in `frame_file'
        /home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:90:in `print_frame'
        /home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:85:in `block in print_backtrace'
        /home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:84:in `each'
        /home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:84:in `print_backtrace'
        /home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:127:in `execute'
        /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:260:in `one_cmd'
        /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:244:in `block (2 levels) in process_commands'
        /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:243:in `each'
        /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:243:in `block in process_commands'
        /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:236:in `catch'
        /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:236:in `process_commands'
        /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:158:in `at_line'
        (eval):5:in `block in at_line'
        (eval):3:in `synchronize'
        (eval):3:in `at_line'
        /home/davidr/Proyectos/byebug/lib/byebug/context.rb:52:in `at_line'
        -e:1:in `<main>'-e:1:in `<main>': Bang! (RuntimeError)

When the raise event comes, byebug thinks the stack size is 2 but there's only one element. I think this is caused by the inconsistent behaviour explained above.

Thanks a lot guys!

[judofyr (Magnus Holm)]

It seems like #initialize is never pushed to the stack:

class Foo
def initialize
puts caller
end
end

Foo.new

Result:

f.rb:8:in new' f.rb:8:in '

// Magnus Holm

On Thu, Jun 27, 2013 at 10:23 AM, deivid (David Rodríguez) <
[e-mail]> wrote:

Issue #8538 has been updated by deivid (David Rodríguez).

"no replies after 10 days" reminder. This is affecting
https://github.com/deivid-rodriguez/byebug, I can easily make it crash by
doing:

davidr@pantani:~/Proyectos/byebug$ ruby -Ilib -rbyebug -e 'byebug;

fail "Bang!"'
-e @ 1
(byebug) catch Exception
Catch exception Exception.
(byebug) c
Catchpoint at -e:1: Bang!' (RuntimeError) from /home/davidr/Proyectos/byebug/lib/byebug/context.rb:44:in at_catchpoint'
from -e:1:in `'
-e @ 1
(byebug) bt
--> #0 at -e:1
INTERNAL ERROR!!! That frame doesn't exist!

/home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:90:in
`frame_file'

/home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:90:in
`print_frame'

/home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:85:in `block in
print_backtrace'

/home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:84:in `each'

/home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:84:in
`print_backtrace'

/home/davidr/Proyectos/byebug/lib/byebug/commands/frame.rb:127:in execute' /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:260:in one_cmd'
/home/davidr/Proyectos/byebug/lib/byebug/processor.rb:244:in
block (2 levels) in process_commands' /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:243:in each'
/home/davidr/Proyectos/byebug/lib/byebug/processor.rb:243:in
block in process_commands' /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:236:in catch'
/home/davidr/Proyectos/byebug/lib/byebug/processor.rb:236:in
process_commands' /home/davidr/Proyectos/byebug/lib/byebug/processor.rb:158:in at_line'
(eval):5:in block in at_line' (eval):3:in synchronize'
(eval):3:in at_line' /home/davidr/Proyectos/byebug/lib/byebug/context.rb:52:in at_line'
-e:1:in <main>'-e:1:in ': Bang! (RuntimeError)

When the raise event comes, byebug thinks the stack size is 2 but there's
only one element. I think this is caused by the inconsistent behaviour
explained above.

Thanks a lot guys!

Bug #8538: c method not pushed into the callstack when called, but popped
when returned
https://bugs.ruby-lang.org/issues/8538#change-40173

Author: deivid (David Rodríguez)
Status: Open
Priority: Normal
Assignee:
Category:
Target version:
ruby -v: ruby 2.0.0p195 (2013-05-14) [i686-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

See the following example:

trace = TracePoint.new do |tp|
  puts "Event: #{tp.event}, Method: #{tp.method_id}\n"
  puts "Stack: #{caller}\n\n"
end

trace.enable

fail "bang!"

The output shows:

Event: c_return, Method: enable
Stack: ["trace.rb:6:in `<main>'"]

Event: line, Method:
Stack: ["trace.rb:8:in `<main>'"]

Event: c_call, Method: fail
Stack: ["trace.rb:8:in `<main>'"]

Event: c_call, Method: new
Stack: ["trace.rb:8:in `fail'", "trace.rb:8:in `<main>'"]

Event: c_call, Method: initialize
Stack: ["trace.rb:8:in `new'", "trace.rb:8:in `fail'", "trace.rb:8:in

`'"]

Event: c_return, Method: initialize
Stack: ["trace.rb:8:in `new'", "trace.rb:8:in `fail'", "trace.rb:8:in

`'"]

Event: c_return, Method: new
Stack: ["trace.rb:8:in `fail'", "trace.rb:8:in `<main>'"]

Event: c_call, Method: backtrace
Stack: ["trace.rb:8:in `<main>'"]

Event: c_return, Method: backtrace
Stack: ["trace.rb:8:in `<main>'"]

Event: raise, Method:
Stack: ["trace.rb:8:in `<main>'"]

Event: c_return, Method: fail
Stack: ["trace.rb:8:in `<main>'"]

trace.rb:8:in `<main>': bang! (RuntimeError)

It looks like the method "initialize" is not pushed into the stack when
called, but something (the previous method call) is popped when returning
from it.

Thanks a lot.

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

[deivid (David Rodríguez)]

judofyr (Magnus Holm) wrote:

It seems like #initialize is never pushed to the stack:

class Foo
def initialize
puts caller
end
end

Foo.new

Result:

f.rb:8:in new' f.rb:8:in '

// Magnus Holm

In your example, it is, you're just not printing the current frame

class Foo
  def initialize
    puts caller(0)
  end
end

Foo.new

Result:

f.rb:4 in `initialize'
f.rb:8:in `new'
f.rb:8:in `<main>'

[ko1 (Koichi Sasada)]

• Category set to core
• Assignee set to ko1 (Koichi Sasada)
• Target version set to 2.1.0

Is it similar problem of the following?
[ruby-core:52971] [ruby-trunk - Bug #7976][Open] TracePoint call is at call point, not call site

I will back from Euruko-mode in a few days.

[deivid (David Rodríguez)]

=begin
Thanks, @ko1 (Koichi Sasada). I commented the other issue, I think it's not the same thing.

I'm adding the actual output versus the expected output to try make this more clear.

tp = TracePoint.new do |tp|
  warn "%-8s %-11p %s" % [tp.event, tp.method_id, caller]
end
tp.enable

raise "bang!"

Actual output:

c_return :enable     ["bt_test.rb:4:in `<main>'"]
line     nil         ["bt_test.rb:6:in `<main>'"]
c_call   :raise      ["bt_test.rb:6:in `<main>'"]
c_call   :new        ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_call   :initialize ["bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :initialize ["bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :new        ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_call   :backtrace  ["bt_test.rb:6:in `<main>'"]
c_return :backtrace  ["bt_test.rb:6:in `<main>'"]
raise    nil         ["bt_test.rb:6:in `<main>'"]
c_return :raise      ["bt_test.rb:6:in `<main>'"]
bt_test.rb:6:in `<main>': bang! (RuntimeError)

Expected output:

c_return :enable     ["bt_test.rb:4:in `enable'", bt_test.rb:4:in `<main>'"]
line     nil         ["bt_test.rb:6:in `<main>'"]
c_call   :raise      ["bt_test.rb:6:in `<main>'"]
c_call   :new        ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_call   :initialize ["bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :initialize ["bt_test.rb:6:in `initialize'", "bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :new        ["bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_call   :backtrace  ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :backtrace  ["bt_test.rb:6:in `backtrace'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
raise    nil         ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :raise      ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
bt_test.rb:6:in `<main>': bang! (RuntimeError)

=end

[deivid (David Rodríguez)]

=begin
Maybe the granularity requested in my previous message implies more work. I would be fine with just correcting the inconsistent behaviour by not popping from the stack when returning from initialize. The expected output in this case would be

c_return :enable     ["bt_test.rb:4:in `<main>'"]
line     nil         ["bt_test.rb:6:in `<main>'"]
c_call   :raise      ["bt_test.rb:6:in `<main>'"]
c_call   :new        ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_call   :initialize ["bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :initialize ["bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :new        ["bt_test.rb:6:in `new'", "bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_call   :backtrace  ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :backtrace  ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
raise    nil         ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
c_return :raise      ["bt_test.rb:6:in `raise'", "bt_test.rb:6:in `<main>'"]
bt_test.rb:6:in `<main>': bang! (RuntimeError)

=end

Salute.

[deivid (David Rodríguez)]

=begin
Hi, I've been investigating this issue and I was misunderstanding it. The order of events is

1. Trigger C_CALL_EVENT
2. Push frame into the stack
3. Pop frame from the stack
4. Trigger C_RETURN_EVENT

That's why I thought initialize was never pushed into the stack. It is, of course, but it is popped before the TracePoint API can see it.

The issue can be closed. Thanks!
=end

• Status changed from Open to Closed