時々失敗するE2Eテストの原因を計測して判別する方法について

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))

turbolinks環境でCSPを導入しようとしたらテストがコケた

CSPを導入しようとして、まず様子見でcontent_security_policy_report_only = trueとしていろいろ試していたらテストが落ちるようになった。content_security_policy_report_only = trueだとjsやcssは普通に適用されるはずなのにおかしい。

落ちているテストをよく見ると、flashメッセージを表示する箇所がほとんどだった。サーバのログを見るとなぜか同じページに2回アクセスしている。

いろいろ追いかけた結果、次の行が原因なのを突き止めた。

javascript_pack_tag 'application', 'data-turbolinks-track': 'reload', defer: true, nonce: true

CSP用にnonce: trueを追加した。これにより、毎回scriptタグのnonce属性が変更される。turbolinksで'data-turbolinks-track': 'reload'としていると、リソースのURLが変更されたときにページがフルにリロードされる仕様。なのだけど、これがURLだけではなくてどの属性が変更されてもフルでリロードされるようになっていた。

turbolinks/snapshot_renderer.ts at master · turbolinks/turbolinks

'data-turbolinks-track': 'reload'を削除したら落ちたテストが通るようになった。でもこれがよい解決策かというと微妙な気がする…

追記

テストは通るようになり、ページが毎回フルでリロードされることはなくなったけど、nonceが変更されたことでturbolinksが「新しいscriptタグが挿入された」と解釈するのかページアクセスのたびにjsが実行されてしまう><

更に追記

とりあえずIssueを立てておきました。

github.com

resize_to_fitオプションはどこからきたのか

Railsのmasterのコードを読んでいて、コメント行でvariantメソッドにresize_to_fitオプションを渡しているのが目についた。

rails/variant.rb at master · rails/rails

というのは、ImageMagickのオプションにresize_to_fitに相当するものがなかったから。minimagickはImageMagickにそのままオプション渡しているはずなのになんでだろう?

Command-line Options @ ImageMagick

と、調べたところ、Rails6からはminimagickに変わってImageProcessingがデフォルトになり、ImageProcessingがresize_to_fitを提供している、ということだった。

Mogrify unrecognized option resize-to-fit · Issue #39 · janko-m/image_processing

mailcatcherとletter_opener_webの使い分け

letter_openerをよく使います。ローカルの開発環境でメールが送信されたらブラウザのタブが新しく開き、メールが送信されたことがすぐにわかる。べんり。

しかし、最近Docker環境で開発することが増えたので、自動でホストマシンのブラウザタブを開くことができなくなってしまいました。どうしよう。

開発用のメールボックスをブラウザで確認するgemとして有名なのはletter_opener_webMailCatcherです。ざっと調べて所感をまとめました。

letter_opener_web

  • letter_opener の拡張
  • rails engineとして作られている
    • なので、Railsにマウントして使う
  • mailcatcherより手軽に使える一方、別プロセスからのメール(例: ワーカからメールを送信する)には対応していないという欠点もある

mailcatcher

  • SMTPサーバを別プロセスで立てる
    • dockerコンテナを一個増やさないといけないのがめんどい
  • 別プロセスからのメールでも問題ない

所感

  • ローカルでdocker-composeを利用した開発環境の場合はletter_opener_webのほうが楽そう
    • 開発環境でのActive Jobはasync(同一プロセス別スレッド)なのでdeliver_laterでも問題なくメール受け取れるはず
  • ↑以外のことをしたいならmailcatcherを使ったほうが便利そう
    • 例えば外部にデモ環境を作る、とか

結論として、とりあえずYAGNIの精神でletter_opener_webにしておくのがいいかな、という気持ちになってきました

ajaxでHTMLをリクエストするタイプの設計のときに、メタ情報もうまく受け取りたい

Railsアプリケーションを書くときに、turbolinksやstimulusなどを使い、なるべくサーバサイドはHTMLを返してjsをあまり書かずに楽をする、という方針でいくとします。このように割り切るとだいぶ楽なのですが、例えば次のようなケースで悩みます。

  • コメントを最新10件表示する
  • コメントが11件以上ある場合は「もっと読む」ボタンが表示される
  • 「もっと読む」を押したときにajax経由でHTML片を取得し、新しくコメントを10件追加表示する
  • 最後のコメントにたどり着いたときに「もっと読む」ボタンを消す

一番最後の「もっと読む」ボタンを消すやり方が悩みどころです。単にHTMLを受け取りコメントの末尾に差し込むやり方では対応できません。だからといってレスポンスをJSONで返し、そこからDOMを生成するのは面倒なのでやりたくない。

