こんにちは！最近、高速化にハマっているRailsエンジニアのシュール(@shule517)です。速くなった時の感動が半端ないですよね！

はじめに

不具合調査ってめちゃめちゃ大変じゃないですか？問題の原因が分かっていなくて、手元で不具合が再現できない時は、調査がかなり難しいです。そのため、不具合が発生したタイミングにできるだけ多くのデバッグ情報を残したくなりますよね！ということで、今回のテーマは「不具合調査の時間を短縮するための仕組み」についてです！

Bugsnagで例外がどこで発生したのかすぐ分かる！

「スタメンの開発環境について」で紹介をしましたが、Railsのエラー監視にBugsnagというサービスを使っています。Slackとの連携ができ、リアルタイムに通知が飛んでくるので、すぐに問題に気づくことができます！実際の画面はこちらです。

Bugsnag

Bugsnagで分かる内容

どこで、どんな例外が発生したのか
例外を踏んだユーザーは誰なのか
どんな環境なのか(OS / ブラウザの種類)

などなど、Bugsnagを導入するとたくさんの情報を集めてくれます！とても便利！！

でも、もう少しデバッグ情報がほしい！

不具合を調査するとなると、Bugsnagでこんな情報が見れると嬉しいですよね！例えば・・・

メソッドに渡ってきた引数はどんな値？
モデルのidは？モデルに保存されている値は？

Bugsnag

今回はこの２つの情報を通知する仕組みを作っていきます。不具合の再現方法を頑張って探すよりも、Bugsnagを見たら原因がすぐに分かるようにしたいですよね！

調査① Bugsnagの公式ドキュメントを読む

Bugsnagの公式ドキュメント(bugsnag DOCS - Rails integration guide)を確認すると、新しいタブを追加して、こちらで設定した情報を載せられるようです！ここに追加のデバッグ情報を載せられたら、良さそうです。

class ApplicationController < ActionController::Base
  before_bugsnag_notify :add_diagnostics_to_bugsnag

  # Your controller code here

  private
  def add_diagnostics_to_bugsnag(report)
    report.add_tab(:diagnostics, {
      product: current_product.name
    })
  end
end

次にデバッグ情報をどのように取得するか検討していきましょう。

メソッドに渡ってきた引数はどんな値？
モデルのidはいくつ？モデルに保存されている値は？

「うーん。。どうしたら良いんだろう？周りのサービスなどではどうしてるんだろう？」と思い、2つのgem(Better Errors / New Relic)のコードを読んでみました。

調査② BetterErrors の gem を参考にする

みんなお世話になっているであろう Railsのデバッグといえばこれですよね。BetterErrorsのコンソールに変数名を入力すれば、値を出力できるので、参考にできそう！

Better Errors

※ BetterErrors より画像を引用

① BetterErrorsのコンソールは、binding.eval(str)を実行してるだけ

module BetterErrors
  module REPL
    class Basic
      def initialize(binding, _exception)
        @binding = binding
      end

      def send_input(str)
        [execute(str), ">>", ""]
      end

    private
      def execute(str)
        "=> #{@binding.eval(str).inspect}\n"
      rescue Exception => e
        "!! #{e.inspect rescue e.class.to_s rescue "Exception"}\n"
      end
    end
  end
end

② そのBindingは、Exceptionを拡張し例外クラスに保持している

module BetterErrors
  module ExceptionExtension
    prepend_features Exception

    def set_backtrace(*)
      if caller_locations.none? { |loc| loc.path == __FILE__ }
        @__better_errors_bindings_stack = ::Kernel.binding.callers.drop(1)
      end

      super
    end

    def __better_errors_bindings_stack
      @__better_errors_bindings_stack || []
    end
  end
end

なるほどなるほど。例外元のBindingを取得することができれば、引数やModelの情報が取れそうですね！

調査③ New Relic の gem を参考にする

次に目をつけたのは、パフォーマンスの監視でいつもお世話になっているNew Relicです。DBの検索時間などの処理時間を細かくデータを取っているので、参考になりそう。gemのコードを読んでみると、ActiveRecordでよく使われているメソッド達(saveなど)に測定用の処理を埋め込んでいました。また、イベントをフックして、処理を埋め込んでいるみたいです。思った以上に泥臭いぞ。。。！

