Better logging from Capybara/RSpec?

Question

I'm having a really tough time investigating the cause of a test failure. I'm a very experienced programmer and am well versed in general debugging techniques, but I'm new to Capybara and RSpec so I'm hoping there's some kind of facility I'm ignorant of that can help me.

In short, I have a test something like this:

expect { click('.fake_button'); sleep 1 }.to change { clicks.count }.by(1)

When the fake button is clicked, it triggers an AJAX call to the Rails app which, among other things, adds a click record to the database. I can think of dozens of things that could be causing this test to fail and have had only limited success getting information out of logs. The tests do not fail in development and it only fails sporadically in test. One of the differences of the test environment is that the tests are run on a server in our office against a server in the cloud, so there are network delays along with other possible issues.

This is very hard to diagnose because there's so little information coming out of the failed test and of course all the database information is thrown away by the time I read about the failure. I know clicks.count didn't change in the test and I can infer that click('.fake_button') succeeded, but due to server time sync issues I can't even be sure that the click happened on the right button or that the AJAX call fired.

What I'd like are some tools to help me follow this test case in the web server logs (maybe using automatic URL parameters, for example), detailed logging about what Capybara did, and a record of the web page as it was when the failure occurred, including cookie values. Can I get any of that? Anything like that?

Answer 1

Capybara simulates human actions. The test code does exactly what needed. It's something a real user should expect. I don't think you should complain the code.

I think it's okay to increase the wait time, say 1 to 2, due to your network latency, but it should not exceed a reasonable value otherwise the app does not work as real user expected.

To debug Capybara codes, there are three methods as I summarized:

1. Add "save_and_open_page" to the place you want to see result. Then a saved html page will appear during the test. (I forget if "launchy" gem should be added)

2. Temporarily set this test as JS to see how this test going.

   scenario "a fake test", js: true do
     # code here
   end
   

   By doing this a real browser will pop up and Capybara will show you step by step how it play the code.

3. Just run $ tail log/test.log to show what happened recently.

Answer 2

Building off what @Billy suggested, log/test.log was not giving me any useful information and I was already using js: true so I tried this:

begin
  expect { click('.fake_button'); sleep 1 }.to change { clicks.count }.by(1)
rescue Exception => e
  begin
    timestamp = Time::now.strftime('%Y%m%d%H%M%S%L')
    begin
      screenshot_name = "tmp/capybara/capybara-screenshot-#{timestamp}.png"
      $stderr.puts "Trying to save screenshot #{screenshot_name} due to test failure"
      page.save_screenshot(screenshot_name)
    rescue Exception => inner
      $stderr.puts "Ignoring exception #{inner} while trying to save screenshot of test page"
    end
    begin
      # Page saved by Capybara under tmp/capybara/ by default
      save_page "capybara-html-#{timestamp}.html"
    rescue Exception => inner
      $stderr.puts "Ignoring exception #{inner} while trying to save HTML of failed test page"
    end
  ensure
    raise e
  end
end

Later I changed the test itself to take advantage of Capybara's AJAX synchronization features by doing something like this:

    starting_count = clicks.count
    click('.fake_button')
    page.should have_css('.submitted')     # Capybara is smart enough to wait for this to happen
    clicks.count.should == starting_count + 1

Note that the CSS I'm looking for is something added to the page in JavaScript by the AJAX callback, so it showing up is a signal that the AJAX call completed.

The rescue blocks are important because the screenshot has a high failure rate from not having enough memory to render the full page and convert it to an image.

EDIT

Though I haven't tried it, a promising solution is Capybara::Screenshot which automatically saves the screenshot and HTML on any failure. Just reading the code it looks like it will have problems when the screenshot fails and I can't tell what state the page will be in by the time the screenshot is triggered, but it certainly looks like it's worth a try.

Answer 3

A nice way to debug tests is to use irb to watch what's actually happening in the browser. RSpec fails usually give decent information for simple cases, but for more complicated things I either split the case up until it is simple, or chuck it in irb for a live session to make sure its doing what it should do.

Make sure to use :selenium as your driver, and you should see firefox come up and be able to be driven by your irb session.