Find tests more easily in your Rails test.log

Here’s a nice little trick to make it easier to search test.log for the results of a specific test that’s failing. This trick works with normal Rails unit tests and with Shoulda tests.

When a Rails test fails, I look for it in test.log to see if there are any clues there. But it’s pretty hard to find the portion of the log associated with the test that failed. In this sample section of a log, where does the processing begin for the test called test_should_require_email_on_signup?

test.log without titles
Which test is which? Where does my test start?

It’s hard to find. Now imagine running rake on all your tests and sifting through the whole test.log looking for one test whose name you know, but the test name isn’t in the log.

So the other day I wrote a bit of code in my test_helper.rb file to make the log a lot easier to sift through. Here’s what the above log looks like with this code in place:

test.log with titles
Ooh, nice-n-clear

Ahh, that’s more like it. Now it’s easy to tell where test_should_require_email_on_signup begins. If you scroll up and look at the first log again, you’ll see that there isn’t even a blank line separating that test from the previous one. (See how the test starts on the SELECT count(*) statement?)

Here’s the code. Drop it into test_helper.rb for your Rails project. To me this seems like a nice little example of how Ruby’s open classes can benefit developers (while understandably considered harmful by some). In a language without monkey patching, I would have to resort to something more painful like changing all my tests to be derived from my own subclass of TestCase, and put this code in that class.

Enjoy!

class ActiveSupport::TestCase
  # This extension prints to the log before each test.  Makes it easier to find the test you're looking for
  # when looking through a long test log.
  setup :log_test

  private

  def log_test
    if Rails::logger
      # When I run tests in rake or autotest I see the same log message multiple times per test for some reason.
      # This guard prevents that.
      unless @already_logged_this_test
        Rails::logger.info "nnStarting #{@method_name}n#{'-' * (9 + @method_name.length)}n"
      end
      @already_logged_this_test = true
    end
  end
end

P.S. I didn’t spend the time to figure out why my callback was being called multiple times for each test. I just inserted the guard you see in the code above to prevent the same test title from being shown multiple times.

Drop me a line in the Reply section below and let me know what you think–especially if you’ve figured out why each one is called multiple times when running from rake or autotest.

Updated 6/18: I corrected the code above because WordPress automatically inserted a “mailto:” tag when it saw the @ sign.

Updated 2/26/10: I changed Test::Unit::TestCase to ActiveSupport::TestCase.