Tracing / Debugging ruby output like set -x in bash

In writing some shell scripts in ruby, I decided that I needed to be able to debug (trace) the lines that were being executed. I even ran across a closed StackOverflow question looking for the same thing.

code=ARGF.readlines.grep_v(/^$/)
eval code.map { |c| %Q|puts "+ #{c.gsub("\"", "\\"").strip}"| }.zip(code).join($/)

After playing around with one of the other answers (see above), I ended up taking a different tactic to try and figure out how to debug the scripts. (By the way, the above code breaks if you have line breaks in a single statement, like the following contrived example):

y = 2
      + 4

The important search term here is “trace”, or Tracer to be exact.

Take the following example:

bind = binding
p bind

bind.local_variable_set(:bind, 2)

p bind

p binding.local_variables

bind = binding

p eval("bind", bind)

if 2 > 3
  puts 2
else
  puts 3
end


if true
  puts "looks like the if true is compiled out"
end

if you run the above (contained in a filename binding.rb) using ruby -r tracer binding.rb then you get the following:

#0:/home/tpowell/.rbenv/versions/2.5.5/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:59:Kernel:<:       return gem_original_require(path)
#0:binding.rb:1::-: bind = binding
#0:binding.rb:2::-: p bind
#<Binding:0x000055fe6879cd38>
#0:binding.rb:4::-: bind.local_variable_set(:bind, 2)
#0:binding.rb:6::-: p bind
2
#0:binding.rb:8::-: p binding.local_variables
[:bind]
#0:binding.rb:10::-: bind = binding
#0:binding.rb:12::-: p eval("bind", bind)
#0:binding.rb:10::-: bind = binding
#<Binding:0x000055fe68835718>
#0:binding.rb:14::-: if 2 > 3
#0:binding.rb:17::-:   puts 3
3
#0:binding.rb:22::-:   puts "looks like the if true is compiled out"
looks like the if true is compiled out

One interesting difference between how ruby -r tracer works from set -x is that the ruby tracer appears skips evaluating the if true at all. The above runs were against ruby 2.5.5. Looking at 3.0.0 (and as far back as 2.6.x), I only get the output of the script:

#<Binding:0x000055af54e0c730>
2
[:bind]
#<Binding:0x000055af54e0c050>
3
looks like the if true is compiled out

Looking at Tracer, it’s using set_trace_func under the hood:

set_trace_func proc { |event, file, line, id, binding, classname|
  printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}

Adding that in the 2.6.x+ world returns:

c-return binding.rb:1  set_trace_func   Kernel
    line binding.rb:5
  c-call binding.rb:5     binding   Kernel
c-return binding.rb:5     binding   Kernel
    line binding.rb:6
  c-call binding.rb:6           p   Kernel
  c-call binding.rb:6     inspect   Kernel
c-return binding.rb:6     inspect   Kernel
.
.
.

That output can be filtered by the event type , but the lines of code themselves aren’t output and apparently set_trace_func was apparently obsoleted as of 2.1.10. TracePoint is the updated way to accomplish this:

trace = TracePoint.new(:line) do |tp|
  p tp
end
trace.enable
.
.
.

But we still have the same problem:

#<TracePoint:line@binding_trace_point.rb:8>
#<TracePoint:line@binding_trace_point.rb:9>
#<Binding:0x00005652f2a125e8>
#<TracePoint:line@binding_trace_point.rb:11>
#<TracePoint:line@binding_trace_point.rb:13>
2
#<TracePoint:line@binding_trace_point.rb:15>
[:trace, :bind]

A crude solution I’ve found around this is to read the line from the file mentioned in the TracePoint from within the block (and this apparently doesn’t end up with a stack overflow).

trace = TracePoint.new(:line) do |tp|
  puts "+ #{File.open(tp.path) { |f| f.each_line.to_a[tp.lineno-1] }}"
end

trace.enable
.
.
.

Which produces a somewhat set -x output:

+ bind = binding
+ p bind
#<Binding:0x000055ef6c9d9f70>
+ bind.local_variable_set(:bind, 2)
+ p bind
2
+ p binding.local_variables
[:trace, :bind]
+ bind = binding
+ p eval("bind", bind)
+ bind = binding
#<Binding:0x000055ef6c8321b8>
+ if 2 > 3
+   if 3 > 2
+     puts 3
3
+   puts "looks like the if true is compiled out"
looks like the if true is compiled out