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?

Solution 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

Solution 2

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

Also if you care about just matching the first message and not any subsequent messages then you can use following

  expect(Rails.logger).to receive(:debug).with("Technical Error Message").ordered.and_call_original
  expect(Rails.logger).to receive(:debug).at_least(:once).with(instance_of(String)).ordered

Note in above variation setting .ordered is important else expectations set start failing.

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

Solution 3

Instead of using this line before the message is logged:

expect(Rails.logger).to receive(:info).with("some message")
something that triggers the logger...

You could set the Rails logger as a spy and use have_received instead:

allow(Rails.logger).to receive(:info).at_least(:once)

something that triggers the logger...

expect(Rails.logger).to have_received(:info).with("some message").once

Solution 4

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.

Solution 5

If you want to keep consistency in your tests, but setting the expectations at last you need to add in your setup:

setup do
 allow(Rails.logger).to receive(:info)
end
...

it 'should log an info message' do
 {code}

  expect(Rails.logger).to have_received(:info).with('Starting the worker...')
end

View more solutions

Comments

[Art Shayderov]

That question did arise several times on SO, see for example here and here and the general consensus was that you don't test logging unless it's a project requirement.

[keruilin]

Art, thanks for the comment. I did read those ones. That may be the ultimate answer.

[Amol Pujari]

I have the similar case expect my expected string is a partial string, I could not figure out so far, how to deal with it, any help?

[absessive]

@AmolPujari expect(Rails.logger).to receive(:info).with(/partial_string/) where "partial_string" is the string you're looking for. Simple Regex compare

[mr_than]

This is great, I'm checking I don't get anything at all logged to error and checking against Rspec's anything matcher does this nicely: expect(Rails.logger).to_not receive(:error).with(anything)

[sixty4bit]

what exactly do you mean by "you have to put this line before the message is logged"? The expectation appears in the code before the code that generates the log? I'm doing that and getting an error because the logger is getting the message that is logged from stuff being done in my let expressions before the it block even runs

[banesto]

@sixty4bit it means, that expext.. receive works as an event listener - you have to set it up first and then launch the code that will log the message you want to catch

[Sasgorilla]

Does this not work in feature specs (as opposed to controller specs)? I'm using the code above: expect(Rails.logger).to receive(:info).with(/foobar/), placed before the spec code that will generate logging. I can plainly see the foobar statement in test.log after the spec runs, but the spec fails with the error above.

[Sean]

The _from_any_process was what I was missing! Took way too long to find this. Thank you!

[alexventuraio]

I used the first approach but why this expect(Rails.logger).to receive(:info).with("A Report processing is already scheduled for: #{report.inspect}") was giving this error: expected: ("A Report processing is already scheduled for: #<Report id: 2677, org_id: 6649, user_id: ...tion: nil, life_state: \"ideation\", chat_link: nil, discarded_at: nil, registrants_count: 2>") ---> got: ("A Report processing is already scheduled for: [#<Report id: 2677, org_id: 6649, user_id:...ion: nil, life_state: \"ideation\", chat_link: nil, discarded_at: nil, registrants_count: 2>]") (1 time)