タイムスタンプの切り捨て：Ruby on Rails ActiveRecord Tale
公開: 2022-03-11テストは、アプリが不安定になるのを防ぐのに役立つはずです。 しかし、ときどき、テスト自体が不安定になる可能性があります。最も単純なテストでさえもです。 これが、PostgreSQLに支えられたRuby on Railsアプリでの問題のあるテストにどのように取り組んだか、そして私たちが発見したことです。
特定のビジネスロジック（メソッドperformによって呼び出される）がcalendarモデル（ Calendarのインスタンス、Ruby on Rails ActiveRecordモデルクラス）を変更しないことを確認したかったので、次のように記述しました。
let(:calendar) { create(:calendar) } specify do expect do perform # call the business action calendar.reload end .not_to change(calendar, :attributes) endこれは1つの開発環境（MacOS）で成功していましたが、CI（Linux）ではほとんどの場合失敗していました。
幸い、別の開発環境（Linux）で再現できましたが、次のメッセージが表示されて失敗しました。
expected `Calendar#attributes` not to have changed, but did change from {"calendar_auth_id"=>8, "created_at"=>2020-01-02 13:36:22.459149334 +0000, "enabled"=>false, "events_...t_sync_token"=>nil, "title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149334 +0000, "user_id"=>100} to { "calendar_auth_id"=>8, "created_at"=>2020-01-02 13:36:22.459149000 +0000, "enabled"=>false, "events_...t_sync_token"=>nil, "title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149000 +0000, "user_id"=>100}何か怪しいものが見えますか？
調査
よく調べてみると、 created_atとupdated_atのタイムスタンプがexpectブロック内でわずかに変更されていることがわかりました。
{"created_at"=>2020-01-02 13:36:22.459149334 +0000, "updated_at"=>2020-01-02 13:36:22.459149334 +0000} {"created_at"=>2020-01-02 13:36:22.459149000 +0000, "updated_at"=>2020-01-02 13:36:22.459149000 +0000} 13:36:22.459149334が13:36:22.459149000 ：22.459149000になるように、秒の小数部分が切り捨てられました。
Performがcalendarオブジェクトを更新しperformいないと確信していたため、タイムスタンプがデータベースによって切り捨てられているという仮説を立てました。 これをテストするために、既知の最も高度なデバッグ手法を使用しました。つまり、putsdebuggingです。
let(:calendar) { create(:calendar) } specify do expect do puts "before perform: #{calendar.created_at.to_f}" perform puts "after perform: #{calendar.created_at.to_f}" calendar.reload puts "after reload: #{calendar.created_at.to_f}" end .not_to change(calendar, :attributes) endただし、出力には切り捨ては表示されませんでした。
before perform: 1577983568.550754 after perform: 1577983568.550754 after reload: 1577983568.550754 これは非常に驚くべきことでした。アクセサ#created_atは、 attributes['created_at']属性ハッシュ値と同じ値である必要がありました。 アサーションで使用されたものと同じ値を出力していることを確認するために、 created_atへのアクセス方法を変更しました。
アクセサcalendar.created_at.to_fを使用する代わりに、属性ハッシュから直接フェッチするように切り替えました： calendar.attributes['created_at'].to_f 。 calendar.reloadに対する疑惑が確認されました！
before perform: 1577985089.0547702 after perform: 1577985089.0547702 after reload: 1577985089.05477 ご覧のとおり、 performを呼び出してもcreated_atは変更されませんでしたが、 reloadは変更されました。
calendarの別のインスタンスで変更が発生して保存されていないことを確認するために、もう1つの実験を実行しました。 テストの前にcalendarをリロードしました。
let(:calendar) { create(:calendar).reload } specify do expect do perform calendar.reload end .not_to change(calendar, :attributes) endそれはテストを緑にしました。
修正
タイムスタンプを切り捨ててテストに失敗するのはデータベースであることがわかっているため、切り捨てが発生しないようにすることにしました。 DateTimeオブジェクトを生成し、それを秒単位で丸めました。 次に、このオブジェクトを使用して、Railsのアクティブレコードのタイムスタンプを明示的に設定しました。 この変更により、テストが修正され、安定しました。
let(:time) { 1.day.ago.round } let(:calendar) { create(:calendar, created_at: time, updated_at: time) } specify do expect do perform calendar.reload end .not_to change(calendar, :attributes) end原因
なぜこれが起こったのですか？ Active Recordのタイムスタンプは、 Time.nowを使用してRailsのActiveRecord::Timestampモジュールによって設定されます。 Timeの精度はOSに依存し、ドキュメントに記載されているように、秒の小数部が含まれる場合があります。
小数部分の長さの頻度をカウントするスクリプトを使用して、MacOSおよびLinuxでTime.now解像度をテストしました。
pry> 10000.times.map { Time.now.to_f.to_s.match(/\.(\d+)/)[1].size }.group_by{|a| a}.map{|k, v| [k, v.count]}.to_h # MacOS => {6=>6581, 7=>2682, 5=>662, 4=>67, 3=>7, 2=>1} # Linux => {6=>2399, 7=>7300, 5=>266, 4=>32, 3=>3} ご覧のとおり、Linuxのタイムスタンプの約70％は、小数点以下7桁の精度でしたが、MacOSでは25％しかありませんでした。 これが、テストがMacOSでほとんどの場合合格し、Linuxでほとんどの時間失敗した理由です。 テスト出力の精度が9桁であることに気付いたかもしれません。これは、RSpecがTime#nsecを使用して時間出力をフォーマットするためです。
Railsモデルがデータベースに保存されると、それらのタイムスタンプは、 timestamp without time zoneと呼ばれるPostgreSQLのタイプを使用して保存されます。これは、マイクロ秒の解像度、つまり小数点以下6桁です。 したがって、 1577987974.6472975がPostgreSQLに送信されると、小数部の最後の桁が切り捨てられ、代わりに1577987974.647297が保存されます。
質問
calendar.attributes['created_at']がリロードされたにもかかわらず、 calendar.reloadを呼び出したときに、なぜcalendar.created_atがリロードされなかったのかという疑問が残ります。
また、 Time精度テストの結果は少し驚くべきものです。 MacOSでは、最大精度は6であると予想していました。 なぜ7桁になることがあるのかわかりません。 私たちをさらに驚かせたのは、最後の桁の値の分布でした。
pry> 10000.times.map { Time.now}.map{|t| t.to_f.to_s.match(/\.(\d+)/)[1] }.select{|s| s.size == 7}.group_by{|e| e[-1]}.map{|k, v| [k, v.size]}.to_h # MacOS => {"9"=>536, "1"=>555, "2"=>778, "8"=>807} # Linux => {"5"=>981, "1"=>311, "3"=>1039, "9"=>309, "8"=>989, "6"=>1031, "2"=>979, "7"=>966, "4"=>978}ご覧のとおり、MacOSの7桁目は常に1、2、8、または9です。
これらの質問のいずれかの答えを知っている場合は、私たちと説明を共有してください。
未来
Ruby onRailsのActiveRecordタイムスタンプがアプリケーション側で生成されるという事実は、これらのタイムスタンプがデータベースに保存されたイベントの信頼できる正確な順序付けに使用される場合にも問題になる可能性があります。 アプリケーションサーバーのクロックが非同期化される可能性があるため、 created_atによって順序付けられたイベントは、実際に発生したものとは異なる順序で表示される場合があります。 より信頼性の高い動作を得るには、データベースサーバーにタイムスタンプを処理させる方がよいでしょう（たとえば、PostgreSQLのnow() ）。
しかし、それは別の記事に値する話です。
この記事の作成を手伝ってくれたGabrieleRenziに特に感謝します。