TracePoint で例外をトレースする

TracePoint は、指定したイベントをトレースするための機能を備えた Ruby の標準ライブラリです。
指定できるイベントはリファレンスを見るとわかりますが、例えば以下のようにすると、メソッドの呼び出しをトレースできます。

sample.rb

TracePoint.trace(:call) do |tp|
  puts [tp.path, tp.lineno, tp.defined_class, tp.method_id, tp.event].join(', ')
end

class HogeClass
  def hoge
  end
end

HogeClass.new.hoge

call を引数に渡して、trace を呼ぶと、ruby で定義されたメソッドの呼び出しをトレースします。実行すると

$ ruby sample.rb
sample.rb, 6, HogeClass, hoge, call

「実行ファイルのパス、呼び出された行、メソッドの定義クラス、メソッド名、トレースイベント」が取れているのが分かります。

trace メソッドは、new と enable で置き換える事も出来ます。

sample.rb

trace = TracePoint.new(:call) {|tp|
  puts [tp.path, tp.lineno, tp.defined_class, tp.method_id, tp.event].join(', ')
}

trace.enable # NOTE 以降 trace が有効になる
...

例外をトレースする

そんな TracePoint で、今回の目的である例外をトレースします。

sample.rb

TracePoint.trace(:raise) do |tp|
  puts [tp.path, tp.lineno, tp.defined_class, tp.method_id, tp.raised_exception].join(', ')
end

class HogeClass
  def hoge
    not_defined
  end
end

HogeClass.new.hoge

$ ruby sample.rb
sample.rb, 7, HogeClass, hoge, undefined local variable or method `not_defined' for #<HogeClass:0x007ffbfa1a1a00>
sample.rb:7:in `hoge': undefined local variable or method `not_defined' for #<HogeClass:0x007ffbfa1a1a00> (NameError)
	from sample.rb:11:in `<main>'

最初の行は puts した内容。後半の行は ruby が自動的に出力するエラーログです。
既に似たような内容が出力されていますね。

debug_inspector

PrettyBacktrace の中身を見ると debug_inspector を使っているのが分かります。これも、Sasada さんが作っているんですね。デバッグ用に作られていて、デバッグ以外に使うなと書いてあります。

何をする Gem？

見ていると、スタックフレームの情報を取り出すためのライブラリのようです。試しに、先ほどの hoge を実行した際のスタックフレームを出力してみます。

sample.rb

require 'debug_inspector'

TracePoint.trace(:raise) do |tp|
  RubyVM::DebugInspector.open {|dc|
    locs = dc.backtrace_locations

    locs.each do |loc|
      puts [loc, loc.path, loc.lineno].join(', ')
    end
  }
end

class HogeClass
  def hoge
    not_defined
  end
end

HogeClass.new.hoge

dc.backtrace_locations で Thread::Backtrace::Location の配列が取得出来ます。Thread::Backtrace::Location は例外発生時に作成されるオブジェクトで、バックトレースの情報を取得することができます。メソッドなどは、リファレンスを参照して下さい。

実行してみると

$ ruby sample.rb
sample.rb:4:in `open', sample.rb, 4
sample.rb:4:in `block in <main>', sample.rb, 4
sample.rb:15:in `hoge', sample.rb, 15
sample.rb:19:in `<main>', sample.rb, 19
sample.rb:15:in `hoge': undefined local variable or method `not_defined' for #<HogeClass:0x007f9bd287c808> (NameError)
	from sample.rb:19:in `<main>'

おー！フレームの情報が出力されています。（最後の 2 行は Ruby が勝手に出力するバックトレースです）

試しに自分でバックトレースを出力させる

自動で出るバックトレースをまねて、自分でも出力させてみます。

sample.rb

require 'debug_inspector'

TracePoint.trace(:raise) do |tp|
  RubyVM::DebugInspector.open {|dc|
    locs = dc.backtrace_locations

    message = locs[2, locs.length].map.with_index {|loc, i|
      if i.zero?
        "#{loc}: #{tp.raised_exception} (#{tp.raised_exception.class})"
      else
        "\tfrom #{loc}"
      end
    }.join("\n")

    puts message
  }
end

class HogeClass
  def hoge
    not_defined
  end
end

HogeClass.new.hoge

$ ruby sample.rb
sample.rb:21:in `hoge': undefined local variable or method `not_defined' for #<HogeClass:0x007fd86a07b558> (NameError)
	from sample.rb:25:in `<main>'
sample.rb:21:in `hoge': undefined local variable or method `not_defined' for #<HogeClass:0x007fd86a07b558> (NameError)
	from sample.rb:25:in `<main>'

上が自分で出力している、下が自動で出力されるバックトレース。だいぶ無理矢理だけどできた！！

`set_backtrace`

このままだと、二つエラーメッセージが表示されてしまって邪魔なので、自分で作成したメッセージを、Ruby の出力するエラーメッセージとしてセットします。
そこで使うのが Exception#set_backtrace です。Exception#set_backtrace を使えば、無理矢理 tp.raised_exception.class などを追加しなくて良くなります。

sample.rb

require 'debug_inspector'

TracePoint.trace(:raise) do |tp|
  RubyVM::DebugInspector.open {|dc|
    locs = dc.backtrace_locations

    message = locs[2, locs.length].map.with_index {|loc, i|
      loc.to_s
    }

    tp.raised_exception.set_backtrace message
  }
end

class HogeClass
  def hoge
    not_defined
  end
end

HogeClass.new.hoge

$ ruby sample.rb
sample.rb:17:in `hoge': undefined local variable or method `not_defined' for #<HogeClass:0x007fda22958ab8> (NameError)
	from sample.rb:21:in `<main>'

かなりすっきりしましたね。

やっとオリジナルのバックトレースを実装

します！（長かった。。。）
変数と不要な（邪魔な）文字列を出力するエラーメッセージを作ってみたいと思います。

実行するメソッドは以下です。

sample.rb

class HogeClass
  def hoge(n)
    str = "hoge #{n}"

    if n > 0
      hoge(n - 1)
    else
      not_defined
    end
  end
end

HogeClass.new.hoge(3)

標準のエラーメッセージはこんな感じ。

sample.rb:23:in `hoge': undefined local variable or method `not_defined' for #<HogeClass:0x007f960285b520> (NameError)
	from sample.rb:21:in `hoge'
	from sample.rb:21:in `hoge'
	from sample.rb:21:in `hoge'
	from sample.rb:28:in `<main>'

