Feature Suggestion: Per-logger tags

[grncdr]

What do you think about allowing individual logger instances to carry their own tags? This would be particularly useful when loggers are owned by an object with an identity (e.g. an ActiveRecord instance).

To clarify what I mean, consider the following example:

class Cart < Entity
  include SemanticLogging::Loggable

  def add_item(item_id, quantity)
    SemanticLogger.tagged(cart_id: self.id) do
      InventoryService.reserve_items(item_id: item_id, quantity: quantity, reserved_by: self)
      # do stuff, maybe a lot of stuff
      logger.debug('added item', item_id: item_id, quantity: quantity)
    end
  end
   
  def remove_item(item_id, quantity)
    SemanticLogger.tagged(cart_id: self.id) do
      InventoryService.cancel_item_reservation(item_id: item_id, quantity: quantity, reserved_by: self)
      # again do a variety of things here
      logger.debug('removed item', item_id: item_id, quantity: quantity)
    end
  end
end

As the number of methods grows, repeating SemanticLogger.tagged(cart_id: self.id) becomes tedious and leads to a lot of indenting. It also means all logging messages of the InventoryService are tagged with the current cart ID, which isn't always desirable.

What would be nice is if I could write this:

class Cart < Entity
  include SemanticLogging::Loggable

  def logger
    @logger ||= super.with_tags(cart_id: self.id)
  end

  def add_item(item_id, quantity)
    InventoryService.reserve_items(item_id: item_id, quantity: quantity, reserved_by: self)
    # do more stuff here
    logger.debug('added item', item_id: item_id, quantity: quantity)
  end
   
  def remove_item(item_id, quantity)
    InventoryService.cancel_item_reservation(item_id: item_id, quantity: quantity, reserved_by: self)
    # do other stuff here
    logger.debug('removed item', item_id: item_id, quantity: quantity)
  end
end

And in case I want the current #tagged behaviour:

class Cart < Entity
  def add_item(other_cart)
    logger.tagged do
      # messages in this block are tagged with cart_id
      InventoryService.reserve_items(item_id: item_id, quantity: quantity, reserved_by: self)
      # do more stuff here
      logger.debug('added item', item_id: item_id, quantity: quantity)
    end
  end
end

[reidmorrison]

Yes, setting the logging tags on a per logger instance is a very interesting use case.

Rather than override the logger we could also setup the logger instance when the job is instantiated. Both approaches work well.

In this case separating tags from named_tags may be worthwhile, or otherwise detect if a hash or array is being assigned.

class Cart < Entity
  include SemanticLogging::Loggable

  def initialize
    logger.named_tags = {cart_id: self.id}
  end

  def add_item(item_id, quantity)
    InventoryService.reserve_items(item_id: item_id, quantity: quantity, reserved_by: self)
    # do more stuff here
    logger.debug('added item', item_id: item_id, quantity: quantity)
  end
   
  def remove_item(item_id, quantity)
    InventoryService.cancel_item_reservation(item_id: item_id, quantity: quantity, reserved_by: self)
    # do other stuff here
    logger.debug('removed item', item_id: item_id, quantity: quantity)
  end
end

The hardest part here is remaining backward compatible, with the existing methods that every logger instance already honors:

    def tagged(*tags, &block)
      # Allow named tags to be passed into the logger
      if tags.size == 1
        tag = tags[0]
        return yield if tag.nil? || tag == ""

        return tag.is_a?(Hash) ? SemanticLogger.named_tagged(tag, &block) : SemanticLogger.fast_tag(tag.to_s, &block)
      end

      # Need to flatten and reject empties to support calls from Rails 4
      new_tags = tags.flatten.collect(&:to_s).reject(&:empty?)
      SemanticLogger.tagged(*new_tags, &block)
    end

    # :nodoc:
    alias with_tags tagged

    # :nodoc:
    def tags
      SemanticLogger.tags
    end

    def named_tags
      SemanticLogger.named_tags
    end

The above behavior just passes the tags through to the thread specific log tags. Changing .with_tags or .tagged would significantly change the existing API. This would result in a lot of very surprised end users who the behavior they rely on suddenly changes.

Alternatively, we could create a new api to hold tags on a per logger instance basis that does not use the api .with_tags or .tagged.

Something like:

def named_tags=(named_tags)
 (@named_tags ||= {}).merge(named_tags)
end

And then when the named tags are returned

def named_tags
 SemanticLogger.named_tags.merge(@named_tags)
end

The next step is to verify that when the Log event is generated that it uses the named tags from this instance of the logger.

Unlike the SemanticLogger.tagged(cart_id: self.id) do block, log entries from other loggers in that block will not include these tags, only calls to the current logger. Not sure if that would be expected behavior.

Feel free to play around with it and look forward to your pull request.

[Shankar1598]

Wow I was looking for the exact same thing

[theocodes]

Hey @reidmorrison @grncdr 👋

This has been inactive for a while but the solutions discussed here would allow me to tidy up some bits in my use-case.

I'm happy to pick this up and get it over the line if you still agree it would be valuable.

Please let me know,
Thanks!

[reidmorrison]

@theocodes definitely open to any efforts to add this capability.

