RubyのTracePointで複雑な例外の挙動を調査する方法

例外の挙動を把握するのは、時に非常に難しいものです。特に大規模なアプリケーションではその傾向が強まります。既存のプロジェクトでコードを書いていて、例外をraiseしたのに奇妙なことが起こった経験はありませんか?例外がどこかで握りつぶされている。環境変数が書き換えられている。あるいは、自分のraiseした例外が別の例外に包まれてしまう——そんなケースです。

この記事では、TracePointを使ってアプリケーション内の例外についてより詳しい情報を得るためのシンプルな方法を紹介します。例外が握りつぶされていたとしても、その動きを追跡できます。

わかりやすい例:コントローラでrescueできないビューのエラー

Railsにおけるコントローラとビューの境界は、例外が直感に反して動くことで有名な場所の一つです。これは簡単に確認できます。ビューの中で例外をraiseし、それをコントローラ側でrescueしてみてください。すると、テンプレートのエラーはコントローラからはrescueできないことに気づくはずです。

# pages_controller.rb

def index
  render
rescue
  # この行は絶対に実行されない
  logger.debug "someone raised the roof"
end

# index.haml

- raise "the roof"

WTF!?! rescueしたはずなのに!?

明らかに裏で何か巧妙な仕掛けが働いています。その正体を見ていきましょう。

TracePointで発生したすべての例外をログに記録する

TracePointはRuby 2.0から搭載されている強力なイントロスペクション(リフレクション)ツールです。実行時のさまざまなイベントに対してコールバックを定義でき、たとえば「クラスが定義されたとき」「メソッドが呼び出されたとき」「例外が発生したとき」などに通知を受け取れます。対応しているイベントはほかにも多数あるので、詳細はTracePointの公式ドキュメントを参照してください。

まずは、例外がraiseされるたびに呼び出され、その概要をログに出力するTracePointを追加してみましょう。

class PagesController < ApplicationController
  def index
    TracePoint.new(:raise) do |tp|
      # tp.raised_exception には、実際にraiseされた例外オブジェクトが入っている!
      logger.debug "#{tp.raised_exception.object_id}: #{tp.raised_exception.class} #{tp.raised_exception.message} ".yellow + tp.raised_exception.backtrace[0].sub(Rails.root.to_s, "").blue
    end.enable do
      render
    end
  end
end

yellowやblueといったメソッドが気になる方のために補足すると、これは色付き出力用のgem「colorize」が提供するもので、ログにANSIカラーコードを付加して見やすくしてくれます。

この状態でページを更新すると、ログには下のスクリーンショットのような内容が出力されます。ここで注目したいのは、2種類の例外がそれぞれ2回ずつraiseされているという点です。各行の先頭にある長い数字は例外オブジェクトのobject_idなので、これを見れば例外オブジェクト自体は2つだけであり、4回raiseされているわけではないことが確認できます。

レンダリング処理中のすべてのraiseがログに記録されています

どのメソッドがどのraiseを引き起こしたのか?

raiseイベントの一覧が取れるだけでも十分便利ですが、「どのメソッドが各raiseを引き起こしたのか」まで分かればさらに有用です。ここでも再びTracePointが活躍してくれます。

TracePointでは、メソッドがreturnするたびに呼ばれるハンドラも登録できます。使い方は「raise」イベントのときと同じくらいシンプルです。次の例では、すべてのメソッドreturnをログに出力しています。

TracePoint.trace(:return) do |tp|
  logger.debug [tp.method_id, tp.lineno, tp.path.sub(Rails.root.to_s, "")].join(" : ").green 
end

ただし、ここには一つ問題があります。このコードをそのままRailsアプリに組み込むと、アプリがリクエストに応答しなくなってしまいます。最も単純なRailsリクエストでも膨大な数のメソッド呼び出しが発生するため、サーバーがタイムアウトする前にログへの書き込みが追いつかなくなるのです。

そこで、本当に知りたいのは「例外を引き起こしたメソッド呼び出し」だけなので、各例外の直後に発生する最初の数件の「return」イベントのみを出力するようコードを修正します。

class PagesController < ApplicationController
  def index
    counter = 0
    return_trace = TracePoint.trace(:return) do |tp|
      logger.debug "\t" + [tp.method_id, tp.lineno, tp.path.sub(Rails.root.to_s, "")].join(" : ").green 
      if (counter += 1) > 3
        return_trace.disable
        counter = 0
      end
    end
    return_trace.disable # デフォルトではTracePointを無効化しておく

    TracePoint.new(:raise) do |tp|
      logger.debug "#{tp.raised_exception.object_id}: #{tp.raised_exception.class} #{tp.raised_exception.message} ".yellow + tp.raised_exception.backtrace[0].sub(Rails.root.to_s, "").blue
      # 「raise」イベントが「return」のTracePointを有効化する
      return_trace.enable
    end.enable do
      render
    end

  end
end

ブラウザを更新すると、ログに次のような行が追加されます。

各「raise」イベントの上に、それを引き起こしたメソッドが表示されます

「return」のTracePointは例外がraiseされたときにしか有効化しないため、最初の「return」イベントは必ず例外をraiseしたメソッドのものになります。

この情報を使えば、冒頭の謎が解けます。元々のRuntimeErrorは、template.rbの310行目にあるhandle_render_errorメソッドによってActionView::Template::Errorへと変換されていたのです。だからこそ、コントローラ側でrescueできなかったわけです。

このテクニックの優れたところは、Railsに一切依存していない点です。内部でどの例外が発生し、どのように捕捉されているのかを詳しく調べたい場面であれば、どんなRubyアプリケーションでもいつでも利用できます。