TracePoint活用事例: Sentryのローカル変数キャプチャ機能

"Sentry"、使っていますか？

去る 2021-11-11 にリリースされた sentry-ruby 4.8.0 gem に "exception frame's local variable capturing" という機能が導入されました。良い感じの和訳が思いついてないのですが本記事ではローカル変数キャプチャ機能と呼称します。

これは例外発生箇所のローカル変数を Sentry Web UI で確認できる便利デバグ機能であるだけでなく TracePoint の cool な活用事例でもあります。せっかくなので機能の説明だけでなく、どのようにこの機能が実現されているのか、コードリーディングしつつ解説を試みます。

"exception frame's local variable capturing" とは？

前置き / 用語整理

機能を説明する前にざっくりと用語を整理します。

exception: 例外
local variable: ローカル変数
capturing: 捕まえる、捕捉する、記録する

frame だけ若干聞き慣れないかと思うので詳説します。

まず、例外のスタックトレース (Exception#backtrace) は例外発生箇所にいたるまでの呼び出し元 (caller の String 表現) の配列です。Ruby プログラムを書いている方なら以下のように整形された表現を見ることも多いでしょう。

irb(main):001:0> def foo; raise 'bye'; end
=> :foo
irb(main):002:0> foo
(irb):1:in `foo': bye (RuntimeError)
  from (irb):2:in `<main>'
  from /Users/m-ohba/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/irb-1.3.5/exe/irb:11:in `<top (required)>'
    from /Users/m-ohba/.rbenv/versions/3.0.1/bin/irb:23:in `load'
  from /Users/m-ohba/.rbenv/versions/3.0.1/bin/irb:23:in `<main>'

例外から直接 backtrace を参照するとよりプリミティブな姿が見えます。

irb(main):003:0> begin; foo; rescue => e; e.backtrace; end
=>
["(irb):1:in `foo'",
 "(irb):3:in `<main>'",
 # 以下省略
]

この配列の要素 1 つ 1 つのことを frame と呼んでいます。

sentry-ruby gem には Sentry::StackTraceInterface::Frame class が存在し、例外の backtrace を parse して frame を表現しています。このframe に詰められた情報が Sentry Web UI では以下のように見えるわけです。

frame が積層されている様子

ローカル変数キャプチャ機能とは？

この機能の概要を https://github.com/getsentry/sentry-ruby/pull/1580 よりかいつまんで述べます。

同機能は例外が発生した箇所のローカル変数をキャプチャして Sentry に送信してくれる便利機能です。たとえば以下のようなスクリプトで例外が発生したとします。

def foo
  a = 1
  b = 0
  request = self.request
  a / b #=> This would cause ZeroDivisionError
end

例外発生箇所におけるローカル変数は a, b, request であり、これらが Sentry の Web UI で確認できるようになります。

これはシンプルな例ですが、実際のアプリケーションではデバグが捗る有用な手がかりになりえます。

📝 ちなみに Sentry に送信される各ローカル変数の値は Object#inspect の戻り値です。1024 bytes 以上の長さの場合は truncate されます。

使う、いますぐ

capture_exception_frame_locals に true をセットすることで有効化できます。

Sentry.init do |config|
  config.capture_exception_frame_locals = true # default is false
end

後述しますがこの機能の実現には TracePoint を使っており、パフォーマンスに影響を与える可能性があるため 4.8.0 ではデフォルトでオフになっています。

`sentry-ruby` Deep Dive

さて、便利なことがわかったところでイチ利用者としては満足なのですが、この機能はどのように実現されているのでしょうか。Rubyist なのでわたし、気になります。

その謎を解明するため、私は https://github.com/getsentry/sentry-ruby の奥地へと向かいました。

TracePoint

そこで出会ったのは Ruby 2.0 から導入されている TracePoint でした。

TracePoint について本記事では詳説しませんが、https://techlife.cookpad.com/entry/2018/12/27/093914#TracePoint-%E5%9F%BA%E7%A4%8E より引用します。

TracePoint は、プログラム中のイベントで起動する Proc を登録するための仕組みです。イベントには、毎行ごとに実行する line イベントや、メソッドの呼び出しと、そのリターンごとに実行する call、return などがあります。

Ruby プログラムで発生する様々なイベントにフックした処理/ハンドラが書けるという強い機能です。

TracePoint でハンドラを登録できるイベントの 1 つに raise があり、例外発生時にフックして任意の処理を呼び出すことができます。

"trick-タネ-"が見えてきたと思います。

`TracePoint.new(:raise)` - 例外の発生にフック

実際の使い方を見てみます。

