Testing Interactions with a State Based Approach

There are two main types of unit tests: state based and interaction based. State based tests rely on the verification of state. These tests typically perform some operation and then check the state of the resulting object:

user = User.new :title => 'manager'
user.promote!
user.title.should == 'senior manager'

In contrast, interaction based tests rely on verification of the interaction between objects. This is generally done with mocks or stubs:

user = User.new
Mailer.should_receive(:send_email).with(user)
user.activate!

This test ensures that the activate! method interacts with the Mailer, without actually sending an email.

Interaction based testing has its uses, but in general, I prefer state based testing. I think that tests full of mocks are brittle and hard to read. Furthermore, when they fail, it can be difficult to understand why.

In my testing, I try to replace interaction based testing with state based when possible. I’m going to walk through an example where a typical test would use mocks, but I’m going to use a state based approad instead.

Say I have a Rails 3 application that accepts social security numbers. These are sensitive, so I want to make sure I don’t log them to the application log. A simple testing approach (using rspec) might look like:

require 'spec_helper'

describe MyController do
  describe "create" do
    it "filters sensitive data from the log" do
      Rails.logger.should_receive(:info).with { |message| message.include?("123-45-6789") }.never 
      post :create, :myobj => {:social_security_number => "123-45-6789"}
    end
  end
end

One problem with this test is that it’s a negative test. It can pass for the wrong reasons. For example, if the controller action blows up before it would normally log, the test may pass even though it would log under normal circumstances. It’s generally better to write a possitive test:

require 'spec_helper'

describe MyController do
  describe "create" do
    it "filters sensitive data from the log" do
      Rails.logger.should_receive(:info).with(include('"social_security_number"=>"[FILTERED]"'))
      post :create, :myobj => {:social_security_number => "123-45-6789"}
    end
  end
end

This test is better, but still not great. One problem is that Rails.logger.info is now mocked out, so there will be no logging which can make debugging a failing test more difficult. Another problem is that if the test fails, the test output only says expectation not met. It does not show you what was actually logged:

  1) MyController create filters sensitive data from the log
     Failure/Error: Rails.logger.should_receive(:info).with(include('"social_security_number"=>"[FILTERED]"'))
       (#).info(include "\"social_security_number\"=>\"[FILTERED]\"")
           expected: 1 time
           received: 0 times
     # ./spec/controllers/my_controller_spec.rb:7:in `block (3 levels) in '

Here is the state based test I prefer:

require 'spec_helper'

describe MyController do
  describe "create" do
    it "filters sensitive data from the log" do
      post :create, :myobj => {:social_security_number => "123-45-6789"}

      log_line = Rails.logger.log_history.grep(/Parameters:/).first
      log_line.should include('"social_security_number"=>"[FILTERED]"')
    end
  end
end

This test actually grabs the log line from a log history. If we don’t find the log line, it will be obvious. If we do find the line, we can compare the expected output with the actual one.

Now, the test failure contains both the expected and actual:

  1) MyController create filters sensitive data from the log
     Failure/Error: log_line.should include('"social_security_number"=>"[FILTERED]"')
       expected "  Parameters: {\"myobj\"=>{\"social_security_number\"=>\"123-45-6789\"}}" to include "\"social_security_number\"=>\"[FILTERED]\""
     # ./spec/controllers/my_controller_spec.rb:9:in `block (3 levels) in '

We can monkey patch Rails.logger to record the log lines in spec_helper.rb:

module LogHistory
  def add(_, _, message = nil, &block)
    log_history << message
    super
  end

  def log_history
    @log_history ||= []
  end

  def clear_log_history
    log_history.clear
  end
end

RSpec.configure do |config|
  config.before(:suite) do
    Rails.logger.extend(LogHistory)
  end

  config.before(:each) do
    Rails.logger.clear_log_history
  end
end

Now, every log line is recorded per test and cleared out in between. This pattern also works well for other external dependencies, such as database statements or queries sent to a search tool. They can be recorded and asserted against directly.