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 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
ここで注意したいのが、chromedriverのログを取得するとき、seleniumのログ設定がないとログを取得することができないということです。どうやら、selenium側でchromedriverの標準エラー出力をseleniumのログ出力と同じにしている模様(かつ、chromedriver側がそれを尊重しているっぽい(未確認))。
selenium/service.rb at abf2219b575bea98e4093fb13843f487da7edb51 · SeleniumHQ/selenium
consoleを見る方法
おまけ。↓のようにするとconsoleの出力が確認できるみたいです(今回は特に活躍することがなかった)
logger.debug(page.driver.browser.manage.logs.get(:browser))