From 6079b37aeb878621a8089d67d976bb65cc7e8c14 Mon Sep 17 00:00:00 2001 From: Reid Morrison Date: Sat, 29 Jun 2024 15:38:30 -0400 Subject: [PATCH] Fixes #216 Completely refactor tests that call the logging api. Include fix from @bethesque for payload test case. --- CHANGELOG.md | 11 +- lib/semantic_logger/log.rb | 4 +- lib/semantic_logger/test/minitest.rb | 74 ++- test/logger_test.rb | 184 ------ test/semantic_logger_logging_test.rb | 821 +++++++++++++++++++++++++++ test/test_helper.rb | 3 + 6 files changed, 886 insertions(+), 211 deletions(-) create mode 100644 test/semantic_logger_logging_test.rb diff --git a/CHANGELOG.md b/CHANGELOG.md index d98755a5..d693bdcf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,10 +5,13 @@ This project adheres to [Semantic Versioning](http://semver.org/). ## [unreleased] -- Add support for Ruby 3.3 -- Allow SyncProcessor to be called from appenders -- Fix incorrect metrics usage examples in documentation -- Add `:duration_ms` to Logfmt fomatter +## [4.16.0] + +- Add support for Ruby 3.3. +- Allow SyncProcessor to be called from appenders. +- Fix incorrect metrics usage examples in documentation. +- Add `:duration_ms` to Logfmt formatter. +- Fixes #216 Log message from supplied message argument when payload contains payload key. ## [4.15.0] diff --git a/lib/semantic_logger/log.rb b/lib/semantic_logger/log.rb index 8b57fb5a..2827de69 100644 --- a/lib/semantic_logger/log.rb +++ b/lib/semantic_logger/log.rb @@ -144,7 +144,9 @@ def extract_arguments(payload, message = nil) raise(ArgumentError, "payload must be a Hash") unless payload.is_a?(Hash) message = nil if message == "" - return payload if payload.key?(:payload) + if payload.key?(:payload) + return message ? payload.merge(message: message) : payload + end new_payload = {} args = {} diff --git a/lib/semantic_logger/test/minitest.rb b/lib/semantic_logger/test/minitest.rb index 19f81a5f..5c11d101 100644 --- a/lib/semantic_logger/test/minitest.rb +++ b/lib/semantic_logger/test/minitest.rb @@ -18,35 +18,65 @@ def semantic_logger_events(klass = nil, &block) # Verify a single log event has all the required attributes. def assert_semantic_logger_event(event, level: nil, name: nil, message: nil, message_includes: nil, payload: nil, payload_includes: nil, + exception: nil, exception_includes: nil, backtrace: nil, thread_name: nil, tags: nil, named_tags: nil, context: nil, + level_index: nil, duration: nil, time: nil, metric: nil, metric_amount: nil, dimensions: nil) - msg = message || message_includes || "no message" - assert event, "Log event missing for message: '#{msg}'" - assert_equal message, event.message if message - assert_includes event.message, message_includes if message_includes - assert_equal name, event.name, -> { "Mismatched log name for message: '#{msg}'" } if name - assert_equal level, event.level, -> { "Mismatched log level for message: '#{msg}'" } if level + assert event, "No log event occurred" + + assert_semantic_logger_entry(event, :message, message) + assert_semantic_logger_entry(event, :name, name) + assert_semantic_logger_entry(event, :level, level) + assert_semantic_logger_entry(event, :thread_name, thread_name) + assert_semantic_logger_entry(event, :tags, tags) + assert_semantic_logger_entry(event, :named_tags, named_tags) + assert_semantic_logger_entry(event, :context, context) + assert_semantic_logger_entry(event, :metric, metric) + assert_semantic_logger_entry(event, :metric_amount, metric_amount) + assert_semantic_logger_entry(event, :dimensions, dimensions) + assert_semantic_logger_entry(event, :level_index, level_index) + assert_semantic_logger_entry(event, :duration, duration) + assert_semantic_logger_entry(event, :time, time) + assert_semantic_logger_entry(event, :exception, exception) + assert_semantic_logger_entry(event, :backtrace, backtrace) + assert_semantic_logger_entry(event, :payload, payload) + + if message_includes + assert_includes( + event.message, + message_includes, + -> { "Expected message to include '#{message_includes}' in log event #{event.inspect}" } + ) + end if payload_includes - payload_includes.each_pair do |key, expected_value| - value = event.payload[key] - if expected_value.nil? - assert_nil value, -> { "Mismatched key: #{key.inspect} in log payload: #{event.payload} for message: '#{msg}'" } - else - assert_equal expected_value, value, -> { "Mismatched key: #{key.inspect} in log payload: #{event.payload} for message: '#{msg}'" } - end + payload_includes.each_pair do |key, expected| + actual = event.payload[key] + assert_semantic_logger_entry(event, "payload #{name}", expected, actual) end - elsif payload - assert_equal payload, event.payload, -> { "Mismatched log payload: #{event.payload} for message: '#{msg}'" } end - assert_equal thread_name, event.thread_name, -> { "Mismatched thread_name for message: '#{msg}'" } if thread_name - assert_equal tags, event.tags, -> { "Mismatched tags for message: '#{msg}'" } if tags - assert_equal named_tags, event.named_tags, -> { "Mismatched named_tags for message: '#{msg}'" } if named_tags - assert_equal context, event.context, -> { "Mismatched context for message: '#{msg}'" } if context - assert_equal metric, event.metric, -> { "Mismatched metric for message: '#{msg}'" } if metric - assert_equal metric_amount, event.metric_amount, -> { "Mismatched metric_amount for message: '#{msg}'" } if metric_amount - assert_equal dimensions, event.dimensions, -> { "Mismatched dimensions for message: '#{msg}'" } if dimensions + if exception_includes + payload_includes.each_pair do |key, expected| + actual = event.exception.send(key) + assert_semantic_logger_entry(event, "Exception #{name}", expected, actual) + end + end + end + + private + + def assert_semantic_logger_entry(event, name, expected, actual = event.send(name)) + return if expected.nil? + + case expected + when :nil + assert_nil actual, "Expected nil #{name} for log event: #{event.to_h.inspect}" + when Class + assert actual.is_a?(expected), -> { "Type #{expected} expected for #{name} in log event: #{event.to_h.inspect}" } + else + assert_equal expected, actual, "Mismatched #{name} for log event: #{event.to_h.inspect}" + end end end end diff --git a/test/logger_test.rb b/test/logger_test.rb index f2988aff..1b761a7e 100644 --- a/test/logger_test.rb +++ b/test/logger_test.rb @@ -20,190 +20,6 @@ def self.call(log) # SemanticLogger::LEVELS.each do |level| [:debug].each do |level| describe "##{level}" do - describe "positional parameter" do - it "logs message" do - logger.send(level, "hello world") - - assert log = log_message - assert_equal "hello world", log.message - end - - it "adds message from block" do - logger.send(level, "hello world") { "Calculations" } - - assert log = log_message - assert_equal "hello world -- Calculations", log.message - end - - it "logs message and payload" do - logger.send(level, "hello world", payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs simple metric" do - metric_name = "/my/own/metric" - logger.send(level, "hello world", metric: metric_name) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal metric_name, log.metric - assert_nil log.payload - assert_nil log.duration - end - - it "logs duration" do - logger.send(level, "hello world", duration: 20) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal 20, log.duration - assert_nil log.payload - assert_nil log.metric - end - - it "logs with backtrace" do - SemanticLogger.stub(:backtrace_level_index, 0) do - logger.send(level, "hello world", payload) { "Calculations" } - - assert log = log_message - assert_equal "hello world -- Calculations", log.message - assert_equal payload, log.payload - assert log.backtrace - assert log.backtrace.size.positive?, log.backtrace - end - end - - it "logs with backtrace and exception" do - SemanticLogger.stub(:backtrace_level_index, 0) do - exc = RuntimeError.new("Test") - logger.send(level, "hello world", exc) - - assert log = log_message - assert_equal "hello world", log.message - assert log.backtrace - assert log.backtrace.size.positive?, log.backtrace - - assert log.exception - refute log.exception.backtrace - assert_equal "RuntimeError", log.exception.class.name - end - end - end - - describe "keyword arguments" do - it "logs message" do - logger.send(level, message: "hello world") - - assert log = log_message - assert_equal "hello world", log.message - end - - it "logs payload and message" do - logger.send(level, message: "hello world", payload: payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs payload and message without payload arg" do - logger.send(level, "hello world", **payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs message without modifying the supplied hash" do - details = {message: "hello world"} - logger.send(level, details) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal "hello world", details[:message] - end - - it "logs payload and message from block" do - logger.send(level) { {message: "hello world", payload: payload} } - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - end - - it "logs payload from block" do - logger.send(level) { {"test_key1" => "hello world", "test_key2" => payload} } - - assert log = log_message - assert_equal log.payload, "test_key1" => "hello world", "test_key2" => payload - end - - it "logs payload only" do - logger.send(level, payload: payload) - - assert log = log_message - refute log.message - assert_equal payload, log.payload - end - - it "logs duration" do - logger.send(level, duration: 123.44, message: "hello world", payload: payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - assert_equal 123.44, log.duration - end - - it "does not log when below min_duration" do - logger.send(level, min_duration: 200, duration: 123.45, message: "hello world", payload: {tracking_number: "123456", even: 2, more: "data"}) - - refute log_message - end - - it "logs metric" do - metric_name = "/my/custom/metric" - logger.send(level, metric: metric_name, duration: 123.44, message: "hello world", payload: payload) - - assert log = log_message - assert_equal "hello world", log.message - assert_equal payload, log.payload - assert_equal 123.44, log.duration - assert_equal metric_name, log.metric - end - - describe "metrics appender" do - let :appender do - InMemoryMetricsAppender.new - end - - it "logs metric only events" do - metric_name = "/my/custom/metric" - logger.send(level, metric: metric_name, dimensions: dimensions) - - assert log = log_message - assert_equal metric_name, log.metric - assert_equal dimensions, log.dimensions - refute log.message - end - end - - it "for compatibility handles random payload logged as keyword arguments" do - logger.send(level, payload) - - assert log = log_message - assert_equal "Message from payload", log.message - refute log.exception - refute log.metric - payload_without_message = payload.dup - payload_without_message.delete(:message) - assert_equal payload_without_message, log.payload - end - end - describe "#filter" do describe "at the appender level" do it "Proc" do diff --git a/test/semantic_logger_logging_test.rb b/test/semantic_logger_logging_test.rb new file mode 100644 index 00000000..c8e5090c --- /dev/null +++ b/test/semantic_logger_logging_test.rb @@ -0,0 +1,821 @@ +require_relative "test_helper" + +# API tests for SemanticLogger +class SemanticLoggerLoggingTest < Minitest::Test + describe SemanticLogger do + let :logger do + SemanticLogger["TestLogger"] + end + + [:trace, :debug, :info, :warn].each_with_index do |level, level_index| + describe "##{level}" do + describe "positional arguments logs" do + it "message only" do + events = semantic_logger_events do + logger.send(level, "hello world") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "combines message from block" do + events = semantic_logger_events do + logger.send(level, "hello world") { "Calculations" } + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world -- Calculations", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with implied payload" do + events = semantic_logger_events do + logger.send(level, "hello world", user_id: 1234) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "implied payload only" do + events = semantic_logger_events do + logger.send(level, user_id: 1234) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with implied payload and duration" do + events = semantic_logger_events do + logger.send(level, "hello world", user_id: 1234, duration: 20.3) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.3, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with explicit payload" do + events = semantic_logger_events do + logger.send(level, "hello world", payload: { user_id: 1234 }) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "explicit payload only" do + events = semantic_logger_events do + logger.send(level, payload: { user_id: 1234 }) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message and payload from block" do + events = semantic_logger_events do + logger.send(level) do + { message: "hello world", payload: { user_id: 123 } } + end + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 123 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + end + + it "payload from block" do + events = semantic_logger_events do + logger.send(level) do + { "test_key1" => "hello world", "test_key2" => "value2" } + end + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: { "test_key1" => "hello world", "test_key2" => "value2" }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + end + + it "message from hash does not modify hash" do + details = { message: "hello world" } + events = semantic_logger_events do + logger.send(level, details) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + assert_equal "hello world", details[:message] + end + + it "message and explicit payload from hash does not modify hash" do + details = { message: "hello world", payload: { user_id: 1230 } } + events = semantic_logger_events do + logger.send(level, details) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 1230 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + assert_equal "hello world", details[:message] + end + + it "message and implied payload from hash does not modify hash" do + details = { message: "hello world", user_id: 1230 } + events = semantic_logger_events do + logger.send(level, details) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 1230 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + assert_equal "hello world", details[:message] + assert_equal 1230, details[:user_id] + end + + it "message with explicit payload and duration" do + events = semantic_logger_events do + logger.send(level, "hello world", payload: { user_id: 1234 }, duration: 20.7) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.7, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "explicit payload and metric only" do + events = semantic_logger_events do + logger.send(level, payload: { user_id: 1234 }, metric: "sidekiq.job.failed") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.job.failed", + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with metric" do + events = semantic_logger_events do + logger.send(level, "hello world", metric: "sidekiq.job.failed") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.job.failed", + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "metric only" do + events = semantic_logger_events do + logger.send(level, metric: "sidekiq.job.failed") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.job.failed", + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with metric and metric_amount" do + events = semantic_logger_events do + logger.send(level, "hello world", metric: "sidekiq.queue.latency", metric_amount: 2.5) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: "sidekiq.queue.latency", + metric_amount: 2.5, + dimensions: :nil, + time: Time + ) + end + + it "message with implied duration" do + events = semantic_logger_events do + logger.send("measure_#{level}".to_sym, "hello world") { sleep 0.1 } + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: Numeric, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with explicit duration" do + events = semantic_logger_events do + logger.send(level, "hello world", duration: 20.3) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.3, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + + end + + it "message with backtrace" do + SemanticLogger.stub(:backtrace_level_index, 0) do + events = semantic_logger_events do + logger.send(level, "hello world", request_id: 1234) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: { request_id: 1234 }, + exception: :nil, + backtrace: Array, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + assert events.first.backtrace.size.positive?, events.first.backtrace + end + end + + it "message with exception" do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, "hello world", exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "exception only" do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: :nil, + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with backtrace and exception" do + SemanticLogger.stub(:backtrace_level_index, 0) do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, "hello world", exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + assert events.first.backtrace + assert events.first.backtrace.size.positive?, events.first.backtrace + end + end + + it "does not log when below min_duration" do + events = semantic_logger_events do + logger.send(level, "hello world", min_duration: 200, duration: 123.45, payload: { tracking_number: "123456", even: 2, more: "data" }) + end + + assert events.empty? + end + end + + describe "message as keyword argument" do + it "message only" do + events = semantic_logger_events do + logger.send(level, message: "hello world") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "combines message from block" do + events = semantic_logger_events do + logger.send(level, message: "hello world") { "Calculations" } + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world -- Calculations", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with explicit payload and duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", payload: { user_id: 1234 }, duration: 20.7) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 20.7, + payload: { user_id: 1234 }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "message with backtrace and exception" do + SemanticLogger.stub(:backtrace_level_index, 0) do + exc = RuntimeError.new("Test") + events = semantic_logger_events do + logger.send(level, message: "hello world", exception: exc) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: :nil, + payload: :nil, + exception: exc, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + assert events.first.backtrace + assert events.first.backtrace.size.positive?, events.first.backtrace + end + end + + it "does not log when below min_duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", min_duration: 200, duration: 123.45, payload: { tracking_number: "123456", even: 2, more: "data" }) + end + + assert events.empty? + end + + it "logs above min_duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", min_duration: 100, duration: 123.45, tracking_number: "123456", even: 2, more: "data") + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 123.45, + payload: { tracking_number: "123456", even: 2, more: "data" }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + + it "logs at min_duration" do + events = semantic_logger_events do + logger.send(level, message: "hello world", min_duration: 100, duration: 100.0, payload: { tracking_number: "123456", even: 2, more: "data" }) + end + + assert_equal 1, events.size + assert_semantic_logger_event( + events.first, + name: "TestLogger", + level: level, + level_index: level_index, + message: "hello world", + thread_name: Thread.current.name, + duration: 100.0, + payload: { tracking_number: "123456", even: 2, more: "data" }, + exception: :nil, + tags: [], + named_tags: {}, + context: :nil, + metric: :nil, + metric_amount: :nil, + dimensions: :nil, + time: Time + ) + end + end + end + end + end +end diff --git a/test/test_helper.rb b/test/test_helper.rb index db334010..febf85cb 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -18,6 +18,9 @@ require_relative "in_memory_appender_helper" require "amazing_print" +# Add Semantic Logger helpers for Minitest +Minitest::Test.include SemanticLogger::Test::Minitest + # Minitest::Reporters.use! Minitest::Reporters::SpecReporter.new class Minitest::Test # Use AwesomePrint to display diffs