If we can figure out a solution that does not break the current behavior would be ideal, otherwise we could make it part of a major version upgrade?

I personally do not call these instance methods, but not sure if anyone else does:

    def tags
      SemanticLogger.tags
    end

    def named_tags
      SemanticLogger.named_tags
    end

[theocodes]

Thanks @reidmorrison

I'll have a play around and report back in the next few days 👍

[ag-TJNII]

I was surprised that tags are thread-global and that logger.tagged {} is actually pushing the tags to a global list, then popping them (1).

Here's an example:

require 'securerandom'
require 'semantic_logger'

SemanticLogger.add_appender(io: $stdout, formatter: :color)

class SomeObject
  attr_reader :logger

  def initialize(id:)
    @id = id

    @logger = SemanticLogger[SecureRandom.uuid]
    logger.push_tags(id: @id)
    puts "LOGGER: #{logger.object_id} TAGS: #{logger.tags}"
  end

  def do_a_thing
    logger.info("Doing a thing")
  end
end

class OtherClass
  include SemanticLogger::Loggable

  def do_a_thing
    logger.info("Doing a thing")
  end
end

objs = Array.new(3) { SomeObject.new(id: SecureRandom.uuid) }
objs.map(&:do_a_thing)

objs.map do |obj|
  Thread.new do
    obj.do_a_thing
  end
end.each(&:join)

OtherClass.new.do_a_thing

LOGGER: 60 TAGS: ["{:id=>\"8c8fa882-f83b-4ce2-b118-07dede897403\"}"]
LOGGER: 80 TAGS: ["{:id=>\"8c8fa882-f83b-4ce2-b118-07dede897403\"}", "{:id=>\"64b0f53a-c0f2-4aab-966e-f3e32c6cf413\"}"]
LOGGER: 100 TAGS: ["{:id=>\"8c8fa882-f83b-4ce2-b118-07dede897403\"}", "{:id=>\"64b0f53a-c0f2-4aab-966e-f3e32c6cf413\"}", "{:id=>\"87967631-b229-47fc-87c5-4c5317fd4749\"}"]
2025-01-28 11:25:37.072645 I [1424726:120] [{:id=>"8c8fa882-f83b-4ce2-b118-07dede897403"}] [{:id=>"64b0f53a-c0f2-4aab-966e-f3e32c6cf413"}] [{:id=>"87967631-b229-47fc-87c5-4c5317fd4749"}] b06ece1f-3a04-43e3-85fa-8d971364beb2 -- Doing a thing
2025-01-28 11:25:37.072702 I [1424726:120] [{:id=>"8c8fa882-f83b-4ce2-b118-07dede897403"}] [{:id=>"64b0f53a-c0f2-4aab-966e-f3e32c6cf413"}] [{:id=>"87967631-b229-47fc-87c5-4c5317fd4749"}] 7d67743d-a0dd-4beb-8012-71328057886b -- Doing a thing
2025-01-28 11:25:37.072711 I [1424726:120] [{:id=>"8c8fa882-f83b-4ce2-b118-07dede897403"}] [{:id=>"64b0f53a-c0f2-4aab-966e-f3e32c6cf413"}] [{:id=>"87967631-b229-47fc-87c5-4c5317fd4749"}] 5b83d551-c870-4c56-8bee-c6393223b27d -- Doing a thing
2025-01-28 11:25:37.073314 I [1424726:140] b06ece1f-3a04-43e3-85fa-8d971364beb2 -- Doing a thing
2025-01-28 11:25:37.073442 I [1424726:160] 7d67743d-a0dd-4beb-8012-71328057886b -- Doing a thing
2025-01-28 11:25:37.073613 I [1424726:180] 5b83d551-c870-4c56-8bee-c6393223b27d -- Doing a thing
2025-01-28 11:25:37.073829 I [1424726:120] [{:id=>"8c8fa882-f83b-4ce2-b118-07dede897403"}] [{:id=>"64b0f53a-c0f2-4aab-966e-f3e32c6cf413"}] [{:id=>"87967631-b229-47fc-87c5-4c5317fd4749"}] OtherClass -- Doing a thing

So even though I've instantiated 3 Logger objects, they're still sharing tags, and the OtherClass got the tags as well. However, when a launch a thread I lose the tags. This is not what I would expect, calling .push_tags() on the individual instances.

I can get the functionality I want with this wrapper class:

class TaggedLogger < SemanticLogger::Logger
  def initialize(name:, tags: {})
    @tags = tags
    super(name)
  end

  SemanticLogger::LEVELS.each do |level|
    define_method(level) do |*args, **kwargs|
      SemanticLogger.tagged(@tags) do
        super(*args, **kwargs)
      end
    end
  end
end

However, now for each log call it is:

• Adding the tags to a global list
• Performing the log
• Removing the tags from a global list

which seems inefficient.

Chesterton's Fence, I don't understand the reason tags were implemented this way. However, for a backwards compatible implementation perhaps adding a unique class that supports instance tags is the answer. If you instantiate or mix in a taggable logger you get per-instance tags, and the current objects maintain the old behavior.

(1) https://github.com/reidmorrison/semantic_logger/blob/master/lib/semantic_logger/semantic_logger.rb#L345-L360