RSpec: how to test Rails logger message expectations?

Question

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?

Answer 1

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