Bug #9009: Wrong binding when tracing c-calls

• Status: Open
• Priority: Normal
• Assignee: -
• Target version: -
• ruby -v: ruby 2.1.0dev (2013-10-04 trunk 43141) [x86_64-linux]
• Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

[yekka (Nikolay Bozhenov)]

When I use set_trace_func to trace ruby code, I get a wrong binding in
case of c-calls. In this case binding.eval("self") is not the receiver
of the call. Whereas in case of ruby-calls binding.eval("self") yields
the receiver of the call.
The underlying problem is that c-calls aren't pushed onto the frame stack.
It seems that currently there is no way to find out the receiver of c-call
inside tracing function.

Example of code:

$ cat test.rb
class IO
def some_method
end
end

puts "true receiver is #{$stdout}\n\n"

set_trace_func proc { |event, file, line, id, binding, classname|
if event == "call" or event == "c-call"
puts "#{event} #{id}:"
puts "\tapparent receiver = #{binding.eval("self")}"
puts "\tbacktrace:"
caller.each { |l| puts "\t\t#{l}" }
puts
end
}

$stdout.write "" # c-call
$stdout.some_method # ruby-call

Execution:

$ ruby test.rb
true receiver is #IO:0x00000000bed2a0

c-call write:
apparent receiver = main
backtrace:
test.rb:18:in `'

call some_method:
apparent receiver = #IO:0x00000000bed2a0
backtrace:
test.rb:2:in some_method'
test.rb:19:in'

Expected result:

true receiver is #IO:0x00000000bed2a0

c-call write:
apparent receiver = #IO:0x00000000bed2a0
backtrace:
somewhere:in write'
test.rb:18:in'

call some_method:
apparent receiver = #IO:0x00000000bed2a0
backtrace:
test.rb:2:in some_method'
test.rb:19:in'

[deivid (David Rodríguez)]

=begin
Hi, I've translate your example to use the TracePoint API

This is the example and result:

class IO
  def some_method
  end
end

puts "true receiver is #{$stdout}\n\n"

TracePoint.trace(:c_call, :call) do |tp|
  puts "#{tp.event} #{tp.defined_class} #{tp.method_id}"
  puts "  apparent receiver = #{tp.self} vs #{tp.binding.eval('self')}"
  Thread.current.backtrace_locations(2).each { |loc| puts "    #{loc}" }
end

$stdout.write ""
$stdout.some_method

results in

true receiver is #<IO:0x8bf4e58>

c_call IO write
  apparent receiver = #<IO:0x8bf4e58> vs main
    test.rb:15:in `<main>'
call IO some_method
  apparent receiver = #<IO:0x8bf4e58> vs #<IO:0x8bf4e58>
    test.rb:2:in `some_method'
    test.rb:16:in `<main>'

My comments:

• Seems like the new way to get the receiver is the (({#self})) instance method of the (({TracePoint})) class. However, the documentation states "(({Same as #binding: trace.binding.eval('self')}))", so that should probably be corrected or further explained.

  • Regarding c-frames not being pushed onto the frame stack, they actually are, but after the Tracepoint/set_trace_func event. I made the same mistake here: #8538. Have a look at source:vm_insnhelper.c#L1514 and observe how (({vm_push_frame})) is called after (({EXEC_EVENT_HOOK})).

• I still think the behaviour should be consistent and when inside a TracePoint event the current frame should either be already in the backtrace or not, but not behave differently for c methods and ruby methods.

=end