I am trying to test that the Rails logger receives messages in some of my specs. I am using the Logging gem.
Let's say that I have a class like this:
class BaseWorker
def execute
logger.info 'Starting the worker...'
end
end
And a spec like:
describe BaseWorker do
it 'should log an info message' do
base_worker = BaseWorker.new
logger_mock = double('Logging::Rails').as_null_object
Logging::Rails.stub_chain(:logger, :info).and_return(logger_mock)
logger_mock.should_receive(:info).with('Starting the worker...')
base_worker.execute
Logging::Rails.unstub(:logger)
end
end
I get the following failure message:
Failure/Error: logger_mock.should_receive(:info).with('Starting worker...')
(Double "Logging::Rails").info("Starting worker...")
expected: 1 time
received: 0 times
I've tried out several different approaches to get the spec to pass. This works for example:
class BaseWorker
attr_accessor :log
def initialize
@log = logger
end
def execute
@log.info 'Starting the worker...'
end
end
describe BaseWorker do
it 'should log an info message' do
base_worker = BaseWorker.new
logger_mock = double('logger')
base_worker.log = logger_mock
logger_mock.should_receive(:info).with('Starting the worker...')
base_worker.execute
end
end
But having to setup an accessible instance variable like that seems like the tail is wagging the dog here. (Actually, I'm not even sure why copying logger to @log would make it pass.)
What's a good solution for testing the logging?
While I agree you generally don't want to test loggers, there are times it may be useful.
I have had success with expectations on Rails.logger
.
Using RSpec's deprecated should
syntax:
Rails.logger.should_receive(:info).with("some message")
Using RSpec's newer expect
syntax:
expect(Rails.logger).to receive(:info).with("some message")
Note: In controller and model specs, you have to put this line before the message is logged. If you put it after, you'll get an error message like this:
Failure/Error: expect(Rails.logger).to receive(:info).with("some message")
(#<ActiveSupport::Logger:0x007f27f72136c8>).info("some message")
expected: 1 time with arguments: ("some message")
received: 0 times
With RSpec 3+ version
Actual code containing single invocation of Rails.logger.error
:
Rails.logger.error "Some useful error message"
Spec code:
expect(Rails.logger).to receive(:error).with(/error message/)
If you want the error message to be actually logged while the spec runs then use following code:
expect(Rails.logger).to receive(:error).with(/error message/).and_call_original
Actual code containing multiple invocations of Rails.logger.error
:
Rails.logger.error "Technical Error Message"
Rails.logger.error "User-friendly Error Message"
Spec code:
expect(Rails.logger).to receive(:error).ordered
expect(Rails.logger).to receive(:error).with(/User-friendly Error /).ordered.and_call_original
Note in above variation setting .ordered
is important else expectations set start failing.
In Rails context I have verified the above code to work as expected however with info
and debug
levels it doesn't seem to work in straightforward manner. I guess its because of Rails internally using debug and info levels which may be causing errors like
(#<ActiveSupport::Logger:0x00000006c55778>).info(*(any args))
expected: 1 time with any arguments
received: 4 times with any arguments
References:
http://www.relishapp.com/rspec/rspec-mocks/v/3-4/docs/setting-constraints/matching-arguments
http://www.relishapp.com/rspec/rspec-mocks/v/3-4/docs/setting-constraints/message-order
If your goal is to test logging functionality you may also consider verifying the output to standard streams.
This will spare you the mocking process and test whether messages will actually end up where they supposed to (STDOUT/STDERR).
With RSpec's output matcher (introduced in 3.0) you can do the following:
expect { my_method }.to output("my message").to_stdout
expect { my_method }.to output("my error").to_stderr
In case of libraries such as Logger
or Logging
you may have to use output.to_<>_from_any_process
.