Capybaraの実行ログをEventListenerを使って表示してみる

RspecとCapybaraを使ってE2Eテストの土台を作ってみる

上記の記事では、スペックの実行結果のみが表示されて詳細な動作ログが出力されていません。
全てのスペックが毎回問題なく成功すれば良いのですが、環境やタイミングなどの要因によって失敗することもあります。

そうすると、「いつ、どのような操作をした時にスペックが失敗したのか」を調べてコードを修正する必要が出てきます。
ここでは、その問題の原因追求の手助けとなる詳細な動作ログを出力出来るようにしたいと思います。

Capybaraのエラーメッセージはそのままでも分かりやすいのですが、複雑なフォームが対象だったり、CI環境でリモート上のマシンでスペックを実行する場合などは動作ログが見えた方が良いですね。

Yahoo! JAPAN
  タイトルが`Yahoo! JAPAN`であること
  検索フォームのパーツの要素が存在すること
  ニューストピックスボックスの要素が存在すること
  主なサービスメニュー内に`ヤフオク!`が存在すること
  検索ワードを未入力で検索した時
    検索結果ページに`ウェブ検索の急上昇ワード`が表示されること (FAILED - 1)
  検索ワードに`Selenium Capybara`を入力した時
    検索結果ページの入力フィールドに検索ワードが入力されていること

Failures:

  1) Yahoo! JAPAN 検索ワードを未入力で検索した時 検索結果ページに`ウェブ検索の急上昇ワード`が表示されること
     Failure/Error: click_on('検 索')

     Capybara::ElementNotFound:
       Unable to find visible link or button "検 索" within #<Capybara::Node::Element tag="div" path="/html/body/div/div[1]/div[3]/form/fieldset/div">
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/node/finders.rb:314:in `block in synced_resolve'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/node/base.rb:85:in `synchronize'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/node/finders.rb:302:in `synced_resolve'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/node/finders.rb:37:in `find'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/node/actions.rb:25:in `click_link_or_button'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/session.rb:808:in `block (2 levels) in <class:Session>'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/dsl.rb:50:in `block (2 levels) in <module:DSL>'
     # ./spec/features/example_spec.rb:37:in `block (4 levels) in <top (required)>'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/session.rb:341:in `within'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/dsl.rb:50:in `block (2 levels) in <module:DSL>'
     # ./vendor/bundle/ruby/2.5.0/gems/capybara-2.18.0/lib/capybara/rspec/matcher_proxies.rb:14:in `within'
     # ./spec/features/example_spec.rb:35:in `block (3 levels) in <top (required)>'

Finished in 20.57 seconds (files took 0.53215 seconds to load)
6 examples, 1 failure

Failed examples:

rspec ./spec/features/example_spec.rb:34 # Yahoo! JAPAN 検索ワードを未入力で検索した時 検索結果ページに`ウェブ検索の急上昇ワード`が表示されること

EventListenerの追加

Class: Selenium::WebDriver::Support::AbstractEventListener

AbstractEventListenerクラスを継承したNavigationListenerを実装していきます。

$ touch spec/helpers/navigation_listener.rb

navigation_listener.rbでは継承元のAbstractEventListenerクラスの各メソッドをoverrideしていきます。メソッドは各イベント前後で用意されており必要なものだけ実装します。ログの出力だけでなく、例えば#before_clickメソッドで「要素をクリックする前にブラウザーをスクロールして要素を画面内に入れる」といった事前動作が必要であれば実装することも可能だと思います。

ここでは、実験も兼ねて結構細かくログを出力しています。エラー発生前は要素を見つけるために何回かリトライすることが多いため、「ログに埋もれて必要な情報が見つからない」と本末転倒にならないようにする必要があります。

追加前のコードはこちらを参照して下さい。
RspecとCapybaraを使ってE2Eテストの土台を作ってみる

spec/helpers/navigation_listener.rb
class NavigationListener < Selenium::WebDriver::Support::AbstractEventListener

  def initialize(log)
    @log = log
    @tag_name_before_click = ''
  end

  def after_find(by, what, driver)
    @log.info "次の要素が見つかりました: #{by}, #{what}"
  end

  def before_click(element, driver)
    # リンクをクリックして別のページに遷移した後、 "after_click" で
    # 前ページの要素を参照すると例外が発生するため、タグ名をインスタンス変数に保存しておく
    @tag_name_before_click = element.tag_name
    if @tag_name_before_click == 'a'
      href = element.attribute('href')
      @log.info "link to: #{href}"
    end
  end

  def after_click(element, driver)
    @log.info "次の要素をクリックしました: #{@tag_name_before_click}"
    @tag_name_before_click = ''
  end

  def after_navigate_to(url, driver)
    @log.info "次のURLへ遷移しました: #{url}"
  end

  def before_close(driver)
    @log.info "次のウィンドウ(タブ)を閉じようとしています: #{driver.window_handle if driver}"
  end

  def after_close(driver)
    @log.info 'ウィンドウ(タブ)を閉じました'
  end

  def after_quit(driver)
    @log.info 'ブラウザーを終了しました'
  end

  def before_execute_script(script, driver)
    @log.info "次のスクリプトを実行しようとしています: #{script}"
  end

  def after_execute_script(script, driver)
    @log.info 'スクリプトを実行しました'
  end

  def before_change_value_of(element, driver)
    @log.info "次の要素に関する値を変更しようとしています: #{element.tag_name if element}"
  end

  def after_change_value_of(element, driver)
    @log.info "次の要素に関する値を変更しました: #{element.tag_name if element}"
  end

