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! 🙏