Sentry.exception_locals_tpは以下のように実装されています。

    def exception_locals_tp
      @exception_locals_tp ||= TracePoint.new(:raise) do |tp|
        exception = tp.raised_exception

        # don't collect locals again if the exception is re-raised
        next if exception.instance_variable_get(:@sentry_locals)
        next unless tp.binding

        locals = tp.binding.local_variables.each_with_object({}) do |local, result|
          result[local] = tp.binding.local_variable_get(local)
        end

        exception.instance_variable_set(:@sentry_locals, locals)
      end
    end

発生した例外の binding が持つローカル変数の一覧 local_variables を参照し、一つずつ Hash にセットしていきます。

それを例外インスタンス exception のインスタンス変数 @sentry_locals にセットしています。同じ例外が別の箇所で再度 raise されたときにはすでにローカル変数がセット済なのでスキップするようになっています。

`TracePoint#enable` - 有効化

Sentry.exception_locals_tp では TracePoint インスタンスを生成しているだけで、まだ有効化されていません。有効化しているのは Sentry.init 内です。

config.capture_exception_frame_locals が truthy なときだけ TracePoint#enable されることがわかります。

    def init(&block)
      config = Configuration.new
      yield(config) if block_given?
      config.detect_release
      apply_patches(config)
      client = Client.new(config)
      scope = Scope.new(max_breadcrumbs: config.max_breadcrumbs)
      hub = Hub.new(client, scope)
      Thread.current.thread_variable_set(THREAD_LOCAL, hub)
      @main_hub = hub
      @background_worker = Sentry::BackgroundWorker.new(config)

      if config.capture_exception_frame_locals
        exception_locals_tp.enable
      end
    end

余談ですが、最初の実装では TracePoint の有効化を Rack middleware でやっており、バックグラウンドジョブ等の Rack middleware を使わないアプリケーションではこのキャプチャ機能が使えませんでした。有効化箇所を Sentry.init に持ってくることで恩恵を受けられる対象が大幅に広がりました。

Sentry に送信

コードリーディングの最後に、TracePoint のフックによってインスタンス変数 @sentry_locals にセットされた値がどのように整形されているかを見てみます。

実装箇所は Sentry::SingleExceptionInterface.build_with_stacktrace になります。ここでは例外 exception を Sentry のイベントに変換する処理を行っています。

    def self.build_with_stacktrace(exception:, stacktrace_builder:)
      stacktrace = stacktrace_builder.build(backtrace: exception.backtrace)

      if locals = exception.instance_variable_get(:@sentry_locals)
        locals.each do |k, v|
          locals[k] =
            begin
              v = v.inspect unless v.is_a?(String)

              if v.length >= MAX_LOCAL_BYTES
                v = v.byteslice(0..MAX_LOCAL_BYTES - 1) + OMISSION_MARK
              end

              v
            rescue StandardError
              PROBLEMATIC_LOCAL_VALUE_REPLACEMENT
            end
        end

        stacktrace.frames.last.vars = locals
      end

      new(exception: exception, stacktrace: stacktrace)
    end

ループの中で @sentry_locals の値を 1 つずつ inspect し、MAX_LOCAL_BYTES (= 1024 bytes) を超える文字列であれば "<超長い文字列>..." のように truncate しています。もし処理を行えず StandardError が起きるような値があった場合には PROBLEMATIC_LOCAL_VALUE_REPLACEMENT (= "[ignored due to error]") に置き換えられます。

ループを抜けたところで最後のフレーム stacktrace.frames.last の vars にセットされた値が、Sentry Web UI で以下のように表示されることになります。

📝 スタックトレースのインタフェースについてはドキュメントで詳説されています。Sentry に送信する値をカスタマイズする日には大変参考になることでしょう。

ローカル変数キャプチャ機能の制約

仕組みを理解したので現時点で存在する以下の制約も理解できました。

キャプチャできるのは最後のフレームだけ

例外が発生した箇所、すなわち最後のフレームのローカル変数しか同機能はキャプチャしません。

Sentry に送信できる payload の最大長が 200KB なので全てのフレームでローカル変数を送るわけにはいかない、という事情のためと推察します。

ライブラリ内で例外が発生した場合は「ライブラリに自分のアプリケーションコードがどんな値を渡したのか？」＝アプリケーション内の最後のフレームでのローカル変数を知りたいのが人情ですが、現状ではそれはできません。ライブラリ内の例外発生箇所のローカル変数のみがキャプチャされます。

アプリケーション内での最後の caller までスタックトレースを遡ってローカル変数を取得することも将来的にはできるようになるかもしれません。

パフォーマンス影響

