Monday, December 30, 2013

Ignoring method invocations with RSpec message expectations

I often find myself with RSpec test examples that are verifying that log output meets expectations, but where the test is only concerned with verifying a single, specific log message has been generated. But usually the logger is receiving additional output that the test is not concerned about. Unfortunately, this output must still be "expected", lest the test will fail. There is (apparently) no way in RSpec to write an message expectation with specific arguments that should occur "at some point", when the message is also received at other times with different arguments.  For example this simple test example fails if logger.info is called more than once by the code being tested:

it "logs a specific message" do
  logger.should_receive(:info).with(/text that must be logged/)
  invoke_your_test_code()
end

RSpec will complain with something like:

expected: (/text that must be logged/)
     got: ("starting process...")


Writing and maintaining the code that explicitly expects all of the other logging calls is cumbersome to write and maintain, and makes the test fragile to log output changes that are not of concern to the test.

However, I found that one can gracefully ignore this extraneous log output by using the any_number_of_times expectation method in conjunction with the specific expectation to ignore all of the other method invocations, as follows:

it "logs a specific message message" do
  logger.should_receive(:info).with(/text that must be logged/)
  logger.should_receive(:info).any_number_of_times
  invoke_your_test_code()
end

The any_number_of_times expectation must occur after the specific expectation that is being verified; otherwise the expected log output will be "consumed" by the any_number_of_times expectation, and the test will fail.