TracePointを使用してRubyでの複雑な例外動作を調査する

Railsのコントローラーとビューの境界は、例外がロジックに反しているように見える1つの場所です。自分で見るのは簡単です。ビューで例外を発生させ、コントローラーでそれをレスキューしてみてください。コントローラーからテンプレートエラーを救うことはできません！

# pages_controller.rb

def index
  render
rescue
  # this will never run
  logger.debug "someone raised the roof"
end

# index.haml

- raise "the roof"

WTF！？！これを救ったと思った！

何かトリッキーなことが起こっているのは明らかです。それが何であるかを理解できるかどうか見てみましょう。

TracePointですべての例外をログに記録する

TracePointsは、Ruby2.0以降に使用されている非常に強力なイントロスペクションツールです。これらを使用すると、さまざまなランタイムイベントのコールバックを定義できます。たとえば、クラスが定義されたとき、メソッドが呼び出されたとき、または例外が発生したときに通知を受け取ることができます。さらに多くのイベントについては、TracePointのドキュメントを確認してください。

例外が発生するたびに呼び出され、その概要をログに書き込むTracePointを追加することから始めましょう。

class PagesController < ApplicationController
  def index
    TracePoint.new(:raise) do |tp|
      # tp.raised_exeption contains the actual exception object that was raised!
      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 メソッド、私はcolorizegemを使用しています。 ANSIカラーコードを出力に追加します。

ページを更新すると、ログは次のスクリーンショットのようになります。お気づきかもしれない興味深い点の1つは、2つの別個の例外があり、それぞれが2回発生することです。各行の先頭にある長い数字は、例外のオブジェクトIDです。このようにして、4つではなく2つの例外オブジェクトがあることがわかります。

このログには、raiseのすべての使用が表示されます。 レンダリングプロセスで

どのメソッドがどのレイズを引き起こしましたか？

「レイズ」イベントのリストがあると非常に便利です。しかし、どのメソッドが各レイズを引き起こしているのかをある程度把握しておけば、さらに良いでしょう。もう一度、TracePointが助けになります。

TracePointを使用すると、メソッドが戻るたびに呼び出されるハンドラーを追加できます。 「レイズ」イベントと同じように簡単に使用できます。以下の例では、すべてのメソッドの戻り値をログに記録しています：

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

ただし、1つの問題があります。このコードをRailsアプリに追加すると、アプリがリクエストへの応答を停止することがわかります。最も単純なRailsリクエストには非常に多くのメソッド呼び出しがあるため、サーバーがすべてをログに書き込む前にタイムアウトになります。

本当に関心があるのは例外の原因となったメソッド呼び出しだけなので、各例外の後に発生する最初の2つの「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 # disable the tracepoint by default

    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
      # The "raise" enables the "return" tracepoint
      return_trace.enable
    end.enable do
      render
    end

  end
end

ブラウザを更新すると、次の行がログに追加されていることがわかります。

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

例外が発生した場合にのみ「return」TracePointを有効にするため、最初の「return」イベントは、例外を発生させたメソッドから発生します。

この情報を使用して、謎を解くことができます。元のRuntimeError ActionView::Template::Errorに変換されています handle_render_errorによる template.rbの310行目のメソッド。

この手法の良いところは、Railsとは何の関係もないことです。どの例外が発生し、内部で捕捉されているかをより詳細に理解する必要がある場合はいつでも使用できます。