Intermittent allow_unknown_url failures

[gardha]

Hello,

I have the following setup (latest versions for all gems):
capybara (2.13.0)
capybara-webkit (1.14.0)
database_cleaner (1.5.3)
Qt 5.5
MacOS Sierra

spec_helper.rb

Capybara::Webkit.configure do |config|
  config.allow_unknown_urls
end

I am intermittently getting errors similar to the following when I run my tests

unknown URL: http://***/assets/***.png music! <==  > 198/287 68.98%  ETA: 00:08:12 - Time: 00:18:11
To block requests to unknown URLs:
  Capybara::Webkit.configure do |config|
    config.block_unknown_urls
  end
To allow just this URL:
  Capybara::Webkit.configure do |config|
    config.allow_url("***/assets/***.png")
  end
To allow requests to URLs from this host:
  Capybara::Webkit.configure do |config|
    config.allow_url("***")
  end
Request to unknown URL: http://www.google-analytics.com/analytics.js

To block requests to unknown URLs:
  Capybara::Webkit.configure do |config|
    config.block_unknown_urls
  end
To allow just this URL:
  Capybara::Webkit.configure do |config|
    config.allow_url("http://www.google-analytics.com/analytics.js")
  end
To allow requests to URLs from this host:
  Capybara::Webkit.configure do |config|
    config.allow_url("www.google-analytics.com")
  end

Please advise, been trying to sort this out for weeks!

[twalpole]

Do you have any other Webkit configuration blocks? Do you have any tests that modify the allow/block rules?

[gardha]

I am not modifying the rules in any of the specs, here is my complete spec_helper.rb

require 'simplecov'
require 'simplecov-json'
require 'simplecov-rcov'

SimpleCov.formatters = [
  SimpleCov::Formatter::HTMLFormatter,
  SimpleCov::Formatter::JSONFormatter,
  SimpleCov::Formatter::RcovFormatter
]

SimpleCov.start do
  add_filter '/spec/'
  add_filter '/config/'
  add_filter '/vendor/'

  add_group 'Controllers', 'app/controllers'
  add_group 'Models', 'app/models'
  add_group 'Helpers', 'app/helpers'
  add_group 'Mailers', 'app/mailers'
  add_group 'Forms', 'app/forms'
  add_group 'Listeners', 'app/listeners'
  add_group 'Decorators', 'app/decorators'
  add_group 'Validators', 'app/validators'
  add_group 'Uploaders', 'app/uploaders'
end if ENV['COVERAGE'] == 'true'

ENV['RAILS_ENV'] ||= 'test'
require File.expand_path('../../config/environment', __FILE__)
require 'rspec/rails'
require 'capybara/email/rspec'
require 'sunspot_test/rspec'
require 'vcr'
require 'webmock/rspec'
require 'database_cleaner'

Dir[Rails.root.join('spec/support/**/*.rb')].each { |f| require f }

ActiveRecord::Migration.check_pending! if defined?(ActiveRecord::Migration)

Capybara::Webkit.configure(&:allow_unknown_urls)

RSpec.configure do |config|
  config.fuubar_progress_bar_options = { :format => '#33 Termites eat through wood two times faster when listening to rock music! <%B> %c/%C %P%% %E - %a' }

  config.infer_spec_type_from_file_location!
  Capybara.javascript_driver = :webkit
  Capybara.always_include_port = true
  Capybara.default_max_wait_time = 15
  ENV['no_proxy'] = "127.0.0.1"

  config.use_transactional_fixtures = false

  config.infer_base_class_for_anonymous_controllers = true

  config.order = 'random'

  config.expect_with :rspec do |c|
    c.syntax = :expect
  end

  # Retry failed tests - stolen from rspec-retry gem
  fetch_current_example = RSpec.respond_to?(:current_example) ? proc { RSpec.current_example } : proc(&:example)

  config.around(:each) do |ex|
    example = fetch_current_example.call(self)
    try_count = ENV['RSPEC_TRY_COUNT'].nil? ? 1 : ENV['RSPEC_TRY_COUNT'].to_i

    try_count.times do |i|
      if i > 0
        message = "Retry ##{i} #{example.location}"
        message = "\n" + message if i == 1
        RSpec.configuration.reporter.message(message)
      end
      example.clear_exception
      ex.run

      break if example.exception.nil?

      clear_lets
      sleep i
    end
  end

  # DBCleaner Setup
  config.before :suite do
    DatabaseCleaner.clean_with :truncation
  end

  config.before :each do
    DatabaseCleaner.strategy = :transaction
  end

  config.before :each, :js => true do
    DatabaseCleaner.strategy = :truncation
  end

  config.before :each do
    DatabaseCleaner.start
  end

  config.after :each do
    DatabaseCleaner.clean
  end

  config.include FactoryGirl::Syntax::Methods
  config.include Features::FeatureHelpers, :type => :feature
  config.extend Features::FeatureClassHelpers, :type => :feature
  config.include Features::Pages, :type => :feature
  config.include Devise::TestHelpers, :type => :controller
  config.include ControllerClassHelpers, :type => :controller
  config.include WaitForAjax, :type => :feature
  config.extend WithModel, :type => :concern
  config.include SpecHelpers

  config.include SunspotMatchers

  # Sunspot stubing
  # host = %r{https?://([^/]*)(?=/|$).*}.match(Sunspot.config.solr.url)[1]

  # WebMock.disable_net_connect!(:allow => host, :allow_localhost => true)

  config.before :each do
    allow_any_instance_of(Redis).to receive(:connected?) { false }
  end

  config.before(:each, :type => :feature) do
    SunspotTest.unstub
    SunspotTest.setup_solr
    Sunspot.remove_all!
    Sunspot.commit
  end

  config.before(:each, :search => true) do
    Sunspot.remove_all!
    Sunspot.commit
  end

  config.after(:each, :type => :feature) do
    SunspotTest.stub
  end

  # delete any documents cached by carrierwave
  config.after(:all) do
    path = Rails.root.join('spec', 'support', 'tmp', ENV['TEST_ENV_NUMBER'] || '', 'uploads').to_s
    FileUtils.rm_rf(Dir[path])
  end

  # VCR setup
  VCR.configure do |c|
    c.cassette_library_dir = 'spec/cassettes'
    c.hook_into :webmock
    c.allow_http_connections_when_no_cassette = true

    # any document coming from amazon
    c.register_request_matcher :amazon do |request_1, _request_2|
      request_1.uri.starts_with?('https://smp-dev-docs.s3.amazonaws.com/uploads/document')
    end

    c.filter_sensitive_data('<CLIENTID>') { XG_CONFIG['xg_client_id'] }
    c.filter_sensitive_data('<USERID>') { XG_CONFIG['xg_user_id'] }
    c.filter_sensitive_data('<PASSWORD>') { XG_CONFIG['xg_user_password'] }
  end
end

# override the cache dir used by Carrierwave
if defined?(CarrierWave)
  CarrierWave::Uploader::Base.descendants.each do |klass|
    next if klass.anonymous?
    klass.class_eval do
      def cache_dir
        Rails.root.join('spec', 'support', 'tmp', ENV['TEST_ENV_NUMBER'] || '', 'uploads').to_s
      end
    end
  end
end

[twalpole]

It probably won't fix this issue, but for test stability you definitely want

 config.append_after :each do     # just 'after' can mean the clean occurs while requests are occurring
  DatabaseCleaner.clean
 end

[twalpole]

Is this still happening, and do you have a minimal way to replicate?

[AlanFoster]

@twalpole This is still happening for me in 1.14.0 Not sure how to replicate consistently though, other than it's definitely an intermittent that we've seen a lot in the past. I'll try bumping to 1.15.0 and keep an eye on it

Edit: I am able to to replicate with Capybara-Webkit 1.15.0. In my experience the error generally comes up more often when capybara-webkit is having a 'bad time'

[twalpole]

@AlanFoster Sorry, but without a repeatable way to replicate this (code, or at the very least a debug log) there is nothing we can really do.

[AlanFoster]

@twalpole Replicating is possible, but it's unfortunately not 100% consistent. I'll run with config.debug = true a few times and see if anything comes up.

[twalpole]

@AlanFoster turn on debug mode - https://github.com/thoughtbot/capybara-webkit#configuration - it should output a bunch of stuff to the console

[twalpole]

Looking through the code there's a possible way this could happen if you are using some kind of test retry on failure implementation. If you do have test retry going on, a debug log would be great to confirm it's what is actually happening.

[AlanFoster]

@twalpole This happens often enough that it's an issue, but not consistently enough for me to replicate. For instance, I've never been able to replicate with config.debug=true, it's a real heisenbug. There's also no retry functionality in place with this set up.

On CI test runs I'll see something similar to:

My Test
  Scenario 1 (FAILED - 1)
  Scenario 2
Request to unknown URL: https://fonts.googleapis.com/css?family=Open+Sans:400,300,600,700%7CRoboto+Slab:400,100,300
To block requests to unknown URLs:
  Capybara::Webkit.configure do |config|
    config.block_unknown_urls
  end
To allow just this URL:
  Capybara::Webkit.configure do |config|
    config.allow_url("https://fonts.googleapis.com/css?family=Open+Sans:400,300,600,700%7CRoboto+Slab:400,100,300")
  end
To allow requests to URLs from this host:
  Capybara::Webkit.configure do |config|
    config.allow_url("fonts.googleapis.com")
  end

