TECH-4787: support progname and message block #34

ColinDKelley · 2020-08-28T04:10:01Z

TECH-4787

[0.10.0] - Unreleased

Added

Added support and tests for all combinations of progname, message, and context:

logger.info(message)
logger.info(context_key1: value, context_key2: value)
logger.info(message, context_key1: value, context_key2: value)
logger.info { message }
logger.info(progname) { message }
logger.info(context_key1: value, context_key2: value) { message }
logger.info(progname, context_key1: value, context_key2: value) { message }

including where progname and message are types other than String.

Fixed

Fixed bug where usage like in Faraday: logger.info(progname) { message } was dropping the message and only showing
progname.
Fixed bug in block form where the message block would be called even if the log_level was not enabled
(this could have been slow).

lib/contextual_logger.rb

…or all 3: progname, context, message block

…progname or message block is not a String

ColinDKelley · 2020-08-28T19:30:44Z

lib/contextual_logger.rb

+    error:  Logger::Severity::ERROR,
+    fatal:  Logger::Severity::FATAL,
+    unknown: Logger::Severity::UNKNOWN
+  }.freeze


I hit the breaking point where I needed to go meta to avoid copying too much code!

ColinDKelley · 2020-08-28T19:32:08Z

lib/contextual_logger.rb

-    def unknown(message = nil, context = {})
-      add(Logger::Severity::UNKNOWN, message.nil? && block_given? ? yield : message, **context)
+    LOG_LEVEL_NAMES_TO_SEVERITY.each do |method_name, log_level|
+      class_eval(<<~EOS, __FILE__, __LINE__ + 1)


@madelynrr I made a matrix on paper and added all the test cases first. Then picked them off one at a time here. This is about the 12th refactor to get it as clean as I could.

ColinDKelley · 2020-08-28T19:35:37Z

lib/contextual_logger.rb

