Skip to content
Open
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
14 changes: 14 additions & 0 deletions docs/api.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
17 changes: 16 additions & 1 deletion lib/semantic_logger/base.rb
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@
module SemanticLogger
class Base
# Class name to be logged
attr_accessor :name, :filter
attr_accessor :name, :filter, :child_named_tags

# Set the logging level for this logger
#
Expand Down Expand Up @@ -250,6 +250,14 @@ 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 = child_named_tags.merge(named_tags)
new_logger = dup
new_logger.child_named_tags = new_named_tags
new_logger
end

private

# Initializer for Abstract Class SemanticLogger::Base
Expand Down Expand Up @@ -290,6 +298,7 @@ def initialize(klass, level = nil, filter = nil)
else
self.level = level
end
@child_named_tags = {}
end

# Return the level index for fast comparisons
Expand Down Expand Up @@ -349,6 +358,9 @@ def log_internal(level, index, message = nil, payload = nil, exception = nil)
end
end

# Add child named tags to the log
log.payload = child_named_tags.merge(log.payload || {})

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?


# Log level may change during assign due to :on_exception_level
self.log(log) if should_log && should_log?(log)
end
Expand Down Expand Up @@ -389,6 +401,9 @@ def measure_internal(level, index, message, params)
# Extract options after block completes so that block can modify any of the options
payload = params[:payload]

# Add child named tags
payload = child_named_tags.merge(payload || {})

# May return false due to elastic logging
should_log = log.assign(
message: message,
Expand Down
6 changes: 5 additions & 1 deletion lib/semantic_logger/loggable.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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_child_named_tags)

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

end

# Replace instance class level logger
Expand Down Expand Up @@ -114,6 +114,10 @@ def #{method_name}(*args, &block)
true
end

def logger_child(**named_tags)
@logger_child_named_tags = named_tags
end

private

# Dynamic Module to intercept method calls for measuring purposes.
Expand Down
14 changes: 14 additions & 0 deletions test/loggable_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -79,5 +87,11 @@ class TestAttribute
TestAttribute.new.logger.is_a?(SemanticLogger::Logger)
end
end

describe "sample child class logger" do
it "has child named tags set" do
assert_equal TestChildClassLogger::TAG_DATA, TestChildClassLogger.logger.child_named_tags
end
end
end
end
13 changes: 13 additions & 0 deletions test/logger_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -153,5 +153,18 @@ def self.call(log)
end
end
end

describe ".child" do
it "creates a child logger" do

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

tag_data = {tag1: "value1", tag2: "value2"}
child_logger = logger.child(**tag_data)
child_logger.info("hello world")

assert_equal tag_data, child_logger.child_named_tags
assert log = child_logger.events.first
assert_equal "hello world", log.message
assert_equal tag_data, log.payload
end
end
end
end