New Relic

※ New Relic より画像を引用

# encoding: utf-8
# This file is distributed under New Relic's license terms.
# See https://github.com/newrelic/rpm/blob/master/LICENSE for complete details.

require 'new_relic/agent/prepend_supportability'

module NewRelic
  module Agent
    module Instrumentation
      module ActiveRecordPrepend
        ACTIVE_RECORD = 'ActiveRecord'.freeze

        module BaseExtensions
          def save(*args, &amp;blk)
            ::NewRelic::Agent.with_database_metric_name(self.class.name, nil, ACTIVE_RECORD) do
              super
            end
          end

          def save!(*args, &amp;blk)
            ::NewRelic::Agent.with_database_metric_name(self.class.name, nil, ACTIVE_RECORD) do
              super
            end
          end
        end

        # saveと同じように下記のメソッドの実装がされていた（略
        # - touch
        # - update_all
        # - delete_all
        # - destroy_all
        # - calculate
        # - pluck
      end
    end
  end
end

なるほどなるほど。例外のイベントが取得できれば、なんとかなりそうですね！

調査④ TracePointで例外をフックする

Rubyのイベントフックを探してみると、TracePointクラスを使うと例外発生時のイベントがフックできるみたいです！

るりま - TracePointクラス

TracePoint.new(:raise) do |tp|
  # ブロック内は例外が発生した時に動く
  tp.raised_exception # Exceptionが取得できる
end

でも、TracePointって遅いのでは？

単純にTracePointを実行すると、約8倍遅くなる！！ (Traceなし：45.1ms → Traceあり：370.2ms)

trace = TracePoint.new {}

10.times.map { Benchmark.realtime { 1000000.times { 1 + 2 } } }.sum/10
# Traceなし => 0.04516370000201277

10.times.map { Benchmark.realtime { trace.enable { 1000000.times { 1 + 2 } } } }.sum/10
# Traceあり => 0.3702467000024626

例外だけをフックすれば、影響がない！

イベントフックの対象を例外だけに限定すれば、通常の処理には影響がありません！！ (Traceなし：42.9ms → Traceあり：42.5ms)

trace_raise = TracePoint.new(:raise) {}

10.times.map { Benchmark.realtime { 1000000.times { 1 + 2 } } }.sum/10
# Traceなし => 0.04297380000061821

10.times.map { Benchmark.realtime { trace_raise.enable { 1000000.times { 1 + 2 } } } }.sum/10
# Traceあり => 0.04251920000097016

これなら速度も問題なさそうですね！これで材料が揃いました！！

調査結果のまとめ

Bugsnagに新しいタブを追加して、情報を追加できる
例外発生元のBindingが取得できれば、引数やModelのデータを取得できる
TracePointで例外のイベントをフックして、例外発生元のBindingが取得できる

Bugsnagにデバッグ情報を追加できました！完成！！

調査結果を元に、Bugsnagの通知内容にデバッグ情報を増やしてみました。

Bugsnag

対応した内容

BugsnagのページにModelAttributesタブを追加！
メソッドに渡した引数の値が確認できるようになった！
Modelで例外が発生した場合は、idや各カラムの値が見えるようになった！

やったー！これで、どのModelで例外が起きたかは分かるけど、どのレコードか分からないっていうことが無くなります。引数に渡ってきたパラメータも分かるので、不具合の調査も捗りそうです！

最終的なコードはこちら！

説明のためにコードを簡略化し、解説コメントを追加してあります。実際には、機密情報に関わる部分はBugsnagで通知しないなどの対応を行っています。

例外時に、例外発生箇所のbindingを保持する

# 例外発生イベントをフックする
TracePoint.trace(:raise) do |trace_point|
  exception = trace_point.raised_exception

  # 例外の発生元の情報を取得するためBindingを保持する
  if trace_point.binding.respond_to?(:callers)
    bindings = trace_point.binding.callers.drop(1)
  else
    bindings = [trace_point.binding]
  end

  # exception.error_bindingsに、例外発生元のbindingを保持させる
  exception.define_singleton_method(:error_bindings) do
    bindings
  end
end

Controllerで例外が発生した時に、Bugsnagを通知する

