Bug #8538
closedc method not pushed into the callstack when called, but popped when returned
Description
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.
Updated by deivid (David Rodríguez) over 11 years ago
"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!
Updated by judofyr (Magnus Holm) over 11 years ago
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) <
deivid.rodriguez@gmail.com> 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:inblock in at_line' (eval):3:in
synchronize'
(eval):3:inat_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-40173Author: 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: UNKNOWNSee 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.
Updated by deivid (David Rodríguez) over 11 years ago
judofyr (Magnus Holm) wrote:
It seems like #initialize is never pushed to the stack:
class Foo
def initialize
puts caller
end
endFoo.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>'
Updated by ko1 (Koichi Sasada) over 11 years ago
- 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.¶
Updated by deivid (David Rodríguez) over 11 years ago
=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
Updated by deivid (David Rodríguez) over 11 years ago
=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.
Updated by deivid (David Rodríguez) about 11 years ago
=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
Updated by Anonymous about 11 years ago
- Status changed from Open to Closed