SlowFinder errors obscure failing assertion error messages

[zmoazeni]

Hi there. I really appreciate the effort you put into debugging and sharing these optimizations. My team enabled the gem for a week and then had to disable it (with an optional enable).

The gem works great. Perhaps too good :smile:. The problem was the gem's error message got in our way while we were debugging a failing test. The SlowFinderError would obscure the reason why a test failed. Here is a concrete example so you can see it for yourself:

## Start a vanilla rails codebase

###
### in the Gemfile:
###
group :development, :test do
  gem 'capybara'
  gem 'poltergeist'
  gem 'capybara-slow_finder_errors', require: false
end

###
### in test/integration/red_green_test.rb
###
require 'test_helper'

# I'm including a bunch of this junk to keep the example as self contained as possible
require 'capybara/rails'
require "capybara/poltergeist"

if ENV['RAISE_SLOW_INTEGRATION_ASSERTIONS']
  require 'capybara/slow_finder_errors'
end

Rails.application.routes.eval_block(->{ get 'test/red_green', :to => 'red_green#index'})

class RedGreenController < ApplicationController
  def index
    render text: "<div id='foo'>hello world</div>"
  end
end

class CurrentRedGeenTest < ActionDispatch::IntegrationTest
  include Capybara::DSL

  setup do
    Capybara.current_driver = :poltergeist
  end

  test 'currently red/greening this test' do
    visit '/test/red_green'
    assert_selector '#foo'
    assert_selector '#bar' # I know this is failing, currently red/green'ing it or I broke it with some other change
    assert_text 'asdlkfj' # This will also fail
  end
end

Here is the output with and without slow_finder_errors:

∴ RAISE_SLOW_INTEGRATION_ASSERTIONS=true be ruby -Itest test/integration/red_green_test.rb
Run options: --seed 2280

# Running:

E

Finished in 3.084543s, 0.3242 runs/s, 0.0000 assertions/s.

  1) Error:
CurrentRedGeenTest#test_currently_red/greening_this_test:
Capybara::SlowFinderError: Timeout reached while running a *waiting* Capybara finder...perhaps you wanted to return immediately? Use a non-waiting Capybara finder. More info: http://blog.codeship.com/faster-rails-tests?utm_source=gem_exception
    test/integration/red_green_test.rb:27:in `block in <class:CurrentRedGeenTest>'

1 runs, 0 assertions, 0 failures, 1 errors, 0 skips

∴ be ruby -Itest test/integration/red_green_test.rb
Run options: --seed 39879

# Running:

E

Finished in 3.599927s, 0.2778 runs/s, 0.0000 assertions/s.

  1) Error:
CurrentRedGeenTest#test_currently_red/greening_this_test:
Capybara::ExpectationNotMet: expected to find css "#bar" but there were no matches
    test/integration/red_green_test.rb:27:in `block in <class:CurrentRedGeenTest>'

1 runs, 0 assertions, 0 failures, 1 errors, 0 skips

---

As you can see, slow_finder_errors is doing it's job, but it's also obscuring the real reason for the test failure. It gives you a line number, which is nice, but expected to find css "#bar" but there were no matches is very helpful.

Now this will only happen with capybara drivers that wait, like poltergeist or capybara-webkit. The default rack_test will fail immediately and consequently not trigger the SlowFinderError.

My team resorted to having slow_finder_errors opt-in, so that we'd run it once we know we have a green suite as a separate optimization step. We can keep doing that, but it's a bummer to not just have this run all the time.

I toyed with just manually printing the warning with the backtrace instead of raising an error:

# ...
rescue Capybara::ElementNotFound => e
  seconds = args.first || Capybara.default_wait_time
  if Time.now-start_time > seconds
    # raise SlowFinderError, "Timeout reached while running a *waiting* Capybara finder...perhaps you wanted to return immediately? Use a non-waiting Capybara finder. More info: http://blog.codeship.com/faster-rails-tests?utm_source=gem_exception"
    puts "SlowFinder: Timeout reached while running a *waiting* Capybara finder...perhaps you wanted to return immediately? Use a non-waiting Capybara finder. More info: http://blog.codeship.com/faster-rails-tests?utm_source=gem_exception"
    puts e.backtrace
  end
  raise
end
# ...

Which changes the semantics so that it's more informative than fail-fast:

∴ RAISE_SLOW_INTEGRATION_ASSERTIONS=true be ruby -Itest test/integration/red_green_test.rb
Run options: --seed 28231

# Running:

SlowFinder: Timeout reached while running a *waiting* Capybara finder...perhaps you wanted to return immediately? Use a non-waiting Capybara finder. More info: http://blog.codeship.com/faster-rails-tests?utm_source=gem_exception
/Users/zmoazeni/.gem/ruby/2.1.5/gems/capybara-2.4.4/lib/capybara/node/matchers.rb:97:in `block in assert_selector'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/capybara-2.4.4/lib/capybara/node/base.rb:84:in `synchronize'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/capybara-slow_finder_errors-0.1.1/lib/capybara/slow_finder_errors.rb:9:in `synchronize_with_timeout_error'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/capybara-2.4.4/lib/capybara/node/matchers.rb:93:in `assert_selector'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/capybara-2.4.4/lib/capybara/session.rb:676:in `block (2 levels) in <class:Session>'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/capybara-2.4.4/lib/capybara/dsl.rb:51:in `block (2 levels) in <module:DSL>'
/Users/zmoazeni/projects/tmp/test_app/test/integration/red_green_test.rb:27:in `block in <class:CurrentRedGeenTest>'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest/test.rb:108:in `block (3 levels) in run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest/test.rb:206:in `capture_exceptions'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest/test.rb:105:in `block (2 levels) in run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest/test.rb:258:in `time_it'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest/test.rb:104:in `block in run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:321:in `on_signal'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest/test.rb:278:in `with_info_handler'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest/test.rb:103:in `run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:768:in `run_one_method'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:295:in `run_one_method'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:289:in `block (2 levels) in run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:288:in `each'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:288:in `block in run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:321:in `on_signal'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:308:in `with_info_handler'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:287:in `run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:150:in `block in __run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:150:in `map'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:150:in `__run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:127:in `run'
/Users/zmoazeni/.gem/ruby/2.1.5/gems/minitest-5.5.0/lib/minitest.rb:56:in `block in autorun'
E

Finished in 3.610658s, 0.2770 runs/s, 0.0000 assertions/s.

  1) Error:
CurrentRedGeenTest#test_currently_red/greening_this_test:
Capybara::ExpectationNotMet: expected to find css "#bar" but there were no matches
    test/integration/red_green_test.rb:27:in `block in <class:CurrentRedGeenTest>'

1 runs, 0 assertions, 0 failures, 1 errors, 0 skips

Any thoughts? Should we continue to make this opt-in? Would you welcome a PR to change the gem to output warning information instead of failing fast with an error? Is there a third option I'm missing altogether?

Thanks for your consideration and your hard work!

[ngauthier]

Hey Zach,

Thanks for the ideas! I also see you joined the fun on the capybara issue :smile:.

This gem is a quick packaging of the audit script I used in conjunction with the blog post on Codeship's blog. I thought it would be nice to be able to include it when you want to do an audit. I recognized the same problem you did: it doesn't make sense while you're doing TDD.

IMO these are our options:

1. Leave it as is, and people have to toggle it on and off (simply with require: false in Gemfile) for development. Or just include weekly or monthly as an audit
2. Switch the exception to a warning. Downside here is the loss of the backtrace (which is really important), but we could do something fun like raise an exception then catch it and print the trace and a warning and continue
3. At Codeship, we have an environment variable on CI that is CI=true. So, we can keep the gem all the time and then require: false in Gemfile but require 'capybara-slow_finder_errors' if ENV['CI'] in our spec_helper. We could document this pattern, but I know it won't work for all teams.

[zmoazeni]

Right on. For 2) the code snippet above includes the backtrace without worrying about an explicit raise/catch. But it does include a slew of other backtrace junk along with it.

I considered 3) but thought it would make legitimate CI failures hard to read. (We use CircleCI but they have offer the same variable).

I'm fine with sticking with 1). I just wanted to bring it up in case this was news to you. I can submit a PR to add a blurb to the readme if you want to keep this as a separate optimization step.

The capybara codebase is rather hard for me to grok, but I have a suspicion doing anything more clever than 2) will cause this simple monkey patch to get more complicated and harder to maintain.

[ngauthier]

Ah sorry missed your backtrace stuff in 2. Yeah my intention is for this to be a canary, nothing more. I think just plugging it in for auditing is the best. If someone wants to use it in a particular way they should be able to code it themselves (like 3).

Ideally the best solution would be to change capybara's behavior to consider a timeout a failure, but that's not gonna happen.

One thing we could do is wrap the SlowFinder exception around the element not found exception so that while developing you get to see both.

[zmoazeni]

Ideally the best solution would be to change capybara's behavior to consider a timeout a failure, but that's not gonna happen.

Totally agree.

[dankohn]

@ngauthier I'll be going with your option 3 above, but it would be very helpful to add that list to the Readme.

[ivanoblomov]

@ngauthier Can you clarify the require syntax for option 3? Requiring slow-finder this way...

require 'capybara-slow_finder_errors' if ENV['CI'].present?

...yields a load error:

~/.rvm/gems/ruby-2.1.5/gems/activesupport-4.1.9/lib/active_support/dependencies.rb:247:in `require': cannot load such file -- capybara-slow_finder_errors (LoadError)

[ngauthier]

@ivanoblomov I'm guessing you still need to add it to your Gemfile?

[ivanoblomov]

@ngauthier we added it as suggested:

group :test do gem 'capybara-slow_finder_errors', '0.1.2', require: false .. end

Not sure why it doesn't resolve.

[ngauthier]

ah, sorry the require line is capybara/slow_finder_errors.

[ivanoblomov]

Thanks @ngauthier, that did the trick.