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.

Paul Gross

Paul Gross

I'm a lead software developer in Seattle working for Braintree Payments.

Read More