Add child logger with instance named tags support

CHANGELOG.md

@@ -5,6 +5,8 @@ This project adheres to [Semantic Versioning](http://semver.org/).
 
 ## [unreleased]
 
+- Add child logger with instance named tags support
+
 ## [4.17.0]
 
 - Correct `source_code_uri` URL

docs/api.md

@@ -633,4 +633,18 @@ Or, when using a Gemfile:
 gem "semantic_logger", require: "semantic_logger/sync"
 ~~~
 
+### Child Logger
+
+It is possible to create child loggers with pre-set instance tags.
+Any log message emitted by a logger with pre-set instance tags will include these tags along with the message data.
+
+~~~ruby
+logger = SemanticLogger["MyClass"]
+child_logger1 = logger.child(tag1: "value1", tag2: "value2")
+child_logger2 = child_logger1.child(tag3: "value3")
+
+# Will include tag1, tag2, tag3 and tag4 in the output
+child_logger2.info("Some message", tag4: "value4")
+~~~
+
 ### [Next: Testing ==>](testing.html)

lib/semantic_logger/base.rb

@@ -6,8 +6,18 @@
 #
 module SemanticLogger
   class Base
+    # Creates a copy of an existing logger.
+    # This method can be overridden by subclasses to provide a specialized implementation.
+    # `child` logger uses this method.
+    def self.copy(instance)
+      raise ArgumentError, "Cannot copy instances different from #{self}" if instance.class != self
+
+      instance.dup
+    end
+
     # Class name to be logged
     attr_accessor :name, :filter
+    attr_reader :instance_named_tags
 
     # Set the logging level for this logger
     #
@@ -250,6 +260,21 @@ def should_log?(log)
       meets_log_level?(log) && !filtered?(log)
     end
 
+    # Creates a new logger with the given instance named tags
+    def child(**named_tags)
+      new_named_tags = instance_named_tags.merge(named_tags)
+      new_logger = self.class.copy(self)
+      new_logger.instance_named_tags = new_named_tags
+      new_logger
+    end
+
+    protected
+
+    def instance_named_tags=(named_tags)
+      # Prevent accidental mutation of log named tags
+      @instance_named_tags = named_tags.dup.freeze
+    end
+
     private
 
     # Initializer for Abstract Class SemanticLogger::Base
@@ -275,7 +300,7 @@ def should_log?(log)
     #          (/\AExclude/ =~ log.message).nil?
     #        end
     #      end
-    def initialize(klass, level = nil, filter = nil)
+    def initialize(klass, level = nil, filter = nil, instance_named_tags = {})
       # Support filtering all messages to this logger instance.
       unless filter.nil? || filter.is_a?(Regexp) || filter.is_a?(Proc) || filter.respond_to?(:call)
         raise ":filter must be a Regexp, Proc, or implement :call"
@@ -290,6 +315,7 @@ def initialize(klass, level = nil, filter = nil)
       else
         self.level = level
       end
+      self.instance_named_tags = instance_named_tags
     end
 
     # Return the level index for fast comparisons
@@ -325,7 +351,7 @@ def log_internal(level, index, message = nil, payload = nil, exception = nil)
         payload = nil
       end
 
-      log = Log.new(name, level, index)
+      log = Log.new(name, level, index, instance_named_tags)
       should_log =
         if exception.nil? && payload.nil? && message.is_a?(Hash)
           # All arguments as a hash in the message.
@@ -376,7 +402,7 @@ def measure_internal(level, index, message, params)
         exception = e
       ensure
         # Must use ensure block otherwise a `return` in the yield above will skip the log entry
-        log = Log.new(name, level, index)
+        log = Log.new(name, level, index, instance_named_tags)
         exception ||= params[:exception]
         message   = params[:message] if params[:message]
         duration  =

lib/semantic_logger/formatters/raw.rb

@@ -64,6 +64,10 @@ def tags
       # Named Tags
       def named_tags
         hash[:named_tags] = log.named_tags if log.named_tags && !log.named_tags.empty?
+        # TODO: Test
+        # TODO: Different hash entry instead?
+        # Always overrides thread named_tags with instance_named_tags
+        hash[:named_tags] = hash.fetch(:named_tags, {}).merge(log.instance_named_tags) if log.instance_named_tags && !log.instance_named_tags.empty?
       end
 
       # Duration

lib/semantic_logger/log.rb

@@ -28,6 +28,9 @@ module SemanticLogger
   # tags
   #   Any tags active on the thread when the log call was made
   #
+  # instance_named_tags
+  #   Any named tags active on the logger instance when the log call was made
+  #
   # level_index
   #   Internal index of the log level
   #
@@ -55,16 +58,17 @@ class Log
 
     attr_accessor :level, :level_index, :name, :message, :time, :duration,
                   :payload, :exception, :thread_name, :backtrace,
-                  :tags, :named_tags, :context,
+                  :tags, :named_tags, :instance_named_tags, :context,
                   :metric, :metric_amount, :dimensions
 
-    def initialize(name, level, index = nil)
+    def initialize(name, level, index = nil, instance_named_tags = {})
       @level       = level
       @thread_name = Thread.current.name
       @name        = name
       @time        = Time.now
       @tags        = SemanticLogger.tags
       @named_tags  = SemanticLogger.named_tags
+      @instance_named_tags = instance_named_tags
       @level_index = index.nil? ? Levels.index(level) : index
     end
 

lib/semantic_logger/loggable.rb

@@ -42,7 +42,7 @@ def self.included(base)
 
         # Returns [SemanticLogger::Logger] class level logger
         def self.logger
-          @semantic_logger ||= SemanticLogger[self]
+          @semantic_logger ||= SemanticLogger[self].child(**@logger_instance_named_tags)
         end
 
         # Replace instance class level logger
@@ -114,6 +114,10 @@ def #{method_name}(*args, &block)
         true
       end
 
+      def logger_child(**named_tags)
+        @logger_instance_named_tags = named_tags
+      end
+
       private
 
       # Dynamic Module to intercept method calls for measuring purposes.

lib/semantic_logger/logger.rb

@@ -56,7 +56,11 @@ def self.sync?
     #    regular expression. All other messages will be ignored
     #    Proc: Only include log messages where the supplied Proc returns true
     #          The Proc must return true or false
-    def initialize(klass, level = nil, filter = nil)
+    #
+    #  instance_named_tags
+    #    Named tags to be added to all log messages for this logger instance
+    #    Default: {}
+    def initialize(klass, level = nil, filter = nil, instance_named_tags = {})
       super
     end
 

lib/semantic_logger/subscriber.rb

@@ -108,8 +108,12 @@ def console_output?
     #   metrics: [Boolean]
     #     Whether to log metric only entries with this subscriber.
     #     Default: false
+    #
+    #   instance_named_tags: [Hash]
+    #     Named tags to be added to all log messages for this subscriber
+    #     Default: {}
     def initialize(level: nil, formatter: nil, filter: nil, application: nil, environment: nil, host: nil,
-                   metrics: false, &block)
+                   metrics: false, instance_named_tags: {}, &block)
       self.formatter = block || formatter
       @application   = application
       @environment   = environment
