Rubyで例外発生時にローカル変数とインスタンス変数をログに記録する方法

簡単には再現できないバグに悩まされたことはありませんか?アプリをしばらく使い続けたユーザーの環境でだけ発生し、エラーメッセージやバックトレースを見ても原因がさっぱり分からない——そんな経験を持つ開発者は多いはずです。

こうした場面で役立つのが、例外が発生する直前のアプリの状態をスナップショットとして記録しておく手法です。たとえば、すべてのローカル変数とその値の一覧を取得できれば、デバッグの強力な手がかりになります。実は、これは思ったより簡単に実現できるのです。

この記事では、例外発生時点でのローカル変数をキャプチャする方法を紹介します。ただし、最初に重要な注意点があります。ここで紹介するテクニックを本番環境(production)で使用してはいけません。ステージング、プレプロダクション、開発環境などであれば問題ありませんが、本番環境では避けてください。今回利用するgemは高度なイントロスペクション(リフレクション)の仕組みに依存しており、最良の場合でもアプリの動作を遅くし、最悪の場合は予測不能な問題を引き起こす可能性があります。

binding_of_callerとは

binding_of_callerというgemを使うと、現在のコールスタックの任意のレベルにある「バインディング(binding)」にアクセスできます。では、バインディングとは一体何なのでしょうか?

「スタック」とは、現在実行中のメソッドのリストのことです。callerメソッドを使うと、現在のスタックの状態を確認できます。以下はそのシンプルな例です。

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()

バインディングとは、現在の実行コンテキストのスナップショットです。次の例では、メソッド内でバインディングを取得し、それを使ってそのメソッドのローカル変数にアクセスしています。

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"

binding_of_caller gemを使えば、現在の実行スタックの任意のレベルにあるバインディングにアクセスできます。たとえば、cメソッドからaメソッドのローカル変数へアクセスすることも可能です。

require "rubygems"
require "binding_of_caller"

def a
  fruit = "orange"
  b()
end

def b
  fruit = "apple"
  c()
end

def c
  fruit = "pear"

  # 2つ上のレベルのバインディングを取得し、そのローカル変数"fruit"を取り出す
  puts binding.of_caller(2).local_variable_get(:fruit) 
end

a() # "orange" と表示される

ここまで読んで、あなたは2つの相反する感情を抱いているかもしれません。1つは「これは本当にクールだ!」という興奮。もう1つは「こんなものを使うと、あっという間に醜い依存関係の泥沼にハマりそうだ…」という警戒心です。

例外発生時にローカル変数をログ出力する

binding_of_callerの使い方をマスターしたところで、例外発生時にすべてのローカル変数をログ出力するのは実に簡単です。以下の例では、raiseメソッドをオーバーライドしています。新しいraiseメソッドは、まず自分を呼び出したメソッドのバインディングを取得し、そこからすべてのローカル変数を順番に取り出して出力します。

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()

実際に実行すると、次のようにローカル変数の内容が出力されます。

演習： インスタンス変数もログに出力してみよう

ローカル変数に加えてインスタンス変数もログに出力するのは、読者の皆さんへの演習課題として残しておきます。ヒント：my_binding.eval("instance_variables")とmy_binding.instance_variable_getは、my_binding.eval("local_variables")やmy_binding.local_variable_getとまったく同じ要領で使えます。

もっと簡単な方法

これはかなりクールなテクニックですが、ログファイルをgrepして手がかりを探すのは、必ずしも効率的なバグ修正方法ではありません。特に、アプリがステージング環境にあり複数人が同時に利用している場合はなおさらです。さらに言えば、自前で管理・保守すべきコードが増えることにもなります。

もしHoneybadgerを使ってアプリのエラーを監視しているなら、ローカル変数を自動的にキャプチャできます。必要なのは、Gemfileにbinding_of_caller gemを追加するだけです。

# Gemfile

group :development, :staging do
  # このgemを含めると、Honeybadger経由でローカル変数のキャプチャが有効になる
  gem "binding_of_caller"
  ...
end

これで設定完了です。以降、例外が発生するたびに、バックトレースやパラメータなどの情報と一緒に、すべてのローカル変数を含んだレポートを受け取れるようになります。