valid,invalid

関心を持てる事柄について

sentry-ravenでエラー通知するとrack envの中身が書き換わることがある

Ruby Rack Sentry ohbarye Advent Calendar 2020

エラー検知・監視ツールであるところのSentryが提供するRubyのSDKにsentry-ravenというgemがあります。

このgemを利用するとごくわずかなコードの記述をするだけでSentryに対してイベントを送信することができます。イベントにはユーザーが定義したカスタムタグや実行環境を含む多様な情報を含めることができ大変便利です。

begin
  some_dangerous_code!
rescue => ex
  Raven.capture_exception(ex)
end

# とか

if record.unknown?
  Raven.capture_message("Found suspisious data")
end

上述のようなコードを見た/書いた方も多いと思います。しかしながら特定条件下では上記のような Raven.capture_*メソッドの呼び出しの内部でRack envの一部を書き換えてしまう ことがあります。

なお、本件が意図した挙動なのか不明だったので本体にレポートしまして、トリアージ待ちです。本件の行く末が気になる方はissueをウォッチしていただければと思います。

github.com

また、sentry-ravenはすでにアクティブな開発が停止しており、sentry-rubyやsentry-railsに移行するようアナウンスがされています。僕が遭遇したプロジェクトでもこの問題による不具合を契機としてmigrationを実施しています。

Migration Guide for Ruby | Sentry Documentation

環境

  • rack 2.1.1
  • sentry-raven 3.1.1

事象の説明

以下の条件をすべて満たすときRack envのenv["rack.request.form_hash"]のHashのうち、2で該当したkeyのvalueがマスク用の文字列 ("********") に破壊的に書き換えられます。

  1. Rack::Request#form_data?がtrueとなる
    • Content-Typeが"application/x-www-form-urlencoded"や"multipart/form-data"であるとき
    • 画像アップロードでハマった
  2. リクエストのform dataのkeyが以下のいずれかに一致・マッチする 
Raven.configure do |config|
  config.sanitize_fields = %w[quite_sensitive_field]
end

後継のsentry-rubyでは起きない？

はい。

sentry-ravenが持つdata sanitization等を行う機構をprocessorと呼ぶのですが、この機構は後継のsentry-rubyや周辺のgemには存在しません。ユーザーが自前でhookを書いたり、SentryのGUIからfilter ruleを登録するようになっています。

何が問題か

Raven.capture_*に副作用がないと思っていると痛い目を見る…。

具体的な例を挙げます。

RailsがActionParameterのインスタンスを作るより手前のRack middlewareでRaven.capture_*を呼び出した場合、paramsの中身の一部が"********"になり、クライアントから送信されたform dataを参照できません。

もしくはRailsのcontrollerやmodelでRaven.capture_*を呼び出し、そのあとでenv["rack.request.form_hash"]を見るようなことがあれば同様にマスクされた文字列になっています。

ActionParameterのインスタンスが保持するform dataはコピーされたものなのでRailsアプリケーション内でparamsを見るふつうの（？）コードを書いていれば途中でRavenを使っても問題ないでしょう。

発見の経緯

そんなことするか？って思いますかね。まぁたしかにenvを直接触ることはほぼ無いと思いますが、rack middlewareのどこかでうっかりSentryに通知することはあるんじゃないでしょうか。というか、あった。

僕がハマったパターンは「committeeのCommittee::Middleware::RequestValidation middlewareでOpenAPI定義に違反するリクエストが来たらSentryに記録する（けど後続の処理はそのまま行う）」という使い方でした。

最初はユーザーが不正なリクエストをして400になっただけと思ったけど、開発環境でも事象が再現すること、および僕が変更したOpenAPIの定義をrevertすると再現しないことを同僚が発見してくれたのでバグだと気づくことができました。

sentry-ravenの実装の詳細

Rack::Request#form_data?がtrueのときRaven::RackはRack::Request#POSTを呼び出し、書き換える対象のHashへの参照を得ています。

 # https://github.com/getsentry/sentry-ruby/blob/82e1ffe711af287ddc23e8517bdb8275beff94d5/sentry-raven/lib/raven/integrations/rack.rb#L87-L89
 def read_data_from(request) 
   if request.form_data? 
     request.POST

後のRaven::Event#to_hashというメソッドで実行環境の情報をHash化します。このときも同一のポインタをそのまま渡しています。

# https://github.com/getsentry/sentry-ruby/blob/82e1ffe711af287ddc23e8517bdb8275beff94d5/sentry-raven/lib/raven/client.rb#L74-L75
def encode(event) 
   hash = @processors.reduce(event.to_hash) { |a, e| e.process(a) }

そしてRaven::Processor::SanitizeDataというデータマスクを行うclassにそのHashが渡るのですが、その中でHash#merge!を実行して破壊的に更新をしています。

# https://github.com/getsentry/sentry-ruby/blob/82e1ffe711af287ddc23e8517bdb8275beff94d5/sentry-raven/lib/raven/processor/sanitizedata.rb#L44-L50
 def sanitize_hash_value(key, value) 
   if key =~ sensitive_fields 
     STRING_MASK 
   elsif value.frozen? 
     value.merge(value) { |k, v| process v, k } 
   else 
     value.merge!(value) { |k, v| process v, k }

デバグ

さらっと書きましたが最初は「OpenAPI定義を変更したらリクエストパラメータがマスクされるようになった」ように見えたのでわけがわかりませんでした。

Raven configのsanitize_fieldを変更すると再現しない、Sentryへの通知をやめると再現しない、といったあたりまで同僚が絞り込んでくれたので、僕の方ではsentry-ravenのコードを読みながらステップ実行していってようやく原因にあたりがつきました。

最小の再現プロジェクトを作る

100%再現するバグなら勝利は約束されるので、最小の構成で再現するプロジェクトを作ってみました。

github.com

Raven::Rackをかませたrack appを作り、その中でRaven.capture_*を呼ぶ。その前後でrack envの中身が変わっていることを確認する。 味の秘密は、それだけ。

require 'rack'
require 'sentry-raven'

Raven.configure do |config|
  config.dsn = ENV['SENTRY_DSN']
  config.sanitize_fields = %w[name]
end

class SentryRavenSanitizeDemo
  def call(env)
    r = Rack::Request.new(env)

    puts "=========Before========="
    puts r.POST
    puts env[Rack::RACK_REQUEST_FORM_HASH]
    before = env[Rack::RACK_REQUEST_FORM_HASH].dup

    begin
      raise "foo"
    rescue => ex
      Raven.capture_exception(ex)
    end

    puts "=========After========="
    puts r.POST
    puts env[Rack::RACK_REQUEST_FORM_HASH]
    after = env[Rack::RACK_REQUEST_FORM_HASH].dup

    [200, {"Content-Type" => "text/plain"}, ["before: #{before}, after: #{after}"]]
  end
end

use Raven::Rack
run SentryRavenSanitizeDemo.new

rackupで起動し、curlでform dataをPOSTしてみると…

$ curl -X POST http://localhost:9292 -F 'name=foo' -F 'age=32'

before: {"name"=>"foo", "age"=>"32"}, after: {"name"=>"********", "age"=>"32"}%

BINGOです。sanitize_fieldをいじったりRaven.capture_exception(ex)を呼ばなければ再現しなくなることもすぐに確認できました。

結論

  • 特定条件下では上記のような Raven.capture_*メソッドの呼び出しの内部でRack envの一部を書き換えてしまう ことがある
  • sentry-ravenはすでにアクティブな開発が停止しているのでsentry-rubyやsentry-railsに移行しよう

ohbarye Advent Calendar 2020の1日目は@ohbaryeが担当しました。