RSpecのsubjectを2回呼んだのに2回目が実行されず、キャッシュやレプリカを疑って時間を溶かした話

管理画面向けのCSVエクスポート処理にテストを書いていたときのことです。「ユーザーの状態によって出力が変わる」という仕様だったので、状態ごとにcontextを分けて、それぞれでエクスポートを実行して出力を確認するテストを書いていました。

ところが、ある状態のテストだけ、DBの値は確かに更新されているのに、出力されたCSVの中身だけが古いまま、という一見矛盾した結果になりました。キャッシュやリードレプリカを疑ってしばらく調べたのですが、原因はsubjectのメモ化でした。RSpecを使っている方なら一度は聞いたことのある仕様ですが、実際にハマると意外と気づけなかったので、調査の過程と対策をまとめておきます。

なお、以下のコード例は実際のプロダクトコードではなく、同じ構造が伝わるように書き起こしたサンプルです。

状況：親のcontextで一度呼び、子のcontextで状態を変えて再度呼んでいた

テストはおおよそ次のような構成でした。exportは、CSVファイルを出力する副作用のあるメソッドです。

RSpec.describe UserCsvExporter do
  subject(:export) { described_class.export(output_path: path) }

  let(:path) { Rails.root.join('tmp/users.csv') }
  let!(:user) { create(:user) }

  before { export }

  it 'ステータスが「有効」で出力される' do
    expect(CSV.read(path).last).to include('有効')
  end

  context '退会処理後' do
    before do
      user.withdraw!
      export # ← 状態を変えたので、出力し直したつもりだった
    end

    it 'ステータスが「退会」で出力される' do
      expect(CSV.read(path).last).to include('退会')
    end
  end
end

退会後のテストでは、withdraw!でユーザーを退会させたあとにexportを呼び、退会後のステータスがCSVに出ることを確認するつもりでした。ただ、実際には「有効」のままでテストが落ちていました。

症状：DBは正しいのに、出力だけが古い

厄介だったのは、user.reload.statusを見るとちゃんと退会になっていることでした。DBは正しいのに、出力だけが古い。この組み合わせだったので、最初は次のようなことを疑いました。

• クエリキャッシュが効いていて、古い値を読んでいるのではないか
• 読み取りレプリカに向いていて、更新が反映されていないのではないか
• 非同期処理が絡んでいて、タイミングの問題なのではないか

いずれも的外れで、ここでかなり時間を使いました。エラーも出ないので、手がかりがなかったのが辛いところです。

切り分け：呼び出し回数と実行回数を比べる

行き詰まったので、エクスポート処理の内部に一時的にputsを仕込んで、実行された回数を確認することにしました。

def self.export(output_path:)
  puts 'export called'
  # ...
end

この状態で退会後のテストを回すと、exportは2回呼んでいるのに、export calledは1回しか出力されませんでした。呼び出し回数より実行ログの回数が少ない。ここでようやく、2回目の呼び出しではメソッド自体が実行されていないのでは、と気づきました。メソッドが実行されていないなら、DBが正しくても出力が古いままなのは当然です。

原因：subjectは同一example内でメモ化される

RSpecの公式ドキュメントには、subjectについて「同じexample内では値がキャッシュされ、別のexampleには引き継がれない」という趣旨の記述があります。名前付きsubjectのsubject(:export)で定義したヘルパーも、同じようにメモ化されます。

今回のテストでは、親のbeforeで1回目のexportが評価され、子のbeforeでの2回目は、ブロックを再実行せずにメモ化された1回目の戻り値を返すだけになっていました。つまり、withdraw!の前に出力された「有効」のCSVが、そのまま残っていただけでした。

subjectは「テスト対象を表す」という体裁をしているので、副作用のあるメソッドを何度も呼べる気がしてしまいます。しかし実態は、letと同じようにメモ化されるヘルパーだと理解しています。この点が、気づきにくさの原因だったと思います。

対処：状態を先に整えてから、1回だけ呼ぶ

対処は、「1 exampleにつき1回しか呼ばない」構成に直すことでした。親のcontextではexportを呼ばず、状態のセットアップを済ませてから、各contextでbefore { export }を独立して1回だけ呼ぶようにしました。

RSpec.describe UserCsvExporter do
  subject(:export) { described_class.export(output_path: path) }

  let(:path) { Rails.root.join('tmp/users.csv') }
  let!(:user) { create(:user) }

  context '初期状態' do
    before { export }

    it 'ステータスが「有効」で出力される' do
      expect(CSV.read(path).last).to include('有効')
    end
  end

  context '退会処理後' do
    before do
      user.withdraw!
      export
    end

    it 'ステータスが「退会」で出力される' do
      expect(CSV.read(path).last).to include('退会')
    end
  end
end

どうしても1つのexampleの中で複数回呼びたい場合は、subjectやletではなく、通常のメソッドとして定義するのが確実です。

def export
  described_class.export(output_path: path)
end

defにしておけば、呼ぶたびに必ずエクスポートが実行されます。

まとめ

今回ハマったことをまとめると、次のとおりです。

• subject(:name)やletは同一example内でメモ化されるので、副作用のあるメソッドを定義して複数回呼ぶと、2回目以降は実行されない
• 「DBの値は正しいのに、呼び出した処理の出力だけが古い」という症状が出ると、キャッシュやレプリカを疑いがちだが、まずメモ化を疑ってよい
• 切り分けは、対象メソッドに一時的にputsを入れて、呼び出し回数と実行回数を比べるのが手っ取り早い
• 副作用のある処理はsubject/letではなく通常のメソッドで定義するか、1 exampleにつき1回だけ呼ぶ構成にする

メモ化の仕様自体はドキュメントに書いてあることですが、エラーも出ずにテストの結果だけがおかしくなるので、気づくまでに時間がかかりました。「呼んだはずの処理が動いていない」と感じたら、デバッグ出力で実行回数を数えてみるのがおすすめです。同じような状況でハマっている方の参考になれば嬉しいです。