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 "\n\nStarting #{@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.

About these ads

15 Responses to “Find tests more easily in your Rails test.log”

  1. Jason Boxman Says:

    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. Brian Morearty Says:

    Thanks for the tip on the webrat gem, Jason. Looks good.

  3. ben.send :blog » Blog Archive » Global Setup In RSpec or How To Add Logging For Specs Says:

    [...] Morearty had an interesting post on how to add additional information to a rails testing log when using Test::Unit. The benefit of this is that you can quickly scan your log file when a test [...]

  4. Gregg Pollack Says:

    Ben Mabey wrote a follow up post showing how to do this in RSpec:

    http://www.benmabey.com/2008/07/04/global-setup-in-rspec-or-how-to-add-logging-for-specs/

    Happy July 4th!

  5. Brian Morearty Says:

    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.

  6. Mike Boone Says:

    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?

  7. Brian Morearty Says:

    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.

  8. John Says:

    I tried this out but am getting an error, wrong number of arguments (1 for 0) for method setup. Looking at the rdoc for the testcase class (http://www.ruby-doc.org/stdlib/libdoc/test/unit/rdoc/classes/Test/Unit/TestCase.html#M004534) and setup doesn’t take any parameters. Any ideas?

  9. Brian Morearty Says:

    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.

  10. Brian Says:

    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
    RAILS_DEFAULT_LOGGER.info “\n\nStarting #{@method_name}\n#{‘-’ * (9 + @method_name.length)}\n”
    end

  11. Brian Says:

    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?

    b

  12. Brian Says:

    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:

    http://www.inwebwetrust.net/post/2008/08/19/redefine-the-run-method-of-test-unit-testcase

    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
    RAILS_DEFAULT_LOGGER.info “\n\nStarting #{@method_name}\n#{‘-’ * (9 + @method_name.length)}\n”
    end

    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.

    b

  13. Russ Kuhn Says:

    As of Rails 2.3.4, if not earlier, @method_name is not supported and should be replaced with just name, as in

    Rails::logger.info “\n\nStarting #{name}\n#{‘-’ * (9 + @name.length)}\n”

  14. Brian Morearty Says:

    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)

  15. Christopher Pickslay Says:

    This rocks Brian. Thanks!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s


Follow

Get every new post delivered to your Inbox.

%d bloggers like this: