Rails 测试失败请求未在 60 秒内完成

Question

在将 rails 从 4.2 升级到 5.2 后，我的测试在开发服务器中工作时卡在请求上，我在运行测试套件时遇到了以下故障。

Failures:

  1) cold end overview shows cold end stats
     Failure/Error: example.run

     RuntimeError:
       Requests did not finish in 60 seconds
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara/server.rb:94:in `rescue in wait_for_pending_requests'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara/server.rb:91:in `wait_for_pending_requests'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara/session.rb:130:in `reset!'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara.rb:314:in `block in reset_sessions!'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara.rb:314:in `reverse_each'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara.rb:314:in `reset_sessions!'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara/rspec.rb:22:in `block (2 levels) in <top (required)>'
     # ./spec/spec_helper.rb:43:in `block (3 levels) in <top (required)>'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/database_cleaner-1.6.2/lib/database_cleaner/generic/base.rb:16:in `cleaning'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/database_cleaner-1.6.2/lib/database_cleaner/base.rb:98:in `cleaning'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/database_cleaner-1.6.2/lib/database_cleaner/configuration.rb:86:in `block (2 levels) in cleaning'
     # /home/asnad/.rvm/gems/ruby-2.5.0/gems/database_cleaner-1.6.2/lib/database_cleaner/configuration.rb:87:in `cleaning'
     # ./spec/spec_helper.rb:37:in `block (2 levels) in <top (required)>'
     # ------------------
     # --- Caused by: ---
     # Timeout::Error:
     #   execution expired
     #   /home/asnad/.rvm/gems/ruby-2.5.0/gems/capybara-2.18.0/lib/capybara/server.rb:92:in `sleep'

Top 1 slowest examples (62.59 seconds, 97.0% of total time):
  cold end overview shows cold end stats
    62.59 seconds ./spec/features/cold_end_overview_spec.rb:13

Finished in 1 minute 4.51 seconds (files took 4.15 seconds to load)
1 example, 1 failure

我的 spec_helper.rb 有配置

RSpec.configure do |config|
  config.include FactoryBot::Syntax::Methods

  config.around(:each) do |example|
    DatabaseCleaner[:active_record].clean_with(:truncation)

    DatabaseCleaner.cleaning do
      if example.metadata.key?(:js) || example.metadata[:type] == :feature
        # VCR.configure { |c| c.ignore_localhost = true }
        WebMock.allow_net_connect!
        VCR.turn_off!
        VCR.eject_cassette
        example.run
      else
        # WebMock.disable_net_connect!
        VCR.turn_on!
        cassette_name = example.metadata[:full_description]
                               .split(/\s+/, 2)
                               .join('/')
                               .underscore.gsub(/[^\w\/]+/, '_')
        # VCR.configure { |c| c.ignore_localhost = false }
        VCR.use_cassette(cassette_name) { example.run }
        VCR.turn_off!
        WebMock.allow_net_connect!
      end
    end
  end

  config.expect_with :rspec do |expectations|
    expectations.include_chain_clauses_in_custom_matcher_descriptions = true
  end

  config.mock_with :rspec do |mocks|
    mocks.verify_partial_doubles = true
  end

  config.filter_run :focus
  config.run_all_when_everything_filtered = true

  config.example_status_persistence_file_path = "spec/examples.txt"

  if config.files_to_run.one?
    config.default_formatter = 'doc'
  end

  # Print the 10 slowest examples and example groups at the
  # end of the spec run, to help surface which specs are running
  # particularly slow.
  config.profile_examples = 10

  # Run specs in random order to surface order dependencies. If you find an
  # order dependency and want to debug it, you can fix the order by providing
  # the seed, which is printed after each run.
  #     --seed 1234
  config.order = :random

  # Seed global randomization in this process using the `--seed` CLI option.
  # Setting this allows you to use `--seed` to deterministically reproduce
  # test failures related to randomization by passing the same `--seed` value
  # as the one that triggered the failure.
  Kernel.srand config.seed
end

# Selenium::WebDriver.logger.level = :debug
# Selenium::WebDriver.logger.output = 'selenium.log'
Capybara.register_driver :selenium_chrome_headless do |app|
  capabilities = Selenium::WebDriver::Remote::Capabilities.chrome(chromeOptions: { args: %w[headless no-sandbox disable-dev-shm-usage disable-gpu window-size=1200,1500] }, loggingPrefs: { browser: 'ALL' })
  Capybara::Selenium::Driver.new(app, browser: :chrome, desired_capabilities: capabilities)
