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 👍