一般に TracePoint を有効化するとパフォーマンスが落ちます。その事実を示すベンチマークもそこかしこに見つかります。

デフォルトでオフになっている主な理由は experimental だからというだけでなく、パフォーマンス懸念が存在するためです。

しかしながら当機能ではフックするイベントが raise 1 つのみであり、"実世界-リアルワールド-"のアプリケーションではさほど影響がないという見解が https://github.com/getsentry/sentry-ruby/pull/1580 にベンチマーク付で載せてあります。

本当にパフォーマンス影響が無視できるレベルかどうかは、ぜひ君の目で確かめてほしい...といったところです。

センシティブデータの対処

当記事でリーディングしたコードを読む限り、ローカル変数に格納されたセンシティブなデータが Sentry に送信されうることに気付いた方もいるかもしれません。

Rails 6.0 以上なら Rails.application.config.filter_parameters を設定することで、それ以前なら Sentry の before_send フックを使うことでセンシティブデータのフィルタリングが可能です。公式ドキュメントを参考にご対応ください。

SmartBank での活用

最後に、弊社 SmartBank での Sentry 活用についてさらっと記述します。

SmartBank では Sentry を用いたエラー監視を行っています。ローカル変数キャプチャ機能については、上述の通り有用かつ面白いと感じたので一部の Rails アプリケーションで早速有効化してみました。

しかしながら実のところ記事公開時点ではまだ同機能の恩恵に預かれるような例外は発生していません。SmartBank では以下のように Sentry のエラー対処・運用をガッツリ行っているので、例外発生数自体もさほど多くないためです。

1. 日常に溶け込んだ Sentry と Slack の連携

例外発生時に Sentry からの通知を受け取る Slack channel があります。

日々エンジニアが目を光らせている…というと若干の誇張になりますが、平日に見慣れないエラーが通知されればおおよそ同日中には誰かしらが初動調査をします。

すぐに解決できないもの、影響が軽微なものはコメントを残していったん見送ります。エラー対応以外の業務に集中するためです。

もちろん、暫定対応と恒久対応が即座に行われる issue もあります。

2. 隔週で棚卸し

隔週でエンジニア全員が集まって Sentry issues の棚卸しを行っています。

即日対応が難しかったものや見送ったものをこの場で議論してトリアージし、必要なら解決に向けて担当者をアサインします。通知がそもそも不要という結論に至れば、同じエラーの通知は行われないようにします。

エラーゼロは目指していませんが、極力 Sentry issues を空っぽにするようにチーム全員で努めています。

突発的なエラー対応は確実かつそれなりに開発者のマインドシェアや時間を奪っていくもので、可能な限りエラー通知が少ないヘルシーな状態を保つことが日常の開発者体験の向上に直結すると考えているためです。

執筆にあたり参考にしたドキュメント等

注1: アイキャッチ画像に使用したロゴは https://sentry.io/branding/ より入手したものです。Sentry は branding page から入手した画像の使用を認めています。

Sentry 本体は多数の言語に対応していますが、言語によってインテグレーションのしやすさや収集できる情報量が多少異なります。TracePoint のような機能を用いてローカル変数キャプチャが実現できる Ruby は面白い言語ですね。他言語ではこのあたりがどうなっているか探ってみるのも面白そうです。

本記事は最近 Go 言語を書き始めた @ohbarye が執筆しました。

inSmartBank

B/43を運営する株式会社スマートバンクのメンバーによるブログです

TracePoint活用事例: Sentryのローカル変数キャプチャ機能

"exception frame's local variable capturing" とは？

前置き / 用語整理

ローカル変数キャプチャ機能とは？

使う、いますぐ

`sentry-ruby` Deep Dive

TracePoint

`TracePoint.new(:raise)` - 例外の発生にフック

`TracePoint#enable` - 有効化

Sentry に送信

ローカル変数キャプチャ機能の制約

キャプチャできるのは最後のフレームだけ

パフォーマンス影響

センシティブデータの対処

SmartBank での活用

執筆にあたり参考にしたドキュメント等

"exception frame's local variable capturing" とは？

前置き / 用語整理

ローカル変数キャプチャ機能とは？

使う、いますぐ

sentry-ruby Deep Dive

TracePoint

TracePoint.new(:raise) - 例外の発生にフック

TracePoint#enable - 有効化

Sentry に送信

ローカル変数キャプチャ機能の制約

キャプチャできるのは最後のフレームだけ

パフォーマンス影響

センシティブデータの対処

SmartBank での活用

執筆にあたり参考にしたドキュメント等

`sentry-ruby` Deep Dive

`TracePoint.new(:raise)` - 例外の発生にフック

`TracePoint#enable` - 有効化