Add child logger with instance named tags support

[Fire-Dragon-DoL]

Issue #165

Changelog

• Add child logger with instance named tags support

Description of changes

A new method is added called child which creates a copy of the current logger and sets instance named tags on the logger. These tags will be included with every log message output by the child logger.
Differently from named_tags, these tags are strictly tied to the logger instance, not to thread variables. This allows creating multiple nested loggers to achieve logging of complex structured data, while keeping the code simple. An example of this could be:

def create
  clogger = logger.child(user_id: user.id, flight_id: @flight.id)
  result_id = create_some_stuff
  clogger.debug("Created successfully", id: result_id)
rescue => err
  clogger.error("Bad failure", err: err.message)
end

Name Alternatives

I personally don't love the name child for this method, I followed what Ougai did. Some possibly better alternatives:

• with_payload
• with_context
• with

Discussion Points

Thread named tags are treated separately and they could overlap with the message payload. I didn't want to touch/involve explicit interaction with thread named tags because it could cause a lot of confusion. I would go further and say that if instance named tags are used, thread named tags should be avoided, otherwise there are questions like:

def create
  child_logger = logger.child(tag1: "bar")
  child_logger.tagged(tag1: "foo") do
    child_logger.info "Message"
  end
end

Should this code output tag1: "foo" or tag1: "bar"? I don't think there is a clear answer for this.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

[ag-TJNII]

This might get some pushback as it's a behavior change. As the child has a independent change set this will change the cross-object tag behavior, correct?

[ag-TJNII]