end

Chromedriver.set_version '2.39'

Capybara.javascript_driver = :selenium_chrome_headless
Capybara::Screenshot.prune_strategy = :keep_last_run

在我的规范中，sign_in current_user 行实际上花费了太多时间，它重定向到一个页面并且在开发环境中工作时甚至很长时间都没有得到响应。 如果您需要其他任何内容，可能是什么原因，请发表评论。

Answer 1

从 4.2 升级到 5.1 和现在的 5.2 后，我自己刚到这里，我在测试中看到了同样的情况，当我在请求中用 binding.pry 冻结了一个测试时，我得到了消息Requests did not finish in 60 seconds。多么棒的故事，跳到最后看 tl;dr（我可能已经想通了。）

现在我已经逐步升级了所有的宝石，这样我就可以保留一分为二的能力，并观察像这样的有趣变化的来源。在从 chromedriver-helper 转换后，我才注意到这个新的 60 秒超时，它报告说它已被弃用到正在接管的新 webdrivers gem，但这似乎与我在 webdrivers 中搜索任何超时或 60 秒值无关，并且只找到了对不相关的 Pull Request #60 的引用（修复了 Issue #59）。

我检查了我的 gem 源目录中的这条消息，Requests did not finish in 60 seconds，发现它实际上不是 Capybara 的旧版本，而是从至少可以追溯到 3.9.0 的版本中提出的，并且在lib/capybara/server.rb 中的最新版本 3.24.0。

这里使用的对象是一个 Timer，你可以在这里找到它的接口，在 helper 中：

https://github.com/teamcapybara/capybara/blob/320ee96bb8f63ac9055f7522961a1e1cf8078a8a/lib/capybara/helpers.rb#L79

此特定消息是由方法wait_for_pending_requests 引发的，该方法将硬60 传递给:expire_in 命名参数，然后发送服务器线程中遇到的任何错误。这意味着时间是不可配置的，大概 60 秒是等待正在进行的 Web 请求完成的合理时间长度，尽管这对我的测试来说有点不方便。

这个方法只在一个地方被调用，reset!，你可以在capybara/session.rb找到它的定义：https://github.com/teamcapybara/capybara/blob/320ee96bb8f63ac9055f7522961a1e1cf8078a8a/lib/capybara/session.rb#L126

重置！方法是一个有趣的方法，它附带一些关于如何使用它的文档。 @server&.wait_for_pending_requests 看起来它可能会调用 wait_for_pending_requests 如果它在请求中有一个活动的服务器线程，然后 raise_server_error！仅当 @server&.error 为真时才会发生类似的行为。

现在我们找到了重置！带有两个别名，每当 Capybara 调用 cleanup! 或 reset_session! 时都会收到此消息 reset!。至此我们大概可以理解发生了什么，但是当我使用 chromedriver-helper 和 selenium 测试好几年的时候，这仍然有点神秘，但从来没有记得以前看到过这个 60 秒的超时。我很犹豫是否将矛头指向 webdriver，但对于为什么这个超时是新的，我没有任何其他答案。除了升级到这个 gem 和任何其他 gem，以及清除弃用警告之外，我还没有做任何可以解释它的事情。

在 Rails 5.1+ 中，capybara 调用 reset 似乎是可能的！更多，也许比测试示例之间更多。特别是当您阅读该方法的文档并考虑现在的单页焦点时，并考虑reset! 文档告诉您它不会重置的所有事情，清除浏览器缓存/HTML 5本地存储/IndexedDB/Web SQL 数据库/等——或者我正在想象它，​​这并不新鲜。但我想象有很多方法可以调用重置！而不会出现在此超时代码中，这可能取决于驱动程序。

您在升级 Rails 时是否已更改为 webdrivers gem？

编辑：我恢复到 chromedriver-helper 只是为了确定，但事实并非如此。实际发生的情况是我的测试在一个线程中失败，但服务器打开了binding.pry 会话。 Capybara 已进入下一个测试，因此要获得一个名为reset! 的新会话，但 60 秒后我仍处于我的 pry 会话中，服务器仍未准备好服务根请求。我感觉 capybara 的线程行为已经改变，在我的记忆中，在服务器请求期间打开的 pry session 会阻止测试失败，直到它返回。但这显然不再发生了。

你是怎么到这里的？不幸的是，我不知道，但这是对收到该消息时发生的情况的公平描述。