Rails アプリケーションの不安定なテストを撲滅したい〜system spec のデバッグ方法とテストを不安定にさせる要因〜

2019-09-17

Ruby
Rails

Rails アプリケーションの開発において、自分の変更に関係のないテストのせいで CI がコケるとストレスですよね？真っ先に直したくなりますよね？不安定なテストを直すのは大変な労力が要ると思ってませんか？実は、たいていのケースは簡単に再現確認ができるし、不安定になる要因もだいたい決まっているし、ログやスクリーンショットを見れば原因も簡単に特定できるんです！

そんなわけで、日頃不安定なテストを潰している身として知見みたいなものをまとめてみました。
今回利用した環境は次のとおりです。

rails 6.0.0
capybara 3.29.0
selenium-webdriver 3.142.4
rspec-rails 3.8.2
Google Chrome 77.0.3865.75 (headless で使用)
ChromeDriver 77.0.3865.40 (f484704e052e0b556f8030b65b953dce96503217-refs/branch-heads/3865@{#442})

記事の中に出てくるコードを含めたサンプルアプリケーションも作ったので、イメージが沸かない場合はこちらも参照すると良いかもです。
abicky/rails-system-spec-example

再現確認方法

CI がたまにコケる場合、まずは再現確認が重要です。コケた example 単体で実行して再現しなくても、9 割以上のケースは CI と同じテストを全く同じ順番で何度か実行してみることで再現するはずです。

テストの実行順番をランダムにしていたり、CI では複数プロセスでテストを実行しているケースもあると思いますが、その場合は --format json の結果を保存しておけば、その情報を基に全く同じ順番で実行することができます。

例えば、result.json というファイルに結果が保存されている場合、次のように rspec を実行すれば全く同じ順番で実行できます。

bundle exec rspec \
  --seed $(jq -r '.seed' result.json) \
  $(jq -r '[.examples[].id] | join(" ")' result.json)

CircleCI 上でテストを動かす場合、次のように結果を artifacts として保存しておくと良いでしょう。

version: 2
jobs:
  build:
    docker:
      - image: circleci/ruby:2.6-node-browsers
    steps:
      - checkout

      -- snip --

      - run:
          command: |
            bundle exec rspec --format json \
                              --out result.json \
                              --format RspecJunitFormatter \
                              --out test_results/rspec.xml \
                              --format progress
                              $(circleci tests glob "spec/**/*_spec.rb" | circleci tests split --split-by=timings)

      - store_test_results:
          path: test_results

      - store_artifacts:
          path: result.json

たまにコケる system spec のデバッグ方法

再現確認できたなら、あとはデバッグするだけです！Ruby で完結している範囲であればブレークポイントを設定したりして地道にデバッグすれば良いでしょうが、system spec は少し大変だと思うので、デバッグの効率を上げるための方法についていくつか紹介します。

とにかくログを見る
Chrome の remote debugging を利用する
スクリーンショットを撮る
サーバ側でエラーがあったら気付けるようにしておく

以下詳細です。

とにかくログを見る

基本中の基本ですが、ログを見ることは超重要です。次のようにすれば chromedriver のログと JavaScript の console log を確認できるようになります。もちろん Rails のログを見ることも重要です。

Capybara.register_driver :verbose_chrome_headless do |app|
  Capybara::Selenium::Driver.new(app,
    browser: :chrome,
    options: Selenium::WebDriver::Chrome::Options.new(
      args: %w[headless],
    ),
    desired_capabilities: Selenium::WebDriver::Remote::Capabilities.chrome(
      # console log にアクセスできるようにする
      'goog:loggingPrefs': {
        browser: "ALL",
      },
    ),
    # chromedriver のログを有効にする
    service: Selenium::WebDriver::Service.chrome(
      args: {
        log_path: '/tmp/chromedriver.log',
        verbose: true,
      },
    ),
  )
end

RSpec.configure do |config|
  config.before(:each, type: :system) do
    driven_by :verbose_chrome_headless
  end
end

例えば、chromedriver のログには次のような情報が出てきます。

[1568544876.601][DEBUG]: DevTools WebSocket Command: Input.dispatchMouseEvent (id=41) 987FE584E90120F2361ABE3E4BAFC95C {
   "button": "left",
   "buttons": 0,
   "clickCount": 1,
   "modifiers": 0,
   "pointerType": "mouse",
   "type": "mousePressed",
   "x": 28,
   "y": 18
}
[1568544876.624][DEBUG]: DevTools WebSocket Response: Input.dispatchMouseEvent (id=41) 987FE584E90120F2361ABE3E4BAFC95C {

}
[1568544876.624][DEBUG]: DevTools WebSocket Command: Input.dispatchMouseEvent (id=42) 987FE584E90120F2361ABE3E4BAFC95C {
   "button": "left",
   "buttons": 1,
   "clickCount": 1,
   "modifiers": 0,
   "pointerType": "mouse",
   "type": "mouseReleased",
   "x": 28,
   "y": 18
}
[0915/195437.184720:ERROR:paint_controller.cc(548)] PaintController::FinishCycle() completed
[1568544877.186][DEBUG]: DevTools WebSocket Event: Page.javascriptDialogOpening 987FE584E90120F2361ABE3E4BAFC95C {
   "defaultPrompt": "",
   "hasBrowserHandler": false,
   "message": "clicked!",
   "type": "alert",
   "url": "http://127.0.0.1:59064/"
}

このログから、(28, 18) をクリックしたら「clicked!」というアラートが表示されたということまで読み取ることができます。

また、次のようなメソッドを定義しておくと、display_console_logs を実行するだけで console log の内容が確認できて便利です。

def display_console_logs
  console_logs.each do |log|
    t = log.timestamp
    message = log.message.sub(%r{http://127.0.0.1:\d+}, '')
    message.sub!(%r{\bapplication-\w+\.js\b}, 'application.js')
    puts "#{Time.at(t / 1000, t % 1000 * 1000).strftime('%F %H:%M:%S.%3N')}: #{log.level}: #{message}"
  end
  nil
end

def console_logs
  @console_logs ||= []
  if page.driver.browser.manage.respond_to?(:logs)
    @console_logs.concat(page.driver.browser.manage.logs.get(:browser))
  else
    # cf. https://stackoverflow.com/questions/56522499/cromedriver-driver-manage-logs-getbrowser-fails-on-chromedriver-75-0-3770-8
    @console_logs.concat(page.driver.browser.logs.get(:browser))
  end
end

display_console_logs を実行すると、例えば次のような内容が表示されます。

2019-09-17 03:13:18.104: INFO: /packs-test/js/application.js 147:8 "Hello from application.js"
2019-09-17 03:13:18.104: INFO: / 14:8 "Hello from index.html"

Chrome 自体のログも役に立ちそうなんですが、Linux で enable-logging v=1 を指定したり、macOS で enable-sandbox-logging を指定したりしても明らかにログの量が少なくてよくわからなかったので有効にしていません。

Chrome の remote debugging を利用する

ローカルホストで system spec を動かせるようになっていて、普通にブラウザを起動できる場合は headless option を取り除くことで簡単にデバッグできますが、そうでない場合は remote debugging を利用すると良いです。
option に remote-debugging-port=9222 等、ポート番号を指定することで利用できるようになります。

Capybara.register_driver :debuggable_chrome_headless do |app|
  Capybara::Selenium::Driver.new(app,
    browser: :chrome,
    options: Selenium::WebDriver::Chrome::Options.new(
      args: %w[headless remote-debugging-port=9222],
    ),
  )
end

RSpec.configure do |config|
  config.before(:each, type: :system) do
    driven_by(:debuggable_chrome_headless)
  end
end

なお、docker container で動かす場合は option に remote-debugging-address=0.0.0.0 も追加し、container とホストのポートをマッピングする必要があります。

remote debugging を有効にして、system spec 実行中に指定したポート (e.g. localhost:9222) にアクセスすると、次のように system spec を実行中のタブの情報が出てきます。

リンクをクリックすると現在のタブの状態がどうなっているか確認することができます。binding.irb などで使えば特定のタイミングで止めることができるので便利です。普通のウェブページと同様、console log の内容も確認できるし、要素をクリックすることもできるし、JavaScript を実行することもできます。

余談ですが、リモートデバッグした後にテストを再開したい場合ってどうすればいいんでしょうね…。Chrome からの応答がなくなってしまうからテストを再開したくても止まったままになる。

スクリーンショットを撮る

system spec は勝手に failed example のスクリーンショットを撮ってくれます。CI で system spec がコケた時の情報としてはかなり有用です。
ローカルで実行した場合は tmp/screenshots 以下にスクリーンショットが残っているから良いですが、CI の場合は artifacts として残るようにしておくと良いでしょう。

例えば CircleCI の場合は次のようにすると良いです。

version: 2
jobs:
  build:
    docker:
      - image: circleci/ruby:2.6-node-browsers
    environment:
      # rails 6.0.0 ではまだ使えないがそのうち使えるようになる
      # cf. https://github.com/rails/rails/pull/36545
      RAILS_SYSTEM_TESTING_SCREENSHOT_HTML: 1
    steps:
      - checkout

      -- snip --

      - store_artifacts:
          path: tmp/screenshots

なお、rails 6.0.0 と rspec-rails 3.8.2 の組み合わせだと Capybara.reset_sessions! を呼んだ後に save_screenshot が呼ばれるので、スクリーンショットの内容が真っ白になります。
所望のスクリーンショットを撮るには次のようなワークアラウンドが必要です。

module SystemHelper
  extend ActiveSupport::Concern

  included do |example_group|
    # Screenshots are not taken correctly
    # because RSpec::Rails::SystemExampleGroup calls after_teardown before before_teardown
    example_group.after do
      take_failed_screenshot
    end
  end

  def take_failed_screenshot
    return if @is_failed_screenshot_taken
    super
    @is_failed_screenshot_taken = true
  end
end

RSpec.configure do |config|
  config.include SystemHelper, type: :system
end

artifacts の保存ができない環境の場合は S3 等に直接アップロードするのもありでしょう。

module SystemHelper
  extend ActiveSupport::Concern

  included do |example_group|
    # Screenshots are not taken correctly
    # because RSpec::Rails::SystemExampleGroup calls after_teardown before before_teardown
    example_group.after do
      take_failed_screenshot
    end
  end

  def take_failed_screenshot
    return if @is_failed_screenshot_taken
    super
    @is_failed_screenshot_taken = true

    if failed? && supports_screenshot?
      File.open(image_path, "rb") do |f|
        Aws::S3::Client.new.put_object(
          bucket: ENV["SCREENSHOT_S3_BUCKET"],
          key: "#{ENV["SCREENSHOT_S3_PREFIX"]}/#{File.basename(image_path)}",
          body: f,
        )
      end
    end
  end
end

サーバ側でエラーがあったら気付けるようにしておく

Rails では action_dispatch.show_exceptions を false にすることで例外を投げるようになって、system spec でもエラーの内容が表示されるようになるんですが、何らかの理由によって action_dispatch.show_exceptions が true に設定されていると例外に気付けません。
例外が原因で本来表示されるべき要素が見つからなかっただけなのに、rspec からは「要素が見つからない」と言われるだけだとデバッグが大変です。ちゃんと Rails のログにアクセスできて、それを見る癖が付いていれば良いですが、そうでなければ難解な問題になるので、断固として config/environments/test.rb の action_dispatch.show_exceptions は false を設定するようにしましょう。

次のキャプチャは action_dispatch.show_exceptions=false の場合の CircleCI 上での見え方です。

cf. https://circleci.com/gh/abicky/rails-system-spec-example/6

次のキャプチャは action_dispatch.show_exceptions=true の場合の CircleCI 上での見え方です。

cf. https://circleci.com/gh/abicky/rails-system-spec-example/7

どちらがわかりやすいか一目瞭然ですよね！上記の例だとまだ「エラーページが表示されているんだな」と気付けますが、JS で通信した要素を挿入する場合などはエラーが起きていることに気付けません。

たまにテストをコケさせる要因

デバッグ方法に加えて、不安定なテストになる要因を知っておけば未然に防ぐことや、そのようなテストを解消する際にかかる時間を短縮することができるはずです。

不安定なテストの要因としてはだいたい次のどれかに当てはまるんじゃないかと思います。

ソートの結果が不定
別の example で追加した DB のレコード
別の example で追加したキャッシュ
非同期リクエストがサーバで処理される前の操作
テストを実行しているサーバの高負荷
トップレベルへの定数定義
stub_const による module 化

以下詳細です。

ソートの結果が不定

例えば created_at の降順でリソースの内容を表示するページで、1 番目のリソースの内容を確認するようなテストがあったとします。

let!(:users) do
  [User.create!(name: "foo"), User.create!(name: "bar")]
end

it "displays the latest user first" do
  visit "/users"
  within ".users .user:first-child" do
    expect(page).to have_content(users.last.name)
  end
end

created_at の精度にもよりますが、このテストは DB に保存される created_at が全く同じ値になる可能性が高いため、User.order(created_at: :desc) でソートしている場合は結果が不定になります。
よって、User.order(created_at: :desc, id: :desc) 等、必ず同じ結果になるようにソートしなければたまにコケるテストになってしまいます。

別の example で追加した DB のレコード

rspec の use_transactional_fixtures が true になっていれば、before :all などトランザクション外でレコードを作成しない限りは問題にならないでしょうが、false にしていて自前でテーブルを管理している場合は問題になることがあります。
これが原因でテストがコケる場合、別の example や rspec-retry の別の試行によって作成されたレコードに影響を受けないように before hook やテスト内容を工夫する必要があります。

別の example で追加したキャッシュ

Rails.cache 等をテストの実行前か実行後にクリアしないといけないのは容易簡単に想像が付くでしょうが、クラスインスタンス変数のメモ化などは曲者です。
例えば次のようなテストを実行すると、RSpec::Mocks::ExpiredTestDoubleError という例外が投げられます。

class SomeClass
  class Foo
    def name
      "foo"
    end
  end

  class << self
    def foo
      @foo ||= build_foo
    end

    def build_foo
      Foo.new
    end
  end
end

RSpec.describe SomeClass do
  it do
    allow(described_class).to receive(:build_foo) { double(name: "bar") }
    expect(described_class.foo.name).to eq "bar"
  end

  it do
    expect(described_class.foo.name).to eq "foo"
  end
end

次のようなエラーメッセージが表示されるわけですが、一瞬何が起きてるのかわからないですよね。

Failures:

  1) SomeClass
     Failure/Error: expect(described_class.foo.name).to eq "foo"
       #<Double (anonymous)> was originally created in one example but has leaked into another example and can no longer be used. rspec-mocks' doubles are designed to only last for one example, and you need to create a new one in each example you wish to use it for.

remove_instance_variable の使用の是非は置いておいて、先ほどのテストを通すには例えば次のようにクラスインスタンス変数を削除する必要があります。

RSpec.describe SomeClass do
  it do
    allow(described_class).to receive(:build_foo) { double(name: "bar") }
    expect(described_class.foo.name).to eq "bar"
  end

  it do
    SomeClass.remove_instance_variable(:@foo)
    expect(described_class.foo.name).to eq "foo"
  end
end

非同期リクエストがサーバで処理される前の操作

例えば次のように、「Update」ボタンを押した後にトップページにアクセスすると更新後の名前でメッセージが表示されることを確認するテストを考えます。

it "updates the user name" do
  visit "/setting"
  fill_in "user[name]", with: "bar"
  click_on "Update"

  visit "/"
  expect(page).to have_content("Hello, bar!")
end

このテストは、click_on "Update" の処理が終わった後に visit "/" が処理されていれば良いのですが、そうでない場合はコケてしまいます。
更新完了後に何かしらのメッセージを表示している場合、そのメッセージが表示されることを確認することでこの問題を解消することができます。

it "updates the user name" do
  visit "/setting"
  fill_in "user[name]", with: "bar"
  click_on "Update"
  expect(page).to have_content("Your name has been successfully updated!")

  visit "/"
  expect(page).to have_content("Hello, bar!")
end

余談ですが、リクエストの完了を待つのに Capybara::Server#wait_for_pending_requests というメソッドが使われている Rails アプリケーションがあって、このメソッドが上手く動かないケースがあることに気付いて issue にしたんですが、「このメソッドは内部向けだし、リクエストの完了をユーザが気付けるような内容を表示し、それの有無を確認すべき」みたいな返答をもらいました。
cf. wait_for_pending_requests doesn’t work if multiple drivers are used · Issue #2106 · teamcapybara/capybara

次のような書き方をしないといけない場合、ユーザ体験として好ましくないってことですね。

it "updates the user name" do
  visit "/setting"
  fill_in "user[name]", with: "bar"
  click_on "Update"
  wait_for_ajax # 更新リクエストの完了を待つメソッド

  visit "/"
  expect(page).to have_content("Hello, bar!")
end

テストを実行しているサーバの高負荷

サーバの高負荷がテストの結果に影響を与えることもあります。

実際にあった例を挙げると、Chrome を使った system spec で StaleElementReferenceError (“stale element reference: element is not attached to the page document”) というエラーに頻繁に遭遇することがありました。

テストの内容は何の変哲もない次のようなものだったんですが、expect(page).to have_content "Clicked" のところでこのエラーが出ました。

within "#wrapper" do
  click_on "Click Me"
  page.driver.browser.switch_to.alert.accept

  expect(page).to have_content "Clicked" #=> StaleElementReferenceError
end

テストがコケている時の傾向から、サーバが高負荷な時に起きるのではと予想したところ、stress コマンドで負荷をかけて実行するとかなりの高確率で再現したので、StaleElementReferenceError が出たらリトライする処理を入れることにしました。

def retry_on_stale_element_reference_error(&block)
  first_try = true
  begin
    block.call
  rescue Selenium::WebDriver::Error::StaleElementReferenceError
    $stderr.puts "Retry on StaleElementReferenceError"
    if first_try
      first_try = false
      retry
    end
    raise
  end
end

within "#wrapper" do
  click_on "Click Me"
  page.driver.browser.switch_to.alert.accept

  retry_on_stale_element_reference_error do
    expect(page).to have_content "Clicked"
  end
end

次の組み合わせの時に遭遇したんですが、同じテストに対して最新の Chrome 77 で試したところ再現しなかったので、どこかのタイミングで直ったのかもしれません。

Chrome 73.0.3683.86
chromedriver 2.46.628388

なお、このエラーはアクセスしようとした要素がページに存在しない場合に出るエラーで、上記のコードでは within 内の page に相当する要素、つまり #wrapper が消えているというエラーメッセージです。
cf. https://chromium.googlesource.com/chromium/src/+/77.0.3865.40/chrome/test/chromedriver/js/call_function.js#183

トップレベルへの定数定義

Ruby のブロックは namespace を作らないので、テスト内で定数を定義するとトップレベルに定義されます。例えば、次のようなテストは ::SomeClass が定義されます。

RSpec.describe SomeModule do
  class SomeClass
    include SomeModule
  end

  subject(:instance) { SomeClass.new }

  describe "#foo" do
    it { expect(instance.foo).to eq "foo" }
  end
end

ファイルが読み込まれた時点でクラスが定義されるので、1 プロセスで全 spec を実行している場合はこれによって結果が不安定になることはないですが、複数プロセスで分割実行する場合は、あるファイルと一緒に処理される時だけテストがコケるという謎の結果になります。
これを回避するには、Class.new でクラスを定義します。

RSpec.describe SomeModule do
  let(:klass) do
    Class.new do
      include SomeModule
    end
  end

  subject(:instance) { klass.new }

  describe "#foo" do
    it { expect(instance.foo).to eq "foo" }
  end
end

stub_const による module 化

例えば A::B という定数を stub する場合、A を読み込む前に stub_const を実行すると A は module になってしまいます。

before do
  stub_const("A::B", 1)
end

他のテストの実行によって A が読み込まれていれば問題ないですが、読み込まれていたりいなかったりでテストがコケたりコケなかったりになります。
これを回避するには、stub_const を実行する前にクラスを参照する必要があります。

before do
  A
  stub_const("A::B", 1)
  # 2 行に跨るのが嫌であれば stub_const("#{A}::B", 1) みたいな書き方でも良い
end

ちなみに stub_const で module になる件についてはちょいちょい issue に上がっているんですが、「stub_const する前にロードすればええやん」というスタンスみたいです。

cf. Fix stub_const for case that const_missing defines target nested constant by sorah · Pull Request #201 · rspec/rspec-mocks

おわりに

あとは実践あるのみです！不安定なテストは放置していると日々増えていくので、同じテストで複数回コケたのを見かけたら地道に潰していきたいですね！！