SUZURI Ruby Rails flaky test

flaky testの原因は、無関係なファイルの1行にあった

SUZURI Ruby Rails flaky test

SUZURI Webアプリケーションエンジニアのarumaです。昨日の記事では、SUZURIで遭遇したflaky testの事例をいくつかご紹介しました。本記事では、その中でも特に原因の特定が難しかった1件を深掘りします。

  1. 発生していた現象
  2. 手がかり1: 自前のメソッドが呼ばれていない
  3. 手がかり2: フレームワークに同名メソッドが追加されていた
  4. 手がかり3: ancestorsチェーンの順序が変わっている
  5. 手がかり4: トップレベルでのinclude
  6. 真相
  7. おわりに

発生していた現象

ApplicationHelper に定義された画像表示用のヘルパーメソッド picture_tag のテストが、時々failしていました。

fail時のログを確認すると、picture_tag が期待と異なるHTMLを生成していました。

CIの実行ログからpass時とfail時それぞれのseed値を確認し、ローカルで同じseedを指定して実行してみると、seed値に応じてpassとfailが再現しました。

手がかり1: 自前のメソッドが呼ばれていない

試しに ApplicationHelper#picture_tag の中身に raise を加えてそれぞれのseedで実行してみると、

  • passしていたseedで実行 → 例外が発生
  • failしていたseedで実行 → 例外は発生せず、同じようにfail

という結果になりました。つまり、failするseedでは、テスト対象 ApplicationHelper#picture_tag がそもそも呼ばれていないということです。では、代わりに何が呼ばれているのでしょうか？

手がかり2: フレームワークに同名メソッドが追加されていた

picture_tag で検索してみると、Rails 7.1で ActionView::Helpers::AssetTagHelper に同名の picture_tag メソッドが新規追加されていたことがわかりました。ApplicationHelper#picture_tag とは異なる動作をするメソッドです。

fail時の出力は、この AssetTagHelper#picture_tag の動作と一致していました。failするseedでは、ApplicationHelper#picture_tag ではなく AssetTagHelper#picture_tag が呼ばれていたようです。

Rubyのメソッド解決は、ancestorsチェーンを前から順にたどり、最初に見つかったメソッドを呼び出す仕組みです。通常、ApplicationHelper は ActionView::Helpers::AssetTagHelper よりもancestorsチェーンの前方に位置するため、フレームワーク側に同名のメソッドが追加されても ApplicationHelper の方が優先されるはずです。

ところが今回は、seed値によって呼ばれるメソッドが変わっています。ancestorsチェーンを実際に確認してみることにしました。

手がかり3: ancestorsチェーンの順序が変わっている

pass時とfail時、それぞれのseedでテスト対象のオブジェクトのancestorsチェーンを出力して比較してみると、次のようになっていました。

pass時

...
 29: ApplicationHelper
...
 77: ActionView::Helpers::AssetTagHelper
...

fail時

...
 76: ActionView::Helpers::AssetTagHelper
...
 95: ApplicationHelper
...

pass時には ApplicationHelper が AssetTagHelper より前にありますが、fail時には順序が逆転していました。つまり、failするseedでは AssetTagHelper#picture_tag が先に見つかり、そちらが呼ばれていたのです。

手がかり4: トップレベルでのinclude

ancestorsチェーンが変わる原因を突き止めるため、ApplicationHelper に included フックを仕込みました。モジュールがどこかに include されるたびに、include先とそのコールスタックを出力するものです。

module ApplicationHelper
  def self.included(base)
    puts "ApplicationHelper included into: #{base}"
    puts caller.first(3).join("\n")
  end
end

failするseedで実行してみると、次の出力が得られました。

ApplicationHelper included into: Object
  spec/graphql/queries/some_query_spec.rb:2:in 'include'
  spec/graphql/queries/some_query_spec.rb:2:in '<main>'

ApplicationHelper が Object クラスに includeされています。該当のspecファイルを見てみると、以下のようなコードでした。

require 'spec_helper'
include ApplicationHelper

describe 'SomeQuery' do
  # ...
end

include が describe ブロックの外、つまりトップレベルで実行されています。トップレベルで include を実行すると、Object クラスに対しての include となります。Object はほぼ全てのRubyクラスの祖先なので、ここにモジュールが追加されると全クラスのancestorsチェーンに影響します。

真相

今回の事象は、3つの要因が重なって発生していました。

  1. Rails 7.1で追加された AssetTagHelper#picture_tag と、自前の ApplicationHelper#picture_tag が名前衝突していた。どちらが呼ばれるかはancestorsチェーンの順序で決まる（通常は自前のメソッドが優先される）
  2. あるspecファイルがトップレベルで（つまり Object へ） include ApplicationHelper を実行していた
  3. RSpecのテスト実行順序はseed値によって毎回変わる

つまり、seed値次第で、テスト実行の流れは次のどちらかになります。

問題のspecが先に実行される場合:

  1. テスト実行開始
  2. 問題のspecが読み込まれ、ApplicationHelper が Object にincludeされる
  3. ヘルパーのspecが実行される。ApplicationHelper はすでにinclude済みのため、テストコンテキストへのincludeが無視され、AssetTagHelper#picture_tag が優先される → fail

問題のspecが後に実行される場合:

  1. テスト実行開始
  2. ヘルパーのspecが実行される。ApplicationHelper が通常通りテストコンテキストにincludeされ、ApplicationHelper#picture_tag が優先される → pass
  3. 問題のspecが読み込まれ、ApplicationHelper が Object にincludeされる（しかし結果に影響しない）

なお、”先か後か” の二択ならfailの確率は50%となりますが、SUZURIのCIではテストを複数プロセスに分散して実行しているため、実際の発生頻度は数%程度となっていたのでした。

原因さえわかれば対策はシンプルで、トップレベルでの include をやめるだけでした。
同種の問題を防ぐには、トップレベルでの include を禁止するlint規則が有効です。

おわりに

この問題は、今回のflaky test対処の中で原因特定に最も時間がかかったケースでした。どの要因も単体では問題になりませんが、3つが重なることで原因の見えにくいflaky testになっていました。

他のflaky testの事例は前回の記事で紹介しています。

関連記事

書いた人