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.

Zoophilia

If I correctly understood you need to print out which arguments were passed to a method that raised an error. Is that correct? – Niello

It doesn't make sense to generalize this for all method calls because object arguments may not have a meaningful string representation. All you'd see is something like: #<Object:0x007ff6d3b7af08> – Oxyhydrogen

@Oxyhydrogen I know that there are many, many situations where this would make no sense (objects without conversion to string, very long strings, programs handling private data and many many other cases). But in situations where methods have arguments that are either strings or objects with implemented to string conversion it would be quite useful. See also "there is a good reason why it is not enabled by default". – Zoophilia

@Niello Thank you very much, initial version of the question was not clear. I want to print out arguments of all methods in stacktrace - starting from one where exception happened. I amended question to make it more obvious that I want to see parameters of all methods. – Zoophilia

@MateuszKonieczny: I'd like to collect that bounty, but I'm afraid that what you want to do is not practically possible. – Samoyedic

@SergioTulentsev "it can't be done for following reasons" is also a valid answer. – Zoophilia

@MateuszKonieczny: yep, I would have posted that, but the only reason I came up with is "because that's how it is [everywhere]". Tried to look for possible solutions in the ruby source code, but it turned out to be way above my pay grade. :) – Samoyedic

i guess that answer of this question should help you – Orthopedist

Answer 1

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]]

Themis

I am unsure if expected, but this code creates a recursion... also unsure how to prevent. – Debrahdebrecen

Answer 2

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.

Sunroom

Answer 3

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.

Collation

Answer 4

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)

Shupe