And then overall RSpec shows Scenario 1 failed with the following:

     Capybara::Webkit::CrashError:
       The webkit_server process crashed!

         Connection reset by peer

       This is a bug in capybara-webkit. For help with this crash, please visit:

       https://github.com/thoughtbot/capybara-webkit/wiki/Reporting-Crashes
     # /usr/local/bundle/gems/capybara-webkit-1.14.0/lib/capybara/webkit/browser.rb:227:in `rescue in command'
     # /usr/local/bundle/gems/capybara-webkit-1.14.0/lib/capybara/webkit/browser.rb:215:in `command'
     # /usr/local/bundle/gems/capybara-webkit-1.14.0/lib/capybara/webkit/browser.rb:41:in `reset!'
     # /usr/local/bundle/gems/capybara-webkit-1.14.0/lib/capybara/webkit/driver.rb:285:in `reset!'
     # /usr/local/bundle/gems/capybara-2.13.0/lib/capybara/session.rb:112:in `reset!'
     # /usr/local/bundle/gems/capybara-2.13.0/lib/capybara.rb:336:in `block in reset_sessions!'
     # /usr/local/bundle/gems/capybara-2.13.0/lib/capybara.rb:336:in `reverse_each'
     # /usr/local/bundle/gems/capybara-2.13.0/lib/capybara.rb:336:in `reset_sessions!'
     # /usr/local/bundle/gems/capybara-2.13.0/lib/capybara/rspec.rb:21:in `block (2 levels) in <top (required)>'
     # ./spec/ui_spec_helper.rb:60:in `block (2 levels) in <top (required)>'
     # ------------------
     # --- Caused by: ---
     # Errno::ECONNRESET:
     #   Connection reset by peer
     #   <internal:prelude>:78:in `__read_nonblock'

I'm not sure if the real problem is Capybara Webkit crashing, and the unknown URL log output is just a side effect of that or not. i.e. I'm not sure if the block_unknown_urls advice is just printed in the wrong order due to a race condition, or if it's actually the next test causing the issue after webkit has crashed on the previous scenario.

[twalpole]

@AlanFoster Ok -- so the code path that I see which would allow for this is that when a crash of the capybara-webkit server happens, it prints out the "Capybara::Webkit::CrashError ..." message and starts up a new server instance. If Driver#reset! is not called before that server is used then the black/whitelists aren't set. Since Driver#reset! should be called after every test/scenario a failure in one test shouldn't cause this in the next. unless someone implemented retry logic and didn't call Driver#reset! before retrying. In your case, however, it appears the server crash may actually be happening during a reset! call which is interesting and could lead to the lists not being reset for the next test. It would be good to figure out why it's crashing the server, but beyond that we may need to figure out how to reset immediately after starting a new server.

[twalpole]

@AlanFoster Can you try the reset_crash branch and see if it makes a difference?

[twalpole]

@AlanFoster Does the thumbs up mean the reset_crash branch did make a difference to the behavior? Or did you not get a chance to try it yet?

[gardha]

If so can we merge this fix?

[twalpole]

@gardha Does it make a difference for you?

[gardha]

I have not tried, but I can try shortly

[AlanFoster]

Thanks @twalpole I'm running with this branch now. I'll post an update after it's been running for a few days :) I've been finding lots of unexpected edge cases, similar to the database cleaner you posted above, and it's taken me a while to fix those intermittents before moving on to this particular issue :)

If I understand correctly this won't fix the underlying issue though, it will just attempt to clean up correctly in a crashing scenario?

[twalpole]

@AlanFoster Correct -- it won't fix the underlying issue of crashes occurring, it should just prevent a crash during reset! resulting in the black/whitelists not getting set for the next test.

[AlanFoster]

@twalpole Confirming that I have seen this again with the custom branch:

Request to unknown URL: https://fonts.googleapis.com/css?family=Open+Sans:400,300,600,700%7CRoboto+Slab:400,100,300
To block requests to unknown URLs:
  Capybara::Webkit.configure do |config|
    config.block_unknown_urls
  end
To allow just this URL:
  Capybara::Webkit.configure do |config|
    config.allow_url("https://fonts.googleapis.com/css?family=Open+Sans:400,300,600,700%7CRoboto+Slab:400,100,300")
  end
...

Although in this scenario I can see the above webkit logs, I can also see that poltergeist actually crashed previously too - would this have any knock on impact on capybara webkit? For context we run both capybara webkit and poltergeist together, as some feature tests consistently crash with capybara webkit that actually consistently pass on poltergeist, and vice versa

[twalpole]

@AlanFoster When this occurs is the previous test crashing in the reset! method? Do you have a stacktrace for it? A Poltergeist session shouldn't have any effect on a capybara-webkit session.