RailsアプリのCIがランダムに失敗して治安が悪化していたのを回復した話

CIが落ちるんですよ。自分のPRとは関係ないところで。で、たまに落ちるやつかー、って再度CIを流す。ランダムにコケるので、まぁ次は通ったりするんだけど、これってあまりよい状態ではない。「またここで落ちた」みたいなのが出てきて、クラス名とかであれか、というのがわかってしまう。

そういうのが複数でてくると、再度CIを流しても別のテストでコケてしまい、テストが永遠に通らない…となる。というわけで少し前に一念発起して直してみた。

今回直したテストは合計3つで、内1つはrspecのbefore/afterでskip_callback/set_callbackしたことによって挙動が変わっていたのが原因。残り1つはArray#indexとacts_as_list#insert_atのpositionが0始まりか1始まりかの違いが原因だった。

rspecのbefore/afterでskip_callback/set_callbackしているパターン

このテストではこのcallbackは動かないようにしたい、という理由でテスト前にスキップするようにして、テスト後に再度セットしていたのだが、これがよくなかった。元々のcallbackは実行条件があったのだが、テスト後の再セットではその条件をつけずにセットしていた。こうなると、実行順序によってはどんな条件でもcallbackが走り、意図しない挙動となる。

たとえば、こういうクラスがある。nameが’taroだったらbefore_createのタイミングで例外を出す。そんなところでraiseはあまりしないと思うが、サンプルなので仕方がない。

class User < ActiveRecord::Base

  before_create :test, if: -> { name == 'taro'}



  def test

    puts 'this is after create callback'

    raise(StandardError)

  end

end

このとき、次のようなテストを書いて、テストの実行順序がランダムだと順序によっては失敗する。test1は、単純に作成したユーザの名前が指定した物かどうかをテストしている。test2は、名前が「taro」の場合例外が起こり、そうでない場合は起こらないことをテストする。ここで、test1ではnameとして「taro」を指定しているので、callbackが走るとテストできない。というわけで、テストの前後にskip/setを追加した。ここのset_callbackで、「name == ‘taro’」の条件が抜けているので、これ以降のテストではcallbackの実行条件が変わってしまう。

require 'rails_helper'



describe 'User' do

  describe 'test 1' do

    before { User.skip_callback(:create, :before, :test) }

    after { User.set_callback(:create, :before, :test) }



    it do

      user = User.create(name: 'taro')

      expect(user.name).to eq 'taro'

    end

  end



  describe 'test 2' do

    context 'name is taro' do

      it 'raised' do

        expect { User.create(name: 'taro') }.to raise_error(StandardError)

      end

    end



    context 'name is jiro' do

      it 'not raised' do

        expect { User.create(name: 'jiro') }.not_to raise_error

      end

    end

  end

end

test2=>test1の場合は問題ないが…

$ bundle exec rspec -f d spec/models



Randomized with seed 63633



User

 test 2

 name is taro

this is after create callback

 raised

 name is jiro

 not raised

 test 1

 should eq "taro"



Finished in 0.01446 seconds (files took 1.32 seconds to load)

3 examples, 0 failures

test1=>test2の場合は失敗する。

$ bundle exec rspec -f d spec/models



Randomized with seed 58258



User

 test 1

 should eq "taro"

 test 2

 name is taro

this is after create callback

 raised

 name is jiro

this is after create callback

 not raised (FAILED - 1)



Failures:



 1) User test 2 name is jiro not raised

 Failure/Error: expect { User.create(name: 'jiro') }.not_to raise_error



 expected no Exception, got #<StandardError: StandardError> with backtrace:

 # ./app/models/user.rb:6:in `test'

 # ./spec/models/user_spec.rb:23:in `block (5 levels) in <top (required)>'

 # ./spec/models/user_spec.rb:23:in `block (4 levels) in <top (required)>'

 # ./spec/models/user_spec.rb:23:in `block (4 levels) in <top (required)>'



Finished in 0.02744 seconds (files took 1.34 seconds to load)

3 examples, 1 failure



Failed examples:



rspec ./spec/models/user_spec.rb:22 # User test 2 name is jiro not raised



Randomized with seed 58258

afterでset_callbackする時に条件をちゃんと指定すればよいのだけど、そもそも他のテストに影響を与える処理をbefore/afterで動かすのはよくなさそう。というわけで、同僚からもアドバイスをもらい、こうした。

require 'rails_helper'



describe 'User' do

  describe 'test 1' do

    before { allow_any_instance_of(User).to receive(:test) }



    it do

      user = User.create(name: 'taro')

      expect(user.name).to eq 'taro'

    end

  end



  describe 'test 2' do

    context 'name is taro' do

      it 'raised' do

        expect { User.create(name: 'taro') }.to raise_error(StandardError)

      end

    end



    context 'name is jiro' do

      it 'not raised' do

        expect { User.create(name: 'jiro') }.not_to raise_error

      end

    end

  end

end

set/skipのかわりにallow_any_instance_ofでモック化すれば例外も起きない。

添字が0始まりか1始まりかで違うパターン

これはテストの実行順序ではなく、単体で発生していた。acts_as_list というライブラリのinsert_atメソッドを使っていたのだけど、どうもこのライブラリでは添字が1始まりになっているようで、Arrayとずれていた。そのため、Array#shuffleで生成したテスト用の値によっては意図通りに動かずに失敗するということだった。

Array#index

これは当然…

irb(main):001:0> [:a, :b, :c].index(:a)

=> 0

act_as_listのtop_of_list

insert_atはデフォルトだとacts_as_list_top [link]

def insert_at(position = acts_as_list_top)

  insert_at_position(position)

end

acts_as_list_topはconfiguration[:top_of_list]らしい [link]

def self.acts_as_list_top

  #{configuration[:top_of_list]}.to_i

end



def acts_as_list_top

  #{configuration[:top_of_list]}.to_i

end

configurationを見るとtop_of_listのデフォルト値は1 [link]

configuration = { column: "position", scope: "1 = 1", top_of_list: 1, add_new_at: :bottom}

そこがずれていたかー、という感想でした。

ランダムに失敗するテストとどう戦うか

callbackによる挙動の変化の場合は失敗したテストのログを眺めて、影響を与えていそうなテストの当たりをつけた。

この記事を書いている時に調べていて知ったのだけど、実行順序についてはSeed値を指定することで再現させることができるらしい。これを修正している時に知りたかった。次からは活用したい。

添字の開始値の場合は実行順序は関係がなかったので、何回もテストを実行して失敗するケースの共通点を探すところから行った。テストに限った話ではないけど、再現条件を調べてそこから原因を考えるというのは結構難しいと思う。今回は小さなテストだったので見る範囲も少なくて住んだけど、これがコード以外の要因（ミドルウェアやネットワークなど）も絡んでくると大変だ。

後は、放置せずに直そう、という反省を得た。CIに10分とか20分とかかかっている場合、こういうランダムな失敗でCIがコケるのはもったいない。今回は短期間で割と一気に直したけど疲れるし、CIが落ちにくくなって良いことなんだけど、悪くなっていたのが元に戻っただけともいえる。

バグが減って治安がよくなりました