1

Some of my feature specs are failing intermittently. Our specs are setting the base-line to be in the past. I have found the following:

  • Error thrown is:

UncaughtThrowError (uncaught throw :warden):

[#B3FBC85E07A6] devise (4.3.0) lib/devise/hooks/timeoutable.rb:26:in 'throw'

[#B3FBC85E07A6] devise (4.3.0) lib/devise/hooks/timeoutable.rb:26:in 'block in '

[#B3FBC85E07A6] warden (1.2.7) lib/warden/hooks.rb:15:in 'block in _run_callbacks'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/hooks.rb:10:in 'each'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/hooks.rb:10:in '_run_callbacks'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/manager.rb:52:in '_run_callbacks'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/proxy.rb:180:in 'set_user'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/test/helpers.rb:21:in 'block in login_as'

[#B3FBC85E07A6] warden (1.2.7) lib/warden.rb:40:in 'block in test_mode!'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/hooks.rb:15:in 'block in _run_callbacks'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/hooks.rb:10:in 'each'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/hooks.rb:10:in '_run_callbacks'

[#B3FBC85E07A6] warden (1.2.7) lib/warden/manager.rb:52:in '_run_callbacks'

...

  • only fails where I use Timecop

Looking at the error (exception was thrown in timeoutable.rb) and the common use of Timecop, I figured that is what is responsible - but I cannot explain why it is happening nor why it is intermittent.

Here is a sample piece of code to further explain the problem:

Timecop.travel(10.weeks.from_now) do
     sign_in(user)
     visit some_path
     expect(page).to have_title('something')
     # ... and more
end

Notice that the error still shows up sometimes despite signing in after time-travel.

Everything works fine normally, in fact this test (and a couple of other ones) fail 1 in every 50+ times at most.

Any help is much appreciated. Thanks in advance.

EDIT: error occurs when visitng a page, as per screenshot. This screenshot is from a Capybara fail, right after I attempt to visit a page.Uncaught exception

Harry V
  • 73
  • 1
  • 1
  • 6

1 Answers1

0

I'm guessing the error you're getting is caused by secondary requests the page issues when you visit it. There is a slight time between when Timecop resets the time and the test is cleaned up where a request from the page could hit the server and be processed with a session cookie that is invalid (due to the server time having changed). Once you confirm the page is issuing additional requests when you visit it, there are a few things you could do to work around the error.

  1. Add an additional expect to the test for whatever the additional request(s) are getting

  2. Set Capybara.raise_server_errors = false for the specific tests, so the server errors get ignored

  3. Implement a way (possibly middleware) to set request.env["devise.skip_timeout"] = true during the specific tests

  4. Use the non block version of Timecop.travel and then call Timecop.return in an append_after block for the specific tests. This should move the call to return until after Capybara has waited for all requests to finish -- might have potential side effects on the test cleanup though, not 100% sure this would be stable.

Thomas Walpole
  • 48,548
  • 5
  • 64
  • 78
  • Thanks @twalpole, I've updated the description of the problem. It happens even just on visits to the site. I've given #4 a go, so far it is ok. #1 I can't do due to it being on page visit. With #2, aren't we just hiding the real issue? An explanation of it would be appreciated. Thanks – Harry V Oct 16 '17 at 02:19
  • @HarryV Yes - it would happen on just visits to the site (assuming my guess is right that the page is requesting more info via an AJAX request). So you can do #1 if you have an expectation for whatever info is being requested to show on the page. #2 is hiding an extraneous error the server is raising which has nothing to do with the test you're running, so it's hiding what #3 would prevent from happening, either way it's irrelevant. #4 fixes it by not resetting the time until after Capybara has waited for all the requests to have finished. Note 10.weeks.from_now is the future not the past. – Thomas Walpole Oct 16 '17 at 02:38
  • Sorry I don't think I was clear. This is happening on page load - so before I even have an opportunity to have an AJAX request. Any idea what these irrelevant errors are that we are hiding? And do options #2 and #3 block essential errors? – Harry V Oct 16 '17 at 05:59
  • @HarryV If this is actually happening on initial page load (verify with your test.log) then my guess isn't correct. In that case the assertions would fail, so #2 and #3 wouldn't allow the test to pass (because the errors wouldn't be irrelevant - the errors are having requests occur after Timecop resets so the session cookie is invalid). However if #4 has fixed the errors it would tend to confirm my guess as correct since it proves you have requests occurring after Timecop has reset to current time. So statements and results are currently conflicting. Post test.log of a fail example – Thomas Walpole Oct 16 '17 at 06:17
  • @twalpole I'll be able to get the logs tomorrow but if you are interested, you'll find all that you need in the above screenshot - I could not find more information in the logs apart from what was displayed on the browser itself. – Harry V Oct 16 '17 at 07:02
  • I should also be clear that that screenshot is from a Capybara fail, right after I attempt to visit a page. – Harry V Oct 16 '17 at 07:03
  • @HarryV The info above doesn't show the order and timing of requests. The test.log should. – Thomas Walpole Oct 17 '17 at 08:44