いくつかやり方を考えてみました。

  1. DOM構造を変更し、「もっと読む」ボタンを上書きできるような形でコメントを追加できるようにする
  2. サーバからはHTMLを含んだjsを返し、クライアント側ではそれを実行するようにする。js内でHTMLの挿入と「もっと読む」ボタンの削除を両方できるように書く
  3. (stimulusを使っていれば)「最後のコメントまで来た」というdata-targetを追加で挿入しておき、HTMLを挿入したあとにtargetをチェックする
  4. レスポンスヘッダに「これが最後のコメントである」という情報を含める

3か4のどちらかがよさそうです。1はDOM構造がページングの仕様に引きずられてしまうのがよくないでしょうし、2はstimulusを使っている場合はjsの処理が散らばるので可読性が下がりそう(stimulusを使っていなければこれが楽でよさそうです)。3は悪くないですが、これも若干DOM構造がページングの仕様に引きずられる感じがありますね。直感的ではない。

stimulusを使っているので、最終的に4で実装しました。こんな感じ。

    fetch(Routes.api_comments_path({ page: nextPage }), { credentials: 'include' })
      .then(response => {
        if (response.headers.has('X-Comments-Last-Page')) {
          this.pagingButtonTarget.style.display = 'none'
        }
        return response.text()
      })
      .then(html => {
        this.commentListTarget.insertAdjacentHTML('beforeend', html)
        this.data.set('page', nextPage)
      })

macで/etc/hostsに定義を追加するときの注意点

開発用に、127.0.0.1に解決されるドメインを/etc/hostsに登録する、ということはそれなりにあると思います。

そのときに、次のように複数行に分けて書くとなぜか example.com へのDNS lookupがめちゃくちゃ遅くなります。自分の環境ではだいたい5秒ほどかかりました。

127.0.0.1       localhost 
127.0.0.1       example.com

これを次のように1行で書くと問題なくなります。

127.0.0.1       localhost example.com

なぜか開発用のサーバが遅い!となってからここにたどり着くまでめっちゃ大変でした…><

参考

superuser.com

確認したバージョン

macOS 10.13.6

参考リンクをたどると、ずっと前からある問題っぽいですね。

OmniAuthでログインを失敗したときのテストでエラーが出たときの対処法

OmniAuthを利用したログインのsystem specで、ログインに失敗した場合のテストが次のようなエラーになった。

  1) ユーザがログインする ログインに失敗したとき "ログインに失敗しました"と表示されること
     Failure/Error: click_link 'Twitterでログイン'
     
     OmniAuth::Error:
       invalid_credentials
     # ./spec/system/login_spec.rb:98:in `block (3 levels) in <top (required)>'

もとになったspecはこちら。

  context 'ログインに失敗したとき' do
    around do |example|
      original_mock_auth = OmniAuth.config.mock_auth[:twitter]
      OmniAuth.config.mock_auth[:twitter] = :invalid_credentials
      visit root_path
      click_link 'Twitterでログイン'
      example.run
      OmniAuth.config.mock_auth[:twitter] = original_mock_auth
    end

    it '"ログインに失敗しました"と表示されること' do
      expect(page).to have_content 'ログインに失敗しました'
    end
  end

これまでは普通にテストが通っていたのでなんだろうと思って調べた。

原因

つまりテストの実行順序の問題で、pumaの起動がOmniAuthのテストより前に来てしまうとRACK_ENVがdevelopmentになり期待していた挙動と異なる振る舞いをするようになってしまっていた。

とりあえず明示的に、次の行をconfig/rails_helper.rbに追加したところうまく動くようになった。

ENV['RACK_ENV'] ||= 'test'

所感

これ、自分と同じようにハマる人が出てくると思うのでライブラリ側でどうにかしたいのだけど、どのライブラリにどのようにPR投げるか悩ましいですね…

  • rspec-rails
  • puma
  • capybara
  • omniauth

のどれか。rspec-railsでrails_helper.rbのテンプレートをいじってRACK_ENVもRAILS_ENVと同様に設定するようにする、というのがいいだろうか。

おまけ

どこでRACK_ENVが設定されているか調べるのに使った雑なスクリプトを置いておきます

module DebugEnv
  def []=(*args)
    key = args.first
    if key == 'RAILS_ENV' || key == 'RACK_ENV'
      p args
      p caller
    end
    super
  end
end

ENV.singleton_class.prepend DebugEnv

あと、この手の環境変数関連のデバッグではspringは切っておいたほうが良さそう(ちゃんと調べきれてないけど、設定されていないはずのタイミングでRACK_ENVが設定されていて、これでかなり時間を奪われた><)

また、rake specrakeでテストを実行しているときにはこの問題は発生しなさそう。

rspec-rails/rspec.rake at master · rspec/rspec-rails