Semantic Logger

Testing

Contents

• Minitest
  • Step 1: install the helpers
  • Step 2: capture events
  • Step 3: assert on the events
  • Match part of a message or payload
• RSpec
  • Step 1: install the helpers
  • Step 2: capture events
  • Step 3: assert on the events
  • Match against a list of events
  • Assert directly on a block
• Other test frameworks

When testing application code, you often want to assert that it logged the right thing: the expected message, level, payload, or metric. Semantic Logger logs through a global, asynchronous pipeline, so you cannot simply read it back from a normal appender. Instead it ships a test helper that captures log events in memory during a block, so you can make assertions on them.

The events are captured as raw SemanticLogger::Log objects, before any appender or formatter runs, so your assertions are not affected by how logging happens to be configured.

Helpers are provided for both Minitest and RSpec. Other frameworks are covered further down.

Minitest

Step 1: install the helpers

Add the helper methods to your tests, once, in test_helper.rb:

Minitest::Test.include SemanticLogger::Test::Minitest

Step 2: capture events

Wrap the code under test in semantic_logger_events. It returns every log event created during the block:

messages = semantic_logger_events do
  User.new.enable!
end

By default it captures events from every class. To capture only the events from one class, pass that class:

messages = semantic_logger_events(ApiClient) do
  # Only ApiClient log events created during this block are captured.
end

Step 3: assert on the events

Check how many events were produced, then assert on each one with assert_semantic_logger_event:

require_relative "test_helper"

class UserTest < ActiveSupport::TestCase
  describe User do
    it "logs message" do
      messages = semantic_logger_events do
        User.new.enable!
      end

      # How many events were logged
      assert_equal 2, messages.count, messages

      # The first event
      assert_semantic_logger_event(
        messages[0],
        level:   :info,
        message: "User enabled"
      )

      # The second event
      assert_semantic_logger_event(
        messages[1],
        level:   :debug,
        message: "Completed"
      )
    end
  end
end

Every argument other than the event itself is optional, so you assert only on what matters to the test. The available checks are:

Match part of a message or payload

For assertions that should not break on incidental detail, match partially.

Use message_includes for a substring of the message:

assert_semantic_logger_event(
  messages[0],
  level:            :info,
  message_includes: "enabled"
)

Use payload_includes to assert specific payload keys while ignoring any extras. Compare with payload, which must match the whole Hash exactly:

# Exact: the payload must be exactly these keys and values
assert_semantic_logger_event(
  messages[0],
  level:   :info,
  message: "User enabled",
  payload: {first_name: "Jack", last_name: "Jones"}
)

# Partial: first_name must be present, other keys are ignored
assert_semantic_logger_event(
  messages[0],
  level:            :info,
  message:          "User enabled",
  payload_includes: {first_name: "Jack"}
)

For more examples, see the Rails Semantic Logger tests.

RSpec

The RSpec helpers mirror the Minitest ones: a capture helper plus matchers for asserting on the captured events.

Step 1: install the helpers

Require the helpers and include them, once, in spec_helper.rb:

require "semantic_logger/test/rspec"

RSpec.configure do |config|
  config.include SemanticLogger::Test::RSpec
end

Step 2: capture events

Wrap the code under test in capture_semantic_logger_events. It returns every log event created during the block, regardless of the global default log level:

events = capture_semantic_logger_events do
  User.new.enable!
end

By default it captures events from every class. To capture only the events from one class, pass that class:

events = capture_semantic_logger_events(ApiClient) do
  # Only ApiClient log events created during this block are captured.
end

Step 3: assert on the events

Use be_a_semantic_logger_event to assert on a single captured event:

RSpec.describe User do
  it "logs message" do
    events = capture_semantic_logger_events do
      User.new.enable!
    end

    expect(events.count).to eq(2)

    expect(events[0]).to be_a_semantic_logger_event(
      level:   :info,
      message: "User enabled"
    )

    expect(events[1]).to be_a_semantic_logger_event(
      level:   :debug,
      message: "Completed"
    )
  end
end

Every argument is optional, so you assert only on what matters to the test. The available checks are the same as the Minitest table above, plus message_includes, payload_includes, and exception_includes for partial matches:

expect(events[0]).to be_a_semantic_logger_event(
  level:            :info,
  message_includes: "enabled",
  payload_includes: {first_name: "Jack"}
)

An expected value that is a Class matches by type, and :nil asserts the attribute is nil:

expect(events[0]).to be_a_semantic_logger_event(time: Time, exception: :nil)

Match against a list of events

a_semantic_logger_event is a composable alias, so it works inside include and other matchers:

expect(events).to include(
  a_semantic_logger_event(message: "User enabled")
)

Assert directly on a block

log_semantic_logger_event captures the events for you and passes if any of them match. Pass on: to capture only one class’s events:

expect { User.new.enable! }.to(
  log_semantic_logger_event(level: :info, message: "User enabled")
)

expect { ApiClient.new.call }.to(
  log_semantic_logger_event(on: ApiClient, metric: "ApiClient/call")
)

Other test frameworks

The same approach works anywhere: replace the logger with a SemanticLogger::Test::CaptureLogEvents instance. It looks and behaves like a normal logger, but keeps the raw log events in memory instead of writing them, so your assertions are unaffected by the configured appenders or their formats.

logger = SemanticLogger::Test::CaptureLogEvents.new

Stub it onto a single class to capture just that class’s logging:

User.stub(:logger, logger) do
  # Capture all logging calls to the User logger.
end

Or stub the global processor to capture logging from every class:

SemanticLogger::Logger.stub(:processor, logger) do
  # Capture all log events during the block.
end

Either way, the captured events are available as logger.events.

If you add helper methods for another framework like the Minitest ones, a pull request would be welcome.