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.