+              add(#{log_level}, nil, context, &block)
+            elsif block
+              add(#{log_level}, nil, context) do
+                "\#{ContextualLogger.normalize_message(arg)}: \#{ContextualLogger.normalize_message(block.call)}"


I wanted to support the full matrix (as enumerated in the CHANGELOG) but I was stymied about how to support all 3 of progname, context, and message when the class add interface only has 2 parameters after the level. My first work-around was to glue progname to message just like ::Logger does, with : . But that wasn't exposing progname to the formatter. So I went with a different approach of storing progname into the context with the :progname key. Stealing that key seems fine since our JSON formatter will wind up putting it in there anyway (in addition to prepending the progname to the message with : as a separator).

ColinDKelley · 2020-08-28T19:38:10Z

lib/contextual_logger.rb

-    def add(init_severity, message = nil, init_progname = nil, **context)   # Ruby will prefer to match hashes up to last ** argument
-      severity = init_severity || UNKNOWN
+    def add(arg_severity, arg1 = nil, arg2 = nil, **context)   # Ruby will prefer to match hashes up to last ** argument
+      severity = arg_severity || UNKNOWN


@jebentier The rewrite below avoids any variable reassignment. Each if/else branch assigns the locals message and progname. And I renamed the formal args to just arg1 and arg2 since it was so confusing to call one progname when half the time it had a message in it!

…h in context hash

jebentier · 2020-08-31T15:07:04Z

lib/contextual_logger.rb

+            if arg.nil?
+              add(#{log_level}, nil, context, &block)
+            elsif block
+              add(#{log_level}, nil, context.merge(progname: arg), &block)


Why did we go with the approach here of packing and unpacking the progname from the context when we can still pass it cleanly through arg1? By doing this (un)packing, we're adding back the bug that the context is populated with unnecessary information that the formatter isn't aware of, leading to potential duplicate data being formatted by the formatter.

For example with the code as it is, if I have a formatter that looks like the following:

-> (severity, timestamp, progname, message_with_context) do message_with_context.merge(log_progname: progname).to_json end

And then I call logger.info('progname', some_context: 'hello') { 'hello world' }, the log line will look like

{ 'message': 'hello world', 'progname': 'progname', 'some_context': 'hello', 'log_progname': 'progname' }

Is it possible to avoid this?

Why did we go with the approach here of packing and unpacking the progname from the context when we can still pass it cleanly through arg1

Because we can't pass it through arg1 when there's a block. (The standard add method only looks at the bock when arg1 is nil.) That's the bug that caused this ticket. I listed the constraints the comments just above.

And we can't call the block first, because the log level needs to be checked.
And we can't check the log level because broadcast has several of them, and they hidden from us.

Ahh, I definitely got confused by which arg is which in the original implementation. I just went back to the original method to look it up. Can you add to the comment's what the original add interface is? def add(severity, message = nil, progname = nil)

Done. 822f94c

spec/lib/contextual_logger_spec.rb

ColinDKelley · 2020-08-31T16:55:38Z

lib/contextual_logger.rb

@@ -106,7 +106,7 @@ def add(arg_severity, arg1 = nil, arg2 = nil, **context)   # Ruby will prefer to
        if arg1.nil?
          if block_given?
            message = yield
-            progname = arg2 || context[:progname] || @progname
+            progname = arg2 || context.delete(:progname) || @progname


@jebentier I added this back as I had it, so that the tunneled progname doesn't live on in the context hash.
Usually I'd avoid delete since that mutates the context here. But it's really succinct, and performs best...and I figured no one else but our code above would be putting a :progname key into the context and calling add in the block form with a context hash! LMK if you disagree.

I think this is okay for now. Maybe something to not in the README is that through this implementation you're able to specify progname using two different method (flip it to a feature 😉 )

logger.info('request') { message } and logger.info(progname: 'request') { message } will pass progname down to the formatter.

@jebentier Can you take a look at the README restructure here: 549e570

ColinDKelley added 4 commits August 27, 2020 15:04

TECH-4787: add test for add() using progname and message block

c77c0ed

TECH-4787: test with/without context X with/without log level enabled

8461260

TECH-4787: extend tests to all levels

b3d3649

TECH-4787: extract LOG_LEVEL_NAMES_TO_SEVERITY

eca53b1

hound bot reviewed Aug 28, 2020

View reviewed changes

lib/contextual_logger.rb Show resolved Hide resolved

TECH-4787: use class_eval and __FILE__, __LINE__

aec156c

ColinDKelley force-pushed the TECH-4787/support_progname_and_message_block branch from 7c53219 to aec156c Compare August 28, 2020 04:18

ColinDKelley added 2 commits August 28, 2020 11:04

TECH-4787: add test for inline context and no progname; add support f…

dd9e841

…or all 3: progname, context, message block

TECH-4787: handle corner case of progname+context+message block when …

2174d3d

…progname or message block is not a String

ColinDKelley force-pushed the TECH-4787/support_progname_and_message_block branch from 8cb6574 to 2174d3d Compare August 28, 2020 18:24

TECH-4787: bump version to 0.10.0.pre.1; update README and CHANGELOG

634e366

ColinDKelley force-pushed the TECH-4787/support_progname_and_message_block branch from 8671f25 to 8058449 Compare August 28, 2020 19:21

TECH-4787: update CHANGELOG to add missing link

c202488

ColinDKelley force-pushed the TECH-4787/support_progname_and_message_block branch from 8058449 to c202488 Compare August 28, 2020 19:28

ColinDKelley requested review from jebentier and madelynrr August 28, 2020 19:29

ColinDKelley commented Aug 28, 2020

View reviewed changes

ColinDKelley added 2 commits August 29, 2020 11:39

TECH-4787: switch format to <progname>: message; pass progname throug…

17f2f1e

…h in context hash

TECH-4787: simplify if/else to ||

d311699

jebentier reviewed Aug 31, 2020

View reviewed changes

TECH-4787: delete :progname from context hash when we added it there

36154e4

hound bot reviewed Aug 31, 2020

View reviewed changes

spec/lib/contextual_logger_spec.rb Show resolved Hide resolved

TECH-4787: add comment about ::Logger#add interface compatibility

822f94c

ColinDKelley commented Aug 31, 2020

View reviewed changes

jebentier approved these changes Sep 1, 2020

View reviewed changes

TECH-4787: restructure README including documenting reset!

549e570

ColinDKelley force-pushed the TECH-4787/support_progname_and_message_block branch from 17b8f29 to 549e570 Compare September 2, 2020 17:55

jebentier approved these changes Sep 2, 2020

View reviewed changes

TECH-4787: bump version to 0.10.0; update CHANGELOG

6b70cfe

ColinDKelley merged commit 6b70cfe into master Sep 3, 2020

ColinDKelley deleted the TECH-4787/support_progname_and_message_block branch September 3, 2020 03:58

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

TECH-4787: support progname and message block #34

TECH-4787: support progname and message block #34

ColinDKelley commented Aug 28, 2020 •

edited

Loading

ColinDKelley Aug 28, 2020

ColinDKelley Aug 28, 2020

ColinDKelley Aug 28, 2020 •

edited

Loading

ColinDKelley Aug 28, 2020 •

edited

Loading

jebentier Aug 31, 2020

ColinDKelley Aug 31, 2020

ColinDKelley Aug 31, 2020

jebentier Aug 31, 2020

ColinDKelley Aug 31, 2020

ColinDKelley Aug 31, 2020

jebentier Sep 1, 2020

ColinDKelley Sep 2, 2020 •

edited

Loading

TECH-4787: support progname and message block #34

TECH-4787: support progname and message block #34

Conversation

ColinDKelley commented Aug 28, 2020 • edited Loading

[0.10.0] - Unreleased

Added

Fixed

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ColinDKelley Aug 28, 2020 • edited Loading

Choose a reason for hiding this comment

ColinDKelley Aug 28, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ColinDKelley Sep 2, 2020 • edited Loading

Choose a reason for hiding this comment

ColinDKelley commented Aug 28, 2020 •

edited

Loading

ColinDKelley Aug 28, 2020 •

edited

Loading

ColinDKelley Aug 28, 2020 •

edited

Loading

ColinDKelley Sep 2, 2020 •

edited

Loading