end

navigation_listener.rbが実装出来たら、それをcapybara.rbで読み込んで使えるようにします。

spec/helpers/capybara.rb
# 下記の参照を追加する
require 'logger'
require_relative './navigation_listener'

# (中略)

# loggerを初期化する
  logger = Logger.new(STDOUT)
  logger.datetime_format = '%Y-%m-%d %H:%M:%S'
  logger.formatter = proc do |severity, timestamp, progname, msg|
    "\t#{timestamp}: #{msg}\n"
  end

# [listener]の引数に[NavigationListener]のインスタンスを指定する
  # ブラウザーを起動する
  Capybara::Selenium::Driver.new(
    app,
    browser: :chrome,
    options: options,
    listener: NavigationListener.new(logger))

NavigationListenerによるログの出力

NavigationListenerが使えるようになったら実行してみましょう。

$ bundle exec rspec spec/features/example_spec.rb

Yahoo! JAPAN
    2018-03-17 18:25:12 +0900: 次のURLへ遷移しました: https://www.yahoo.co.jp/
    2018-03-17 18:25:12 +0900: 次のURLへ遷移しました: about:blank
    2018-03-17 18:25:12 +0900: 次の要素が見つかりました: xpath, /html/body/*
  タイトルが`Yahoo! JAPAN`であること
    2018-03-17 18:25:14 +0900: 次のURLへ遷移しました: https://www.yahoo.co.jp/
    2018-03-17 18:25:14 +0900: 次の要素が見つかりました: css selector, #srchfield
    2018-03-17 18:25:14 +0900: 次の要素が見つかりました: css selector, input#srchtxt
    2018-03-17 18:25:14 +0900: 次の要素が見つかりました: css selector, input.srchbtn
    2018-03-17 18:25:15 +0900: 次のURLへ遷移しました: about:blank
    2018-03-17 18:25:15 +0900: 次の要素が見つかりました: xpath, /html/body/*
  検索フォームのパーツの要素が存在すること
    2018-03-17 18:25:15 +0900: 次のURLへ遷移しました: https://www.yahoo.co.jp/
    2018-03-17 18:25:15 +0900: 次の要素が見つかりました: xpath, //div[@id='topicsboxbd']
    2018-03-17 18:25:15 +0900: 次のURLへ遷移しました: about:blank
    2018-03-17 18:25:15 +0900: 次の要素が見つかりました: xpath, /html/body/*
  ニューストピックスボックスの要素が存在すること
    2018-03-17 18:25:16 +0900: 次のURLへ遷移しました: https://www.yahoo.co.jp/
    2018-03-17 18:25:16 +0900: 次の要素が見つかりました: css selector, #yahooservice
    2018-03-17 18:25:16 +0900: 次のURLへ遷移しました: about:blank
    2018-03-17 18:25:16 +0900: 次の要素が見つかりました: xpath, /html/body/*
  主なサービスメニュー内に`ヤフオク!`が存在すること
  検索ワードを未入力で検索した時
    2018-03-17 18:25:17 +0900: 次のURLへ遷移しました: https://www.yahoo.co.jp/
    2018-03-17 18:25:17 +0900: 次の要素が見つかりました: css selector, #srchbd
    2018-03-17 18:25:17 +0900: 次の要素が見つかりました: xpath, .//*[self::input | self::textarea][not(((((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'radio')) or (./@type = 'checkbox')) or (./@type = 'hidden')) or (./@type = 'file')))][((((./@id = 'srchtxt') or (./@name = 'srchtxt')) or (./@placeholder = 'srchtxt')) or (./@id = //label[(normalize-space(string(.)) = 'srchtxt')]/@for))] | .//label[(normalize-space(string(.)) = 'srchtxt')]//.//*[self::input | self::textarea][not(((((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'radio')) or (./@type = 'checkbox')) or (./@type = 'hidden')) or (./@type = 'file')))]
    2018-03-17 18:25:17 +0900: 次の要素に関する値を変更しようとしています: input
    2018-03-17 18:25:17 +0900: 次の要素に関する値を変更しました: input
    2018-03-17 18:25:17 +0900: 次の要素が見つかりました: xpath, .//a[./@href][((((./@id = '検索') or (normalize-space(string(.)) = '検索')) or (./@title = '検索')) or .//img[(./@alt = '検索')])] | .//input[((((./@type = 'submit') or (./@type = 'reset')) or (./@type = 'image')) or (./@type = 'button'))][((./@id = '検索') or ((./@value = '検索') or (./@title = '検索')))] | .//input[(./@type = 'image')][(./@alt = '検索')] | .//button[(((./@id = '検索') or ((./@value = '検索') or (./@title = '検索'))) or ((normalize-space(string(.)) = '検索') or .//img[(./@alt = '検索')]))] | .//input[(./@type = 'image')][(./@alt = '検索')]
    2018-03-17 18:25:18 +0900: 次の要素をクリックしました: input
    2018-03-17 18:25:18 +0900: 次の要素が見つかりました: xpath, .//*[self::input | self::textarea | self::select][not((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'hidden')))][((((./@id = 'yschsp') or (./@name = 'yschsp')) or (./@placeholder = 'yschsp')) or (./@id = //label[contains(normalize-space(string(.)), 'yschsp')]/@for))] | .//label[contains(normalize-space(string(.)), 'yschsp')]//.//*[self::input | self::textarea | self::select][not((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'hidden')))]
    2018-03-17 18:25:18 +0900: 次の要素が見つかりました: css selector, h2
    2018-03-17 18:25:18 +0900: 次のURLへ遷移しました: about:blank
    2018-03-17 18:25:18 +0900: 次の要素が見つかりました: xpath, /html/body/*
    検索結果ページに`ウェブ検索の急上昇ワード`が表示されること
  検索ワードに`Selenium Capybara`を入力した時
    2018-03-17 18:25:19 +0900: 次のURLへ遷移しました: https://www.yahoo.co.jp/
    2018-03-17 18:25:19 +0900: 次の要素が見つかりました: css selector, #srchbd
    2018-03-17 18:25:19 +0900: 次の要素が見つかりました: xpath, .//*[self::input | self::textarea][not(((((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'radio')) or (./@type = 'checkbox')) or (./@type = 'hidden')) or (./@type = 'file')))][((((./@id = 'srchtxt') or (./@name = 'srchtxt')) or (./@placeholder = 'srchtxt')) or (./@id = //label[(normalize-space(string(.)) = 'srchtxt')]/@for))] | .//label[(normalize-space(string(.)) = 'srchtxt')]//.//*[self::input | self::textarea][not(((((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'radio')) or (./@type = 'checkbox')) or (./@type = 'hidden')) or (./@type = 'file')))]
    2018-03-17 18:25:19 +0900: 次のスクリプトを実行しようとしています: arguments[0].value = ''
    2018-03-17 18:25:19 +0900: スクリプトを実行しました
    2018-03-17 18:25:19 +0900: 次の要素に関する値を変更しようとしています: input
    2018-03-17 18:25:19 +0900: 次の要素に関する値を変更しました: input
    2018-03-17 18:25:19 +0900: 次の要素が見つかりました: xpath, .//a[./@href][((((./@id = '検索') or (normalize-space(string(.)) = '検索')) or (./@title = '検索')) or .//img[(./@alt = '検索')])] | .//input[((((./@type = 'submit') or (./@type = 'reset')) or (./@type = 'image')) or (./@type = 'button'))][((./@id = '検索') or ((./@value = '検索') or (./@title = '検索')))] | .//input[(./@type = 'image')][(./@alt = '検索')] | .//button[(((./@id = '検索') or ((./@value = '検索') or (./@title = '検索'))) or ((normalize-space(string(.)) = '検索') or .//img[(./@alt = '検索')]))] | .//input[(./@type = 'image')][(./@alt = '検索')]
    2018-03-17 18:25:20 +0900: 次の要素をクリックしました: input
    2018-03-17 18:25:20 +0900: 次の要素が見つかりました: xpath, .//*[self::input | self::textarea | self::select][not((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'hidden')))][((((./@id = 'yschsp') or (./@name = 'yschsp')) or (./@placeholder = 'yschsp')) or (./@id = //label[contains(normalize-space(string(.)), 'yschsp')]/@for))] | .//label[contains(normalize-space(string(.)), 'yschsp')]//.//*[self::input | self::textarea | self::select][not((((./@type = 'submit') or (./@type = 'image')) or (./@type = 'hidden')))]
    2018-03-17 18:25:20 +0900: 次のURLへ遷移しました: about:blank
    2018-03-17 18:25:20 +0900: 次の要素が見つかりました: xpath, /html/body/*
    検索結果ページの入力フィールドに検索ワードが入力されていること

Finished in 13.76 seconds (files took 0.55063 seconds to load)
6 examples, 0 failures

    2018-03-17 18:25:20 +0900: ブラウザーを終了しました

…selectorの指定の仕方にもよると思いますが、Capybaraが操作対象の要素を見つける時は柔軟な(複雑な)xpathの指定をしていたりするんですね。

まとめ

ざっとNavigationListenerを実装してみました。
CI環境でリモート上のマシンでスペックを実行する場合などはブラウザーの画面を見られないこともあると思いますので、このような感じで動作ログが追えるようになっていると良いかも知れません。

Sign up for free and join this conversation.
Sign Up
If you already have a Qiita account log in.