では、実装します。
変数を取り出すところは、PrettyBacktrace を参考にして、、、

sample.rb

require 'debug_inspector'

TracePoint.trace(:raise) do |tp|
  RubyVM::DebugInspector.open {|dc|
    locs = dc.backtrace_locations

    message = locs[2, locs.length].map.with_index(2) {|loc, i|
        iseq = dc.frame_iseq(i)

        variables = if iseq
            binding_obj = dc.frame_binding(i)

            iseq.to_a[10].inject({}){|variables, name|
              begin
                variables[name] = binding_obj.local_variable_get(name)
              rescue NameError, TypeError
              end
              variables
            }
          else
            {}
          end

        unnecessary_str = unless variables.empty?
            variables.map {|k, v|
              "#{k} (ノ｀Д)ノ彡 #{v}"
            }.join(' | (ﾟ∀ﾟ)人(ﾟ∀ﾟ) | ')
          else
            '(ヾﾉ･∀･`)ﾅｲﾅｲ'
          end

        "#{loc} : #{unnecessary_str}"
      }

    tp.raised_exception.set_backtrace message
  }
end

class HogeClass
  def hoge(n)
    str = "hoge #{n}"
    if n > 0
      hoge(n - 1)
    else
      not_defined
    end
  end
end

HogeClass.new.hoge(3)

できた。
実行してみると

$ ruby sample.rb
sample.rb:45:in `hoge' : n (ノ｀Д)ノ彡 0 | (ﾟ∀ﾟ)人(ﾟ∀ﾟ) | str (ノ｀Д)ノ彡 hoge 0: undefined local variable or method `not_defined' for #<HogeClass:0x007f98a1133490> (NameError)
	from sample.rb:43:in `hoge' : n (ノ｀Д)ノ彡 1 | (ﾟ∀ﾟ)人(ﾟ∀ﾟ) | str (ノ｀Д)ノ彡 hoge 1
	from sample.rb:43:in `hoge' : n (ノ｀Д)ノ彡 2 | (ﾟ∀ﾟ)人(ﾟ∀ﾟ) | str (ノ｀Д)ノ彡 hoge 2
	from sample.rb:43:in `hoge' : n (ノ｀Д)ノ彡 3 | (ﾟ∀ﾟ)人(ﾟ∀ﾟ) | str (ノ｀Д)ノ彡 hoge 3
	from sample.rb:50:in `<main>' : (ヾﾉ･∀･`)ﾅｲﾅｲ

できた！！

うんうん、いいですね。
それでは、みなさんもバックトレースを自作して、素敵なデバッグライフを！