Fixes #216

Completely refactor tests that call the logging api.
Include fix from @bethesque for payload test case.

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]
 

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        = {}

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

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