Global Setup In RSpec or How To Add Logging For Specs

Brian 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 fails and see clues on why it failed. If you're using RSpec you can add the same functionality all within the confines of the RSpec API for both specs (examples) and the story runner.

Global Setup for Specs

In order to announce the running of a spec in rail's test log for all of the specs you need to take advantage of RSpec's global setup capabilities. To recreate the same type of logging message that Brian did for Test::Unit in RSpec you would simply need to add this in your spec_helper.rb:

    Spec::Runner.configure do |config|
      ...
      config.before(:each) do
          full_example_description = "Starting #{self.class.description} #{@method_name}"
          RAILS_DEFAULT_LOGGER.info("\n\n#{full_example_description}\n#{'-' * (full_example_description.length)}")      
      end
      
    end

Note, that I am using the RAILS_DEFAULT_LOGGER constant instead of Rails::logger which was just introduced in Rails 2.1. If you are using Rails 2.1 then I would suggest using the prettier and newer way. I personally don't feel the need to have "Starting" preface each description in the log file and prefer just to use the example description:

    Spec::Runner.configure do |config|
      
      ...
      config.before(:each) do
          full_example_description = "#{self.class.description} #{@method_name}"
          RAILS_DEFAULT_LOGGER.info("\n\n#{full_example_description}\n#{'-' * (full_example_description.length)}")
      end
    end

Global Setup for Stories

When using the RSpec Story Runner you often want to do some standard setup and teardown for each story and/or scenario. (Such as cleaning up the database, or resetting ActionMailer::Base.deliveries.) While the Story language does not provide a way to express this sort of setup and teardown (which is a good thing IMO) you can achieve the same effect by registering Listeners with the correct hooks. The useful available hooks you can use are as follows:

    class MyStoryListener
       def run_started(number_of_scenarios); end
       def story_started(story, narrative); end
       def story_ended(story, narrative); end
       def scenario_started(story, scenario); end
       def scenario_succeeded(story, scenario); end
       def scenario_pending(story, scenario, error); end
       def scenario_failed(story, scenario, error); end
       def run_ended; end
    end

For example, if you wanted to add similar logging capabilities to your stories as we did with our specs above you would need to create a custom Listener and register it. The code to do that is as follows: (this should live in your stories/helper.rb file)

    class StoryLoggerListener

       def scenario_started(story, scenario)
        story_description    = "Story: #{story}"
        scenario_description = "  Scenario: #{scenario}"
        line_width = (story_description.length > scenario_description.length) ? story_description.length : scenario_description.length
        # yes, I know I could do [story_description.length, scenario_description.length].max
        RAILS_DEFAULT_LOGGER.info("\n\n#{story_description}\n#{scenario_description}\n#{"-"*line_width}")
       end

       def method_missing(method, *args)
          # no-op
        end
    end
    
    # This is how you register your listener
    Spec::Story::Runner.register_listener(StoryLoggerListener.new)

The trick is to have method_missing handle all of your unimplemented hooks and just implement the ones you care about. The last line is what lets the Story Runner know about your listener so that the hooks are actually called.

Since scenarios tend to take a lot more space in a log file than an individual spec I don't find this logging as useful. The use of Listeners within the Story framework, in general, can be extremely useful though and is a nice feature to know about.

I hope this post helps in shedding some light on some lesser known features of RSpec and results in more useful log files. :)


About this entry