How do I get ruby to print a full backtrace that includes arguments passed to functions?

Question

Sometimes backtrace is enough to diagnose problem. But sometimes reason of crash is not obvious without knowledge what was passed to function.

Getting information what was passed to function that caused crash would be quite useful, especially in cases where reproducing is not obvious because it was caused by for example exception in network connection, weird user input or because program is depends on randomisation or processes data from external sensor.

Lets say that there is following program

def handle_changed_input(changed_input)
    raise 'ops' if changed_input =~ /magic/
end

def do_something_with_user_input(input)
    input = "#{input.strip}c"
    handle_changed_input(input)
end

input = gets
do_something_with_user_input(input)

where user typed "magic" as input. Normally one has

test.rb:2:in `handle_changed_input': ops (RuntimeError)
    from test.rb:7:in `do_something_with_user_input'
    from test.rb:11:in `<main>'

as output. What one may do to show also what was passed to function? Something like

test.rb:2:in `handle_changed_input("magic")': ops (RuntimeError)
    from test.rb:7:in `do_something_with_user_input("magi\n")'
    from test.rb:11:in `<main>'

It would be useful in many situations (and not truly useful where parameters are not representable as strings of reasonable legth, there is a good reason why it is not enabled by default).

How one may add this functionality? It is necessary that program works as usually during normal operation and preferably there is no additional output before crash.

I tried for example

def do_something_with_user_input(input)
    method(__method__).parameters.map do |_, name|
        puts "#{name}=#{binding.local_variable_get(name)}"
    end
    raise 'ops' if input =~ /magic/
end

input = gets

found in Is there a way to access method arguments in Ruby? but it would print on every single entrance to function what both would flood output and make program significantly slower.

Answer 1

I think that it is possible. The code below is not perfect and would require some additional work, but it caputers the primary idea of a stacktrace with argument values. Please note, that in order to know the call site, I am zipping the original stacktrace with the entry sites catched by trace function. To distinguishe these entries I use '>' and '<' respectively.

class Reporting
  def self.info(arg1)
    puts "*** #{arg1} ***"
  end
end


def read_byte(arg1)
  Reporting.info(arg1)
  raise Exception.new("File not found")
end

def read_input(arg1)
  read_byte(arg1)
end

def main(arg1)
  read_input(arg1)
end


class BetterStacktrace
  def self.enable
    set_trace_func -> (event, file, line, id, binding, classname) do
      case event
      when 'call'
        receiver_type = binding.eval('self.class')
        if receiver_type == Object
          meth = binding.eval('__method__')
          params = binding.method(meth).parameters.select{|e| e[0] != :block}
          values = params.map{|_, var| [var, binding.local_variable_get(var)]}
          self.push(event, file, line, id, classname, values)
        else
          self.push(event, file, line, id, classname)
        end
      when 'return'
        self.pop
      when 'raise'
        self.push(event, file, line, id, classname)
        Thread.current[:_keep_stacktrace] = true
      end
    end
  end

  def self.push(event, file, line, id, classname, values=nil)
    Thread.current[:_saved_stacktrace] = [] unless Thread.current.key?(:_saved_stacktrace)
    unless Thread.current[:_keep_stacktrace]
      if values
        values_msg = values.map(&:last).join(", ")
        msg = "%s:%d:in `%s(%s)'" % [file, line, id, values_msg]
      else
        msg = "%s:%d:in `%s'" % [file, line, id]
      end
      Thread.current[:_saved_stacktrace] << msg
    end
  end

  def self.pop()
    Thread.current[:_saved_stacktrace] = [] unless Thread.current.key?(:_saved_stacktrace)
    unless Thread.current[:_keep_stacktrace]
      value = Thread.current[:_saved_stacktrace].pop
    end
  end

  def self.disable
    set_trace_func nil
  end

  def self.print_stacktrace(calls)
    enters = Thread.current[:_saved_stacktrace].reverse
    calls.zip(enters).each do |call, enter|
      STDERR.puts "> #{enter}"
      STDERR.puts "< #{call}"
    end
    Thread.current[:_saved_stacktrace] = []
  end
end

BetterStacktrace.enable

begin
  main(10)
rescue Exception => ex
  puts "--- Catched ---"
  puts ex
  BetterStacktrace.print_stacktrace(ex.backtrace)
end


BetterStacktrace.disable
begin
  main(10)
rescue Exception
  puts "--- Catched ---"
  puts ex
  puts ex.backtrace
end

The output of the above code is as follows:

*** 10 ***
--- Catched ---
File not found
> work/tracing_with_params.rb:10:in `read_byte'
< work/tracing_with_params.rb:10:in `read_byte'
> work/tracing_with_params.rb:8:in `read_byte(10)'
< work/tracing_with_params.rb:14:in `read_input'
> work/tracing_with_params.rb:13:in `read_input(10)'
< work/tracing_with_params.rb:18:in `main'
> work/tracing_with_params.rb:17:in `main(10)'
< work/tracing_with_params.rb:82:in `<main>'
*** 10 ***
--- Catched ---
File not found
work/tracing_with_params.rb:10:in `read_byte'
work/tracing_with_params.rb:14:in `read_input'
work/tracing_with_params.rb:18:in `main'
work/tracing_with_params.rb:82:in `<main>'

EDIT:

The calls to class functions are not recorded. This has to be fixed in order for the stacktrace printing function not to get invalid output. Moreover I used the STDERR as output to easily get one or the other output. You can change it if you wish.

Answer 2

MAX_STACK_SIZE = 200
tracer = proc do |event|
  if event == 'call' && caller_locations.length > MAX_STACK_SIZE
    fail "Probable Stack Overflow"
  end
end
set_trace_func(tracer)

Answer 3

I don't have a complete solution but... But you can get method arguments of all called methods in controlled environment with TracePoint class from Ruby core lib.

Look at the example:

trace = TracePoint.new(:call) do |tp|
  puts "===================== #{tp.method_id}"
  b_self = tp.binding.eval('self')
  names = b_self.method(tp.method_id).parameters.map(&:last)
  values = names.map { |name| tp.binding.eval(name.to_s) }
  p names.zip(values)
end

trace.enable

def method_a(p1, p2, p3)
end

method_a(1, "foobar", false)

#=> ===================== method_a
#=> [[:p1, 1], [:p2, "foobar"], [:p3, false]]

Answer 4

To print exception backtraces, Ruby uses the C function exc_backtrace from error.c (exc_backtrace on github). Unless you patch Ruby with the functionality you need, I don't think there a way to change exception backtrace outputs. Here is a snippet (trace.rb) you might find useful:

set_trace_func -> (event, file, line, id, binding, classname) do
  if event == 'call' && meth = binding.eval('__method__')
    params = binding.method(meth).parameters.select{|e| e[0] != :block}
    values = params.map{|_, var| [var, binding.local_variable_get(var)]}
    printf "%8s %s:%-2d %15s %8s %s\n", event, file, line, id, classname, values.inspect
  else
    printf "%8s %s:%-2d %15s %8s\n", event, file, line, id, classname
  end
end


def foo(a,b = 0)
  bar(a, foo: true)
end

def bar(c, d = {})
  puts "!!!buz!!!\n"
end

foo('lol')

The output of that snippet is:

c-return /path/to/trace.rb:1   set_trace_func   Kernel
    line /path/to/trace.rb:12
  c-call /path/to/trace.rb:12    method_added   Module
c-return /path/to/trace.rb:12    method_added   Module
    line /path/to/trace.rb:16
  c-call /path/to/trace.rb:16    method_added   Module
c-return /path/to/trace.rb:16    method_added   Module
    line /path/to/trace.rb:20
    call /path/to/trace.rb:12             foo   Object [[:a, "lol"], [:b, 0]]
    line /path/to/trace.rb:13             foo   Object
    call /path/to/trace.rb:16             bar   Object [[:c, "lol"], [:d, {:foo=>true}]]
    line /path/to/trace.rb:17             bar   Object
  c-call /path/to/trace.rb:17            puts   Kernel
  c-call /path/to/trace.rb:17            puts       IO
  c-call /path/to/trace.rb:17           write       IO
!!!buz!!!
c-return /path/to/trace.rb:17           write       IO
c-return /path/to/trace.rb:17            puts       IO
c-return /path/to/trace.rb:17            puts   Kernel
  return /path/to/trace.rb:18             bar   Object
  return /path/to/trace.rb:14             foo   Object

I hope that helps you as much as it helped me.