時々失敗するE2Eテストの原因を計測して判別する方法について - おもしろwebサービス開発日記チラシの裏

Railsをお仕事で使っている方はみんなE2Eのテストで時々失敗するやつに苦労しているんじゃないかなと思います。

@mtsmfmさんの発表スライドが詳しいので基本的にはこれで大体のケースには対応できるはず。

スライド読むのがめんどくさい人向けに、一部抜粋かつ要約すると

なんらかの要因(CSSアニメーションや画像のロード)でDOM要素が移動する場合にクリックをミスしてしまってテストが失敗するケースが「時々失敗するテスト」の大多数を占める

という話になります。これを防ぐためにはCSSのアニメーションをオフにしたり、↓のようなメソッドを利用して画像が完全にロードするまで待ってからクリックする、という方法があります。

  def wait_for_image_loading
    Timeout.timeout(Capybara.default_max_wait_time) do
      sleep 0.5 until evaluate_script(<<~JS)
        Array.prototype.every.call(
          document.querySelectorAll('img'),
          (e) => e.complete
        )
      JS
    end
  end

で、僕も同様のやり方を採用していたのですがそれでも時々テストが失敗します。そこでいい加減原因を究明しないとなーと思ったので計測の方法を調べました。

前提

Rails
rspec
capybara
selenium
headless chrome

です。バージョンはどれも現時点での最新安定版です

どこをクリックしているのか調べる

seleniumやchrome driverはそれぞれログ出力するオプションを持っていますが、僕が調べた限りではあまり有用な情報は取れませんでした(一番最後にログの取得方法を書いておきます)

seleniumには、クリックや画面遷移やjsの実行などの前後にコールバックメソッドを実行する仕組みが用意されています。

Class: Selenium::WebDriver::Support::AbstractEventListener — Documentation for selenium-webdriver (3.142.2)

これを継承した次のようなクラスを作ります。

class NavigationListener < Selenium::WebDriver::Support::AbstractEventListener
  def initialize(logger)
    @logger = logger
  end

  def after_find(by, what, driver)
    logger.info "finded #{by}, #{what}"
  end

  def before_click(element, driver)
    logger.info "clicking location: #{element.location}"

    if element.tag_name == 'a'
      href = element.attribute('href')
      logger.info "before click to: #{href}"
    end
  end

  def after_navigate_to(url, driver)
    logger.info "after navigate to: #{url}"
  end

  private

  attr_reader :logger
end

rails_helper.rbで次のようなcapybara用のdriverを作ります

logger = Logger.new(Rails.root.join('log', 'selenium_hooks.log'))
listener =  NavigationListener.new(logger)

Capybara.register_driver :selenium_chrome_headless do |app|
  browser_options = Selenium::WebDriver::Chrome::Options.new
  browser_options.args << '--headless'
  browser_options.args << '--disable-gpu'
  browser_options.args << '--no-sandbox'

  Capybara::Selenium::Driver.new(
    app, browser: :chrome, options: browser_options, listener: listener
  ).tap do |driver|
    driver.browser.manage.window.size = Selenium::WebDriver::Dimension.new(
      1920, 1080
    )
  end
end

これで、どこをクリックしようとしたのかログに残すことができます。次に、失敗を再現させてみましょう。たまにコケるテストを1000回ほど実行してみます。

# 略
    1000.times do
      it '送信したメッセージが表示されていること' do
        expect(page).to have_content(message.body)
      end
    end

このとき、rails_helper.rbで次のように最初にテストがコケたタイミングでテスト全体が終了するようにしておくと便利です。

config.fail_fast = 1

無事テストが失敗したら、失敗したときのクリック座標と成功したときのクリック座標とを比べてみたり、log/test.logでリクエストが正しく送られてきているかを確認します。僕は↓のような結果になりました。test.logを確認してもリクエストが送られていないので、これはクリックミスしている疑いが濃厚ですね…。

失敗しているとき
clicking location : #<struct Selenium::WebDriver::Point x=413.5, y=381.375>
成功しているとき
clicking location: #<struct Selenium::WebDriver::Point x=413.5, y=551.765625>

最終的に、僕の今回のケースではturbolinksを利用しているのが原因で、wait_for_image_loadingが遷移前のページに対して実行されてしまい有効に動いていなかったのが原因である、という結論になりました。次のページへの遷移を待ってからwait_for_image_loadingを実行することで解決。

seleniumとchrome driverのログを取得する方法

他にハマって時間を取られる人が減るように記録に残しておきます。seleniumのログは次のようにするととれます。

Selenium::WebDriver.logger.level = :debug
Selenium::WebDriver.logger.output = 'selenium.log'

Ruby Bindings · SeleniumHQ/selenium Wiki

chromedriverのログは次のように、新しくdriverを定義する中のdriver_optsオプションを利用します。

Capybara.register_driver :selenium_chrome_headless do |app|
  browser_options = Selenium::WebDriver::Chrome::Options.new
  browser_options.args << '--headless'
  browser_options.args << '--disable-gpu'
  browser_options.args << '--no-sandbox'

  Capybara::Selenium::Driver.new(
    app, browser: :chrome, options: browser_options, driver_opts: '--verbose'
  ).tap do |driver|
    driver.browser.manage.window.size = Selenium::WebDriver::Dimension.new(
      1920, 1080
    )
  end
end

driver_optsオプションで指定した文字列がchromedriverの起動オプションとして渡されます。(driver_optsオプションを利用すると、seleniumにdeprecatedだと怒られるのですがいったんこれでOKとしています)。

Logging - ChromeDriver - WebDriver for Chrome

(2023/08/29追記)今はdriver_optsオプションは使えません。次のようにserviceオプションを利用します。

Capybara.register_driver :selenium_chrome_headless do |app|
  options = Selenium::WebDriver::Chrome::Options.new
  options.args << '--headless'
  options.args << '--disable-gpu'
  options.args << '--no-sandbox'
  service = Selenium::WebDriver::Service.chrome
  service.args << '--verbose'
  Capybara::Selenium::Driver.new(
    app, browser: :chrome, timeout: 600, options:, service:
  )
end

(追記ここまで)

ここで注意したいのが、chromedriverのログを取得するとき、seleniumのログ設定がないとログを取得することができないということです。どうやら、selenium側でchromedriverの標準エラー出力をseleniumのログ出力と同じにしている模様(かつ、chromedriver側がそれを尊重しているっぽい(未確認))。

selenium/service.rb at abf2219b575bea98e4093fb13843f487da7edb51 · SeleniumHQ/selenium

consoleを見る方法

おまけ。↓のようにするとconsoleの出力が確認できるみたいです(今回は特に活躍することがなかった)

logger.debug(page.driver.browser.manage.logs.get(:browser))