Icon kobu medium
Kota Miyake

Rails4.2.8.rc1のMessageVerifierでハマる

ついにRuby2.4に対応したRails4.2.8.rc1がリリースされたので、社内のプロジェクトでさっそくアップデートを試してみました。

gem 'rails', '4.2.8.rc1'
$ bundle update rails

とりあえずテストを流してみたのですが、いくつかテストが失敗してしましました。。。

どうやらトークンがデータベースで用意しているカラムの長さを超えてしまったようです。

ActiveRecord::StatementInvalid:
Mysql2::Error: Data too long for column 'token' at row 1

ちなみにトークンを生成しているロジックは以下のような感じです。

Rails.application.message_verifier(:invitation).generate([1, Time.current])

失敗しているはずのテストが、なぜか単体で動かすと成功するという謎の挙動をしていました。

細かくテストを実行していったところ、どうやらタイムゾーンが変わる部分のテスト以降で落ちているようだったので、コンソールでタイムゾーンを切り替えて結果がどうなるか実行してみました。

pry(main)> Time.zone = 'UTC'
=> "UTC"
pry(main)> Rails.application.message_verifier(:invitation).generate([1, Time.current])
=> "BAhbB2kGVTogQWN0aXZlU3VwcG9ydDo6VGltZVdpdGhab25lWwhJdToJVGltZQ2qRR3ARpubjAY6CXpvbmVJIghVVEMGOgZFRkkiCFVUQwY7CFRACQ==--37c53d559cbb466f31e5cfcc5c11404280264b1f"
pry(main)> Time.zone = 'Tokyo'
=> "Tokyo"
pry(main)> (:invitation).generate([1, Time.current])
=> "BAhbB2kGVTogQWN0aXZlU3VwcG9ydDo6VGltZVdpdGhab25lWwhJdToJVGltZQ2qRR3A4swAjQc6CXpvbmVJIghVVEMGOgZFRjohQF90b190aW1lX3dpdGhfc3lzdGVtX29mZnNldEl1OwYNqkUdgOLMAI0HOgtvZmZzZXRpApB+OwdJIghKU1QGOwhGSSIKVG9reW8GOwhUdTsGDbNFHcDizACN--3f02bc96b451c582679e7fab998f49a36359822d"

なんとタイムゾーンにTokyoを指定したらトークンの長さが結構な長さになってしまいました。

今度はMessageVerifierがどのようにトークンを生成しているか見てみることにしました。

Rails::Application::message_verifier

secretを生成してActiveSupport::MessageVerifierのインスタンスを生成します。

ActiveSupport::MessageVerifier#generate

ここで渡された値を指定されたSerializer(デフォルトではMarshal)でdumpして、結果をBase64でエンコードしています。

とりあえず一番深い場所にあるMarshal#dumpしている部分をタイムゾーンを変えて実行してみました。

pry(main)> Time.zone = 'UTC'
=> "UTC"
pry(main)> Marshal.dump([1, Time.current])
"\x04\b[\ai\x06U: ActiveSupport::TimeWithZone[\bIu:\tTime\r\xABE\x1D\xC0\xBAm[\x03\x06:\tzoneI\"\bUTC\x06:\x06EFI\"\bUTC\x06;\bT@\t"
pry(main)> Time.zone = 'Tokyo'
=> "Tokyo"
pry(main)> Marshal.dump([1, Time.current])
=> "\x04\b[\ai\x06U: ActiveSupport::TimeWithZone[\bIu:\tTime\r\xABE\x1D\xC0\xD2\x85\x1D\x04\a:\tzoneI\"\bUTC\x06:\x06EF:!@_to_time_with_system_offsetIu;\x06\r\xABE\x1D\x80\xD2\x85\x1D\x04\a:\voffseti\x02\x90~;\aI\"\bJST\x06;\bFI\"\n" +
"Tokyo\x06;\bTu;\x06\r\xB4E\x1D\xC0\xD2\x85\x1D\x04"

以前は問題なかったということは、どうやらActiveSupport::TimeWithZoneの挙動が変わったようです。

コミットログを見てみると、どうやらそれらしきものを発見。

Cache to_time to improve performance when comparing

詳細はいまいちわかっていないのですが、どうやらgetlocalした結果をキャッシュするようにしたようです。

そこで追加された変数(@_to_time_with_system_offset)がdumpした時に残っているので、今回のようにトークンの長さが大きく変わってしまったようです。

ActiveSupport::MessageVerifierではなくタイムゾーン関連の変更が原因だったというお話。

コメント
新しいコメント