This is also going to change behavior to instantiate a new (well, dup'd) object every time when previously it returned a cached object. This could be a performance issue in some codebases.

[Fire-Dragon-DoL]

This might get some pushback as it's a behavior change. As the child has a independent change set this will change the cross-object tag behavior, correct?

I do not understand this statement, forgive me. I suspect you have more context about the codebase and so you know more about the object interactions, so I'm missing something to understand this statement.
I know it's a lot to ask, but could you provide me a code example to help me understand what you are referring to?

This is also going to change behavior to instantiate a new (well, dup'd) object every time when previously it returned a cached object. This could be a performance issue in some codebases.

There is a behavior change, but the caching will still take place, since SemanticLogger[self] already returns a new logger copy every time and doesn't do any caching:

# definition of SemanticLogger[self]
  def self.[](klass)
    Logger.new(klass)
  end

Given that @semantic_logger ||= SemanticLogger[self].child(**@logger_child_named_tags) does effectively instantiate twice the amount of objects (2), but it still performs the caching: first it creates the child logger, then it does the ||= operation.

I can definitely optimize this further, I didn't want to increase the complexity of the change by introducing more constructor parameters.

[ag-TJNII]

Creating a new object could have performance impacts in client codebases. If there's a codebase that calls this method with high frequency, say on every GET in a high-volume app, currently it's just a cache lookup which will be performant. Changing it to create a new object every time will have a performance impact that could surprise users, depending how they're calling this method.

[ag-TJNII]

Shouldn't this be merging log.tags?

https://github.com/reidmorrison/semantic_logger/blob/master/lib/semantic_logger/log.rb#L19-L20

  # payload
  #   Optional Hash or Ruby Exception object to be logged

https://github.com/reidmorrison/semantic_logger/blob/master/lib/semantic_logger/log.rb#L28-L29

  # tags
  #   Any tags active on the thread when the log call was made

[Fire-Dragon-DoL]

I see what you are saying. Let me think about this a bit, I did not use the original tags because they come from threads, so I used a separate tag attribute (child_named_tags). I also didn't introduce support for "unnamed tags" in the child tags because I thought the support for "unnamed tags" was to mainly stay compatible with rails tagged method, but for child is not really necessary

[Fire-Dragon-DoL]

OK after reading your comments and going through the PR, I understood the codebase a lot more. I made a change (in a separate commit) that overhauls the approach quite heavily. It touches more files, but I think it does everything in a better way.

I think I need to add a test for the formatters using the named tags, and cover some TODO items.

The additional commit will be squashed if this approach makes more sense.

What do you think?

[ag-TJNII]

I think it would be good to break this into 3 tests:

• That it creates a new logger child object (I'd check that it's a new object).
• That the child supports adding new tags.
• That adding tags to the new child doesn't modify the tags on the parent.

[Fire-Dragon-DoL]

Thank you so much for the feedback (responding to this comment but referring to all of them).
This is super valuable.

I think I can address every point you raised, I'll start working on this and come back when I have questions.

[Fire-Dragon-DoL]

That it creates a new logger child object (I'd check that it's a new object).

I'm open to putting this in a test, but in reality this is an implementation detail. I wouldn't want people to depend on the fact that it creates an object with a different object_id, it's not really what this change is about. Instead I think your third point here is the thing that I really should address:

That adding tags to the new child doesn't modify the tags on the parent.

This test is really the behavior that needs to be verified: the child should not affect the parent.

That the child supports adding new tags.

Do you mean that child_named_tags is editable?

[ag-TJNII]

this is an implementation detail.

Yes, but in checking that it's a new object the test will implicitly check that the attributes are independent. That's the value I'm suggesting in the test.

[Fire-Dragon-DoL]

This could be controversial. It won't break existing codebases, but I found unreasonable to add yet another "tags" field (tags, named_tags, instance_named_tags). I'm ok if we want to proceed that way, but I think this yields a better experience.

[ag-TJNII]

This is getting into why I suggested making a different logger object for this, which I never heard back about from the community. I was thinking keep the old behavior under the old objects, and allow users to instantiate a new logger type with the tag behavior we're discussing here. That would allow for flattening of the tags structures.

[Fire-Dragon-DoL]

I think your point is valid, however I thought semantic_logger attempted to stay API-compatible with TaggedLogger. Removing the thread-based tags would effectively break that compatibility (cannot use the block syntax anymore). In this way it's possible to still be compatible and expand the API

[Fire-Dragon-DoL]

Otherwise parent and child logger end up with the same events, which makes no sense

[thdaraujo]

Hi, @reidmorrison! Thanks for all the work you do on this gem, and sorry to bother you!

Would you have a minute to give your opinion on this feature? We think it would be a nice addition, but curious about your thoughts.

Thank you! 🙏

[reidmorrison]

There is a lot to take in. I do like the idea of adding tags to a specific logger instance, so if we start with the interface, would using the existing tagged make sense?

logger = SemanticLogger["MyClass"]
logger1 = logger.tagged(tag1: "value1", tag2: "value2")
logger2 = logger1.tagged(tag3: "value3")

# Will include tag1, tag2, tag3 and tag4 in the output
logger2.info("Some message", tag4: "value4")

I.e. If we call tagged without supplying a block, it returns a new logger instance. When a block is supplied it applies the tags to all logging in the current thread.

[reidmorrison]

Or, if we only want this feature to support named tags (Hash) for now we could do something like this?

logger = SemanticLogger["MyClass"]
logger1 = logger.named_tagged(tag1: "value1", tag2: "value2")
logger2 = logger1.named_tagged(tag3: "value3")

# Will include tag1, tag2, tag3 and tag4 in the output
logger2.info("Some message", tag4: "value4")

Since there is currently no logger instance level method named_tagged, there are no backward compatibility challenges.

[reidmorrison]

The next question is around expected behavior. For example should changes to the underlying/parent logger apply to the new child?

For example:

logger = SemanticLogger["MyClass"]
logger.level = :info

logger1 = logger.named_tagged(tag1: "value1", tag2: "value2")
logger2 = logger1.named_tagged(tag3: "value3")

# Change the parent log level
logger.level = :debug

# Will this line be logged, or should it have its own logging level?
logger2.debug("Some message", tag4: "value4")

[reidmorrison]

Based on the answer for the question above, if we need to maintain changes in the parent logger, we could look to other examples in Ruby.
For example an Enumerator is returned when we call #each without a block:

# With an array
array = [1, 2, 3, 4, 5]
enumerator = array.each  # Returns an Enumerator object, doesn't iterate yet

# You can then call methods on the enumerator
enumerator.with_index { |value, index| puts "#{index}: #{value}" }

This scenario is a little more complicated in that we cannot delegate logging calls to the parent logger since it would not contain the named tags. Maybe starting with a class that inherits from Base and then adds the necessary behavior, and delegates to the parent Base for logging level etc?

[Fire-Dragon-DoL]

Hi @reidmorrison , thank you so much for taking a look. This is good timing, I can dedicate next week to technical tasks, so I can bring this PR to a good shape 🎉

I haven't touched this PR in a bit, but I remember when implementing the "child logger", there were a lot of possible edge-cases to cover and a few challenges.

I think we should follow ActiveSupport::TaggedLogging:

• It is backward compatible: tagged without a block cannot be used currently in semantic_logger, raising an error
• It is compatible with ActiveSupport::TaggedLogging, matching the API 1:1
• It create a new logger without delegating to the parent, essentially it's a duplicate. Changing the level of the parent will not affect the child and changing the level of the child will not affect the parent
• The syntax could be the same one you suggested, which incidentally is also the same that ActiveSupport::TaggedLogging uses: logger.tagged("foo", "bar") (logger.tagged(name: "bar") for named tags, or logger.tagged("foo", name: "bar") for both)
• When a block is omitted it creates a duplicate logger using instance variables: the created logger is completely independent from the parent
• It has a similar issues with thread vs instance variables and it's being solved in the exact same way you suggested in your first comment and in the same way ActiveSupport::TaggedLogging does

A code sample explaining everything:

logger0 = SemanticLogger["MyClass"]
logger0.level = :debug
logger1 = logger0.tagged(tag1: "value1", tag2: "value2")
logger2 = logger1.tagged(tag3: "value3")

# Parent and child loggers are different objects
logger1.object_id != logger2.object_id # => true

# Changing logger level for a parent doesn't affect a child (not really parent/child)
logger1.level == :debug # => true
logger1.level = :warn
logger2.level == :debug # => true
logger2.debug "foo" # prints "foo" with all the associated tags

logger1.debug "foo" # prints nothing, since level is "warn"

I think this answers your question around behavior and in some way it probably points toward using tagged without block as the syntax.

Edge Cases

Named Tags and Thread Tags

logger0 = SemanticLogger["MyClass"]
logger0.level = :debug

logger1 = logger0.tagged(tag1: "value1")

logger1.tagged(tag2: "value2") do # the instance tags should be applied to the thread too
  some_method
end

def some_method
  logger = SemanticLogger["MyClass"]
  logger.info "stuff" # => should print both tag1 and tag2 from the thread. The thread got the variables set from the instance variables
  logger.info "stuff", tag2: "valueB" # => should print tag1 and tag2 but tag2 value should be "valueB"

  logger2 = logger.tagged(tag2: "valueBBB", tag3: "something")
  logger2.info "stuff" # => should print tag1, tag2 with "valueBBB" and tag3
end

Array tags and Thread Tags

logger0 = SemanticLogger["MyClass"]
logger0.level = :debug

logger1 = logger0.tagged("tag1", "tag2")

logger1.tagged("tag3") do # the instance tags should be applied to the thread too
  some_method
end

def some_method
  logger = SemanticLogger["MyClass"]
  logger.info "stuff" # => should print tag1, tag2 and tag3 from the thread
  logger.info "stuff", named_tag1: "valueB" # => should print tag1, tag2, tag3 and named_tag1
end

Child loggers and thread variables

logger0 = SemanticLogger["MyClass"]
logger1 = logger0.tagged("tag1", named_tag1: "value1")

logger1.tagged("tag2", named_tag2: "value2") do
  some_method0
end

def some_method0
  logger = SemanticLogger["MyClass"]
  logger.tagged("tag3", named_tag3: "value3") do
    some_method1
  end
end

def some_method1
  logger = SemanticLogger["MyClass"]
  logger.info("stuff", named_tag4: "value4")
  # should print the following tags:
  # - tag1
  # - named_tag1
  # - tag2
  # - named_tag2
  # - tag3
  # - named_tag3
  # - named_tag4
end

This approach could be very confusing, but it covers all the edge-cases I could think of.
I expect people to simply use thread-based tags sparingly and instance tags more freely