Rspec tests and testing logging happens

[nikonoid]

This is likely a documentation issue, but I wanted to save someone else or future me some time, and have a discussion about if there is a better way to solve this issue.

Environment

• Ruby 2.7.4
• Rails 6.0.4.1
• RSpec 3.7

Expected Behavior

Testing Loggin behaviour is useful when it amounts to a contract between your app and some monitoring/log aggregation and alerting system.

using RSpec a test like

it "should emit warning log" do
  expect(Rails.logger).to receive(:warn).with(expected_log_message)
  calls_to_controller_which_emits_warn
end

should pass

Actual Behavior

using RSpec a test like

expect(Rails.logger).to receive(:warn).with(expected_log_message)

should fails because the Rails.logger object in the test suite is not the same object as the Rails.logger in the controller( as there is an instance per controller which knows about things like the name of the controller).

Curent solution

In my spec_helper.rb

  config.before(:example) do
    allow(SemanticLogger::Logger).to receive(:new).and_return(Rails.logger)
  end

[reidmorrison]

Sorry, we don't use RSpec, you are on your own there.

[pre]

If you write something like expect(Rails.logger) it sounds like it's not clear what is the boundary of responsibilities in your test suite.

The question in this issue is about a specific details, however, I think it's impossible to answer without really knowing what you're really trying to do.

In other words, I feel the question needs some more architectural thought, that is, I don't think the question as is can be answered here in the first place.

[reidmorrison]

I was hoping the community would contribute something generic for tests.

In our application we have added a custom logger that gathers all log messages in memory for a specific model. This way other log messages are excluded and there are no issues with asynchronous logging etc.

Add this custom class to your test_helper.rb until the next release of Semantic Logger which will include it.

module SemanticLogger
  module Test
    class CaptureLogEvents < SemanticLogger::Subscriber
      attr_accessor :events

      # By default collect all log levels, and collect metric only log events.
      def initialize(level: :trace, metrics: true)
        super(level: level, metrics: true)
      end

      def log(log)
        (@events ||= []) << log
      end
    end
  end
end

Example, using it in a unit level test:

class UserTest < ActiveSupport::TestCase
  describe User do
    let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new }
    let(:user) { User.new }

    it "logs message" do
      user.stub(:logger, capture_logger) do
        user.enable!
      end
      assert_equal "Hello World", capture_logger.events.last.message
      assert_equal :info, capture_logger.events.last.level
    end
  end
end

Could you convert the above minitest example in RSpec format so that I can include it as an example for others to use?

[reidmorrison]

I bet there are cleaner, better ways to build this into minitest and RSpec?

The full log event structure that can be tested against: https://logger.rocketjob.io/log_struct.html

This could be the start of something we can grow to make testing easier? https://github.com/reidmorrison/semantic_logger/commit/54cf74164eab20567a1279e43947c7e36cb02f6c

[reidmorrison]

If you point to Semantic Logger master branch you can use the new testing feature for minitest. Looking for a volunteer to convert it to RSpec for those that use RSpec. https://logger.rocketjob.io/testing.html

[jgascoignetaylor-godaddy]

@reidmorrison converted to rspec syntax:

context 'when it blows up' do
  let(:capture_logger) { SemanticLogger::Test::CaptureLogEvents.new }

  it 'should should log the error' do
    allow_any_instance_of(MyThing).to receive(:logger).and_return(capture_logger)
    MyThing.new('asdf').do_something!

    expect(capture_logger.events.last.message).to include('Here is a message')
    expect(capture_logger.events.last.level).to eq(:error)
  end
end

[jdelStrother]

FWIW here's my attempt at adding some nicer RSpec expectations around SemanticLogger: https://gist.github.com/jdelStrother/c37082b04ee27622dd3715484177e0b5

which can be used like:

 expect {
   User.first.logger.info("hello")
 }.to log_event(message: "hello", on: User)

or

 logs = capture_logs {
   post "/login", params: { username: "bob" }
 }
 expect(logs[0]).to be_semantic_log(message: "Started")
 expect(logs).to include(a_semantic_log(payload_including: { params: { "username" => "bob" } })