こんにちは、ヘイ株式会社 CTO 室の id:hogelog です。
先日 STORES https://stores.jp/ec を支える Rails アプリケーションが静かに Rails 6.0 から Rails 6.1 にアップグレードされたのですが、そんな中で出会った現象が非常に不可解でエキサイティングなものだったので紹介させていただきます。
起きた現象
Rails 6.1 アップグレードで発生した不具合は要約すると「入れ子構造のハッシュを引数として作成した ActionController::Parameters 子要素のハッシュは ActionController::Parameters になっているはずなのになぜか低確率で ActiveSupport::HashWithIndifferentAccess になってしまう」というものでした。
不具合に関連するコードのみ示すと以下のようなものになります。
def update # params => { foos: [ { status: "done", name: "おいしいお米" } ] } foos_params = params.fetch(:foos) ... params.fetch(:foos).each do |foo_params| # foo_params は ActionController::Parameters となるはずだが低確率で ActiveSupport::HashWithIndifferentAccess になってしまう foo = foo_params.permit(:status, :name) ... end ... end
不具合の再現コード
以下、上述コード例から更に構成要素を減らした再現コードです。
require "bundler/inline" gemfile do source "https://rubygems.org" gem "actionpack", "6.1.6" end require "action_controller" 1000.times do |i| source_hash = { foo: [ { bar: Object.new } ] } params = ActionController::Parameters.new(source_hash) puts "#{i}: #{params} #{params.fetch(:foo)[0].class} #{params.fetch(:foo)[0].class}" raise params[:foo][0].class unless params.fetch(:foo)[0].is_a?(ActionController::Parameters) end
このコードを実行してみると
$ ruby rails.rb 0: {"foo"=>[{"bar"=>#<Object:0x000000014dc2c0d8>}]} ActionController::Parameters ActionController::Parameters 1: {"foo"=>[{"bar"=>#<Object:0x000000015b86aae0>}]} ActionController::Parameters ActionController::Parameters 2: {"foo"=>[{"bar"=>#<Object:0x000000015b8694b0>}]} ActionController::Parameters ActionController::Parameters 3: {"foo"=>[{"bar"=>#<Object:0x000000014dc3fcf0>}]} ActionController::Parameters ActionController::Parameters 4: {"foo"=>[{"bar"=>#<Object:0x000000014dc3f200>}]} ActionController::Parameters ActionController::Parameters 5: {"foo"=>[{"bar"=>#<Object:0x000000014dc3e710>}]} ActionController::Parameters ActionController::Parameters 6: {"foo"=>[{"bar"=>#<Object:0x000000014dc3dc20>}]} ActionController::Parameters ActionController::Parameters 7: {"foo"=>[{"bar"=>#<Object:0x000000014dc3d130>}]} ActionController::Parameters ActionController::Parameters 8: {"foo"=>[{"bar"=>#<Object:0x000000014dc3c640>}]} ActionController::Parameters ActionController::Parameters 9: {"foo"=>[{"bar"=>#<Object:0x000000015b8632e0>}]} ActionController::Parameters ActionController::Parameters 10: {"foo"=>[{"bar"=>#<Object:0x000000015b8600b8>}]} ActionController::Parameters ActionController::Parameters 11: {"foo"=>[{"bar"=>#<Object:0x000000014dc33540>}]} ActionController::Parameters ActionController::Parameters 12: {"foo"=>[{"bar"=>#<Object:0x000000014dc32a50>}]} ActionController::Parameters ActionController::Parameters 13: {"foo"=>[{"bar"=>#<Object:0x000000014dc31f60>}]} ActionController::Parameters ActionController::Parameters 14: {"foo"=>[{"bar"=>#<Object:0x000000014dc31470>}]} ActionController::Parameters ActionController::Parameters 15: {"foo"=>[{"bar"=>#<Object:0x000000014dc30980>}]} ActionController::Parameters ActionController::Parameters 16: {"foo"=>[{"bar"=>#<Object:0x000000014dbd3c80>}]} ActionController::Parameters ActionController::Parameters 17: {"foo"=>[{"bar"=>#<Object:0x000000014dbd0e18>}]} ActionController::Parameters ActionController::Parameters 18: {"foo"=>[{"bar"=>#<Object:0x000000014dc47888>}]} ActionController::Parameters ActiveSupport::HashWithIndifferentAccess Traceback (most recent call last): 3: from rails.rb:10:in `<main>' 2: from rails.rb:10:in `times' 1: from rails.rb:14:in `block in <main>' rails.rb:14:in `raise': exception class/object expected (TypeError)
低確率で params.fetch(:foo)[0].class
が "ActiveSupport::HashWithIndifferentAccess"
になることが確認できます。稀に1000回のループ中で一度も発生せず完走する場合もあります。環境によっては何度実行しても再現しないかもしれません。
不具合の原因
低確率でしか発生しない、二回目の参照時以降のみ入れ替わるなど発生状況がかなり限定されるため、不具合発見直後も「何が起きているのか」からよくわからず原因の特定もとても難しい不具合でした。先に示したコード例は非常にシンプルなものですが、実際に不具合が発生した部分のコードはより複雑に込み入ったものです。
Rails 6.1 アップグレードで発生したので、それが原因だろうということは想像がつきました。歴史の長い Rails アプリケーションの Rails アップグレードで不具合をおこすコードは、経験的には以下のようなものが多いです。
- バージョン間での非互換に対応できていなかったコード
- 元のバージョンでも特に保証されていたわけではなかったがたまたま意図通りに動いていた(行儀の悪い)コード
本不具合についてもその経験則に従って Rails 6.0 -> 6.1 非互換を調べ、また該当不具合箇所やモンキーパッチなどで行儀の悪い処理をしている箇所がないか調べました。しかしどうもそのような箇所は見つかりません。Rails 6.1.6 のソースコード、Ruby のソースコードまで追いかけて原因にたどりつきました。
ActionController::Parameters#fetch
はソースのハッシュからフェッチしてきた値が配列だった場合、その子要素に含まれるハッシュも ActionController::Parameter
に変換します。変換済みの配列は内部に保持し、次回以降の #fetch
呼び出しでソースハッシュからフェッチした値が変換済み配列に保持された値と同一ならば変換処理をスキップして返します。
本不具合はこの処理が正常に動作しない場合があるというものでした。不具合調査で首を傾げながらアプリケーション、Rails の挙動を追っていた hey 社内各位の気持ちを追体験してほしい気持ちでつい紹介までを引っ張ってしまいましたが、実のところ rails/rails では既に修正された不具合でした。
Rails 6.1 から導入された ActionController::Parameters#eql?
は同一の値を持つハッシュは true
を返していました。一方で #hash
が返す値は同一の値を持つハッシュであっても異なります。これは Ruby が #hash
に求める仕様を満たしていません。
そのため ActionController::Parameters
のインスタンス(及び子要素として ActionController::Parameters
を持つ配列インスタンス)をキーとして扱った時の Hash の挙動が不定となり、冒頭に示した「入れ子構造のハッシュを引数として作成した ActionController::Parameters 子要素のハッシュは ActionController::Parameters になっているはずなのになぜか低確率で ActiveSupport::HashWithIndifferentAccess になってしまう」という現象が発生したのでした。
STORES での対応
さて先の rails gem の修正ですが、まだ main ブランチにマージされただけでリリースされていません。そこで STORES の Rails アプリケーションではモンキーパッチで先の修正を取り込むこととしました。
安全なモンキーパッチの当て方については Ruby on Rails アプリケーションにおけるモンキーパッチの当て方 - クックパッド開発者ブログ がとても参考になります。
unless Rails::VERSION::STRING == "6.1.6" raise "Consider removing this patch" end module FixActionControllerParameterHash def eql?(other) self.class == other.class && permitted? == other.permitted? && parameters.eql?(other.parameters) end def hash [self.class, @parameters, @permitted].hash end end ActionController::Parameters.prepend(FixActionControllerParameterHash)
この修正については Rails 6.1 向けにも取り込まれる可能性が高いと判断し、Rails アップグレードの度にこのモンキーパッチをなくせないか精査していきます。
STORES はシステムとしてもそれなりの時間を経ていますがまだまだ元気に開発され続けているシステムです。この不具合が示すように、世の中の大多数の Rails アプリケーションが踏まない Rails のバグを踏むことがあるぐらいには大きなシステムです。そんなちょっと大変な楽しいシステム開発に興味がある方は是非一度以下のページから「ヘイってのはどんな会社なのかな?」と眺めてみませんか?
スペシャルサンクス
なお不具合調査において自分は ActionController::Parameter 初期化時に与えたハッシュの子要素の配列の #hash
値とその配列を変換した後の #hash
値が特定の類似性があるときに Hash のキーとして同一のものと扱われてしまう、というところまで絞りこめたのですが、その後「これは Ruby の不具合かもしれない!」とウキウキしながら*1 ruby-jp Slack https://ruby-jp.github.io/ に相談しにいったのでした。
しかし実際には前述の通り Rails の不具合。
@pocke さん @ko1 さんに「#eql?
が true なのに #hash
が異なるのがおかしい」「#eql?
が true ならば Hash のキーとしては同じものとして扱われるのが正しい」という Ruby の仕様についてご教授いただいたのでした。
https://github.com/rails/rails/pull/45221 で治ってそうと教えてくれたのも @pocke さんでした。
不具合調査で色々と挙動を追いかけたけども、まずは GitHub の Issue や PR をしっかり調べることの重要さをまざまざと感じたのでした。
しかしながらカジュアルに言語処理系の開発者と会話できる ruby-jp Slack の価値をまた強く感じた日でした。その場がなければこの不具合の解決までももうちょっと時間がかかってしまったかもしれません。対話いただいた @pocke さん @ko1 さんには心より感謝いたします。