class ApplicationController < ActionController::Base
  rescue_from Exception, with: :notify_bugsnag

  # Controller内で例外が発生した場合に、Bugsnagを通知する
  def notify_bugsnag(exception)
    BugsnagReporter.notify(exception)
    raise exception
  end
end

例外の発生箇所の引数や、ActiveRecordのモデル情報をBugsnagへ通知する

module BugsnagReporter
  class << self
    def notify(exception)
      Bugsnag.notify(exception) do |report|
        # Bugsnagに新しいタブを追加する
        report.add_tab(:model_attributes, models: model_attributes(exception))
      end
      skip_bugsnag(exception) # 二重で通知されないように通知をスキップする
    end

    def skip_bugsnag(exception)
      def exception.skip_bugsnag
        true
      end
    end

    def model_attributes(exception)
      # 例外に保持しておいたbindingを使う
      exception.error_bindings.map do |binding|
        instance = binding.eval('self')
        debug = {}
        # ActiveRecord：：Modelの中で例外が発生した場合は、カラムのデータを出力する
        debug.store("#{instance.class.name.downcase}_attributes", instance.attributes) if instance.respond_to?(:attributes)

        # 例外発生場所のローカル変数を出力
        debug.store(:local_variables, local_valiables(binding))

        # 例外発生場所のインスタンス変数を出力
        debug.store(:instance_variables, instance_variables(instance))

        [trace_path(binding), debug]
      end.compact.to_h
    end

    # 例外発生場所のローカル変数を取得
    def local_valiables(binding)
      binding.local_variables.map { |name| [name, format(binding.local_variable_get(name))] }.to_h
    end

    # 例外発生場所のインスタンス変数を取得
    def instance_variables(instance)
      instance.instance_variables.map { |name| [name, format(instance.instance_variable_get(name))] }.to_h
    end

    # データを読みやすいように加工
    def format(value)
      return value.attributes if value.respond_to?(:attributes)
      return value.to_sql if value.respond_to?(:to_sql)
      value
    end

    # 例外発生場所のファイルパスを生成する
    def trace_path(binding)
      instance = binding.eval('self')
      method_name = binding.eval('__method__')
      file = binding.eval('__FILE__')
      line = binding.eval('__LINE__')

      "#{instance.class.name}##{method_name} - #{file}:#{line}"
    end
  end
end

おわりに

Bugsnagを拡張して、不具合の調査を楽にする仕組みについて解説しました。この対応は、僕が不具合の原因を突き止めるまでに時間がかかってしまった失敗をもう一度起こさないようにするための改善の１つです。このように、スタメンのエンジニアチームの行動指針にもある「失敗に向き合う」が実践でき、自分自身、そしてサービスを改善＆成長していけるエンジニアを募集しています！

ぜひ、まずはエンジニア採用サイトを見てみてください！

ブログを最後まで読んでいただいて、ありがとうございました！！

stmn tech blog

Bugsnagと黒魔術で、Railsの不具合調査を楽にする仕組み！

はじめに

Bugsnagで例外がどこで発生したのかすぐ分かる！

Bugsnagで分かる内容

でも、もう少しデバッグ情報がほしい！

調査① Bugsnagの公式ドキュメントを読む

調査② BetterErrors の gem を参考にする

Better Errors

調査③ New Relic の gem を参考にする

New Relic

調査④ TracePointで例外をフックする

でも、TracePointって遅いのでは？

例外だけをフックすれば、影響がない！

調査結果のまとめ

Bugsnagにデバッグ情報を追加できました！完成！！

対応した内容

最終的なコードはこちら！

おわりに

はじめに

Bugsnagで例外がどこで発生したのかすぐ分かる！

Bugsnagで分かる内容

でも、もう少しデバッグ情報がほしい！

調査① Bugsnagの公式ドキュメントを読む

調査② BetterErrors の gem を参考にする

Better Errors

調査③ New Relic の gem を参考にする

New Relic

調査④ TracePointで例外をフックする

でも、TracePointって遅いのでは？

例外だけをフックすれば、影響がない！

調査結果のまとめ

Bugsnagにデバッグ情報を追加できました！ 完成！！

対応した内容

最終的なコードはこちら！

おわりに

Bugsnagにデバッグ情報を追加できました！完成！！