@@ -118,7 +122,7 @@ def initialize(level: nil, formatter: nil, filter: nil, application: nil, enviro
 
       # Subscribers don't take a class name, so use this class name if a subscriber
       # is logged to directly.
-      super(self.class, level, filter)
+      super(self.class, level, filter, instance_named_tags)
     end
 
     # Return the level index for fast comparisons.

lib/semantic_logger/test/capture_log_events.rb

@@ -20,6 +20,12 @@ module Test
     #     end
     #   end
     class CaptureLogEvents < SemanticLogger::Subscriber
+      def self.copy(instance)
+        new_instance = super
+        new_instance.events = []
+        new_instance
+      end
+
       attr_accessor :events
 
       # By default collect all log levels, and collect metric only log events.

lib/semantic_logger/test/minitest.rb

@@ -20,12 +20,13 @@ def semantic_logger_events(deprecated_klass = nil, klass: deprecated_klass, sile
         logger.events
       end
 
+      # TODO: Add instance_named_tags
       # 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,
+                                       instance_named_tags: nil, level_index: nil, duration: nil, time: nil,
                                        metric: nil, metric_amount: nil, dimensions: nil)
         assert event, "No log event occurred"
 
@@ -35,6 +36,7 @@ def assert_semantic_logger_event(event, level: nil, name: nil, message: nil, mes
         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, :instance_named_tags, instance_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)

test/loggable_test.rb

@@ -27,6 +27,14 @@ class TestAttribute
     include SemanticLogger::Loggable
   end
 
+  class TestChildClassLogger
+    include SemanticLogger::Loggable
+
+    TAG_DATA = {tag1: "value1", tag2: "value2"}.freeze
+
+    logger_child(**TAG_DATA)
+  end
+
   describe SemanticLogger::Loggable do
     describe "inheritance" do
       it "should give child classes their own logger" do
@@ -79,5 +87,11 @@ class TestAttribute
         TestAttribute.new.logger.is_a?(SemanticLogger::Logger)
       end
     end
+
+    describe "sample child class logger" do
+      it "has instance named tags set" do
+        assert_equal TestChildClassLogger::TAG_DATA, TestChildClassLogger.logger.instance_named_tags
+      end
+    end
   end
 end

test/logger_test.rb

@@ -153,5 +153,38 @@ def self.call(log)
         end
       end
     end
+
+    describe ".child" do
+      it "creates a child logger with instance named tags merged with parent" do
+        parent_tag_data = {parent_tag: "parent_value"}
+        child_tag_data = {tag1: "value1", tag2: "value2"}
+        parent_logger = logger.child(**parent_tag_data)
+        child_logger = parent_logger.child(**child_tag_data)
+
+        child_logger.info("hello world")
+
+        assert_equal parent_tag_data, parent_logger.instance_named_tags
+        assert_equal parent_tag_data.merge(child_tag_data), child_logger.instance_named_tags
+      end
+
+      it "outputs log entries with different instance named tags from the parent" do
+        parent_tag_data = {parent_tag: "parent_value"}
+        child_tag_data = {tag1: "value1", tag2: "value2"}
+        parent_logger = logger.child(**parent_tag_data)
+        child_logger = parent_logger.child(**child_tag_data)
+
+        parent_logger.info("hello parent")
+
+        assert log_parent = parent_logger.events.first
+        assert_equal "hello parent", log_parent.message
+        assert_equal parent_tag_data, log_parent.instance_named_tags
+
+        child_logger.info("hello child")
+
+        assert log_child = child_logger.events.first
+        assert_equal "hello child", log_child.message
+        assert_equal parent_tag_data.merge(child_tag_data), log_child.instance_named_tags
+      end
+    end
   end
 end