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.


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


  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 "nnStarting #{@method_name}n#{'-' * (9 + @method_name.length)}n"
      @already_logged_this_test = true

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.

15 thoughts on “Find tests more easily in your Rails test.log”

  1. Excellent. I was just about to dig into that myself. I am using shoulda and webrat and running through a bunch of controllers to verify they all status 200. Now I can more easily spot which one failed and how. Check out the webrat gem if you haven’t yet — it’s great!

  2. Thanks to Ben Mabey for that follow-up on how to do this in RSpec and to Gregg Pollack of RailsEnvy fame for pointing it out. I haven’t used RSpec yet (although I’m about to learn it since the team I just switched to at Intuit is using it), so I wasn’t sure yet how to do my logging trick in RSpec.

  3. Great idea.

    I dropped the code into my Rails 2.0.2 app’s test_helper.rb and got this error trying to run a unit test:

    ./test/unit/../test_helper.rb:42: undefined method `setup’ for Test::Unit::TestCase:Class (NoMethodError)

    Anyone else seeing this?

  4. Hmm. Mike, I haven’t heard from anyone else who said they had that problem with an undefined method ‘setup’. Please drop another note here if you find a solution.

  5. Hum, that’s interesting, John. The call to setup is supposed to call a class method, not an instance method. (The doc page you referenced is referring to the instance method.) You might double-check to see if you entered it the way I wrote it.

    Or perhaps things have changed in a newer version of Rails. (Or an older one.)

    The code above works in Rails 2.0.2. There’s a file called setup_and_teardown.rb that has these lines:

    base.send :include, ActiveSupport::Callbacks
    base.define_callbacks :setup, :teardown

    define_callbacks creates a “setup” method and a “teardown” method as class methods. These methods are very much like the before_save, after_save, etc. methods, in that they take a parameter which is the name of a function to call before setup and after teardown. So my code that says “setup :log_test” tells the test framework to call the :log_test function before calling the “setup” instance method.

    Perhaps things work differently in other versions of Rails.

  6. In an attempt to better understand monkey patching, I added a setup method to my test_helper.rb, as I understand it’s called for each test. It worked, but I don’t know how I didn’t break the actual setup method.

    def setup “nnStarting #{@method_name}n#{‘-‘ * (9 + @method_name.length)}n”

  7. Ah, didn’t break unit tests, but broke functional tests (I should have checked before posting). How can this be overridden properly in test_helper.rb? Or, should I place the method in each unit test rb file like functional tests?


  8. I have this working (Rails 2.0.2, ruby 1.8.4), but it’s not DRY and there are better ways. Fernando Blat Talks about how to add special actions before and after each test via an alias_method_chain for the run method:

    Anyway, this is what I did before finding Fernando’s approach:

    For Unit Tests, add the setup method below in each test .rb file (you can also add a teardown method to log the end of the test, but having the start logged between each test was a good enough of delimiter for me). If you already have a setup method, of course just add the logger code line.

    def setup “nnStarting #{@method_name}n#{‘-‘ * (9 + @method_name.length)}n”

    For Functional tests (because mine still use Test::Unit::TestCase), simply add the logger code line to the existing setup method.

    Sorry for the previous posts and confusion. There is a better approach to keep this DRY, but until I figure that out, this is what I’ve done, it worked, so I thought I’d share — but I encourage you to learn the proper approach.


  9. As of Rails 2.3.4, if not earlier, @method_name is not supported and should be replaced with just name, as in “nnStarting #{name}n#{‘-‘ * (9 + @name.length)}n”

  10. The fix for Rails 2.x turned out to be a one-liner. I have corrected it in the post.

    I changed “Test::Unit::TestCase” to “ActiveSupport::TestCase”.

    This fixes the error people were talking about in the comments:
    ./test/unit/../test_helper.rb:42: undefined method `setup’ for Test::Unit::TestCase:Class (NoMethodError)

Leave a Reply

Your email address will not be published. Required fields are marked *

Feel free to use <a>, <b>, <i>, <strong>, <em>, <strike>, <code>.

Code blocks:
[code language="ruby/javascript/html/css/sass/bash"]