Logging local & instance variables when exceptions occur in Ruby

Have you ever had a bug that you couldn't easily reproduce? It only seems to happen when people have used your app for a while. And the error message and backtrace are surprisingly unhelpful.

It's times like these that it would be really handy if you could take a snapshot of the app's state just before the exception occurred. If you could have, for example, a list of all the local variables and their values.  Well, you can - and it's not even that hard!

In this post I'll show you how to capture locals at the time of an exception. But first, I need to warn you. None of these techniques should be used in production. You can use them in staging, preprod, development, etc. Just not production. The gems we'll use rely on some pretty heavy introspection magic, that at best will slow your app down. At worst...who knows?

Introducing binding_of_caller

The binding_of_caller gem lets you access bindings for any level of the current stack. Sooo.....what exactly does that mean?

The "stack" is simply a list of methods currently "in-progress."  You can use the caller method to examine the current stack.  Here's a simple example:

def a
  puts caller.inspect # ["caller.rb:20:in `<main>'"]
  b()
end

def b
  puts caller.inspect # ["caller.rb:4:in `a'", "caller.rb:20:in `<main>'"]
  c()
end

def c
  puts caller.inspect # ["caller.rb:11:in `b'", "caller.rb:4:in `a'", "caller.rb:20:in `<main>'"]
end

a()

A binding is a snapshot of the current execution context. In the example below, I capture the binding of a method, then use it to access the method's local variables.

def get_binding
  a = "marco"
  b = "polo"
  return binding
end

my_binding = get_binding

puts my_binding.local_variable_get(:a) # "marco"
puts my_binding.local_variable_get(:b) # "polo"

The binding_of_caller gem gives you access to the binding for any level of the current execution stack. For example, I could use it to allow the c method access to the a method's local variables.

require "rubygems"
require "binding_of_caller"

def a
  fruit = "orange"
  b()
end

def b
  fruit = "apple"
  c()
end

def c
  fruit = "pear"

  # Get the binding "two levels up" and ask it for its local variable "fruit"
  puts binding.of_caller(2).local_variable_get(:fruit) 
end

a() # prints "orange"

At this point, you're probably feeling two conflicting emotions. Excitement, because this is REALLY COOL. And revulsion, because this could degenerate into an ugly mess of dependencies faster than you can say DHH.

Logging locals at the time of exception

Now that we've mastered binding_of_caller, logging all the local variables at the time of exception is a piece of cake. In the example below I'm overriding the raise method. My new raise method fetches the binding of whatever method called it. Then it iterates through all locals and prints them out.

require "rubygems"
require "binding_of_caller"

module LogLocalsOnRaise
  def raise(*args)
    b = binding.of_caller(1)
    b.eval("local_variables").each do |k|
      puts "Local variable #{ k }: #{ b.local_variable_get(k) }"
    end
    super
  end
end

class Object
  include LogLocalsOnRaise
end

def buggy
  s = "hello world"
  raise RuntimeError
end

buggy()

Here's what it looks like in action:

Exercise: Log instance variables

I'll leave it as an exercise for you to log instance variables alongside locals. Here's a hint: you can use my_binding.eval("instance_variables") and my_binding.instance_variable_get in exactly the same way that you would use my_binding.eval("local_variables") and my_binding.instance_variable_get.

The easy way

This is a pretty cool trick. But grepping around log files isn't the most convenient way to fix bugs, especially if your app is on staging and you have multiple people using it. Also, it's just more code that you have to maintain.

If you happen to use Honeybadger to monitor your app for errors, we can capture locals automatically. All you have to do is add the binding_of_caller gem to your Gemfile:

# Gemfile

group :development, :staging do
  # Including this gem enables local variable capture via Honeybadger
  gem "binding_of_caller"
  ...
end

Now, whenever an exception occurs, you'll get a report of all locals along with the backtrace, params, etc.