Merge 549e570 into 0e91096

CHANGELOG.md

@@ -3,6 +3,26 @@
 Inspired by [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 Note: this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
+## [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).
+
 ## [0.9.1] - 2020-08-18
 ### Fixed
 - Fixed bug where merging context with string keys was causing a "key" is not a Symbol error
@@ -61,6 +81,7 @@ are already passed to the formatter as arguments so that the formatter and decid
  - Extracted `ContextualLogger.normalize_log_level` into a public class method so we can call it elsewhere where we allow log_level to be
    configured to text values like 'debug'.
 
+[0.10.0]: https://github.com/Invoca/contextual_logger/compare/v0.9.1...v0.10.0
 [0.9.1]: https://github.com/Invoca/contextual_logger/compare/v0.9.0...v0.9.1
 [0.9.0]: https://github.com/Invoca/contextual_logger/compare/v0.8.0...v0.9.0
 [0.8.0]: https://github.com/Invoca/contextual_logger/compare/v0.7.0...v0.8.0

Gemfile.lock

@@ -1,7 +1,7 @@
 PATH
   remote: .
   specs:
-    contextual_logger (0.9.1)
+    contextual_logger (0.10.0.pre.1)
       activesupport
       json
 

README.md

@@ -43,30 +43,85 @@ end
 
 contextual_logger = ApplicationLogger.new(STDOUT)
 ```
+## Ways to Set Context
+Context may be provided any of 3 ways. Typically, all 3 will be used together.
 
-### Logging
-All base logging methods are available for use with _or_ without added context
+- Globally for the process
+  - For a block or period of time. These may be nested.
+    - Inline when logging a message
+
+Indentation above indicates nested precedence. The indented, inner level "inherits" the context
+from the enclosing, outer level. If the same key appears at multiple levels,
+the innermost level's value will take precedence.
+
+Each of the 3 ways to set context is explained below, starting from the innermost (highest precedence).
+
+### Log Entries With Inline Context
+All base logging methods (`debug`, `info`, `warn` etc) are available for use with optional inline context passed as a hash at the end:
 ```ruby
-contextual_logger.info('Something might have just happened', file: __FILE__, current_object: inspect)
+contextual_logger.info('Service started', configured_options: config.inspect)
 ```
 
-If there is a base set of context you'd like to apply to a block of code, simply wrap it in `#with_context`
+The block form with optional 'progname' is also supported. As with `::Logger`, the block is only called if the log level is enabled.
+```ruby
+contextual_logger.debug('progname', current_id: current_object.id) { "debug: #{expensive_debug_function}" }
+```
+Equally, the `Logger#add` may be passed an optional inline context at the end:
 ```ruby
-contextual_logger.with_context(file: __FILE__, current_object: inspect) do
-  contextual_logger.info('Something might have just happened')
-  try.doing_something()
-rescue => ex
-  contextual_logger.error('Something definitely just happened', error: ex.message)
+contextual_logger.add("INFO", 'progname', 'Service started', configured_options: config.inspect)
+```
+The block form of `Logger#add` is also supported:
+```ruby
+contextual_logger.add("DEBUG", 'progname', file: __FILE__, current_object: inspect) { "debug: #{expensive_debug_function}" }
+```
+
+### Applying Context Around a Block
+If there is a set of context you'd like to apply to a block of code, simply wrap it in `#with_context`.
+These may be nested:
+```ruby
+log_context = { file: __FILE__, current_object: inspect }
+contextual_logger.with_context(log_context) do
+  contextual_logger.info('Service started')
+
+  invoice_log_context = { invoice_id: invoice.id }
+  contextual_logger.with_context(invoice_log_context) do
+    contextual_logger.info('About to process invoice')
+
+    process(invoice)
+  end
 end
 ```
 
+### Applying Context Across Bracketing Methods
+The above block-form is highly recommended, because you can't forget to reset the context.
+But sometimes you need to set the context for a period of time across bracketing methods that aren't
+set up to use in a block.
+You can manage the context reset yourself by not passing a block to `with_context`.
+In this case, it returns a `context_handler` object to you on which you must
+later call `reset!` to pop that context off the stack.
+
+Consider for example the `Test::Unit`/`minitest` convention of `setup` and `teardown`
+methods that are guaranteed to be called before/after tests.
+The context could be set in `setup` and reset in `teardown`:
+```ruby
+def setup
+  log_context = { file: __FILE__, current_object: inspect }
+  @log_context_handler = logger.with_context(log_context)
+end
+
+def teardown
+  @log_context_handler&.reset!
+end
+````
+
+### Setting Process Global Context
 If you'd like to set a global context for your process, you can do the following
 ```ruby
 contextual_logger.global_context = { service_name: 'test_service' }
 ```
 
-### Redaction
-#### Registering a Secret
+## Redaction
+### Registering a Secret
 In order to register sensitive strings to the logger for redaction to occur, do the following:
 ```ruby
 password = "ffbba9b905c0a549b48f48894ad7aa9b7bd7c06c"
@@ -79,11 +134,11 @@ The above will produce the resulting log line:
 03/10/20 12:22:05.769 INFO Request sent with body { 'username': 'test_user', 'password': '<redacted>' }
 ```
 
-### Overrides
-#### ActiveSupport::TaggedLogging
-ActiveSupport's TaggedLogging extension adds the ability for tags to be prepended onto logs in an easy to use way.  This is a very
-powerful piece of functionality.  If you're using this, there is an override you can use, to pull the tags into the context.
-All you need to do is add the following to your application's start up script:
+## Overrides
+### ActiveSupport::TaggedLogging
+ActiveSupport's `TaggedLogging` extension adds the ability for tags to be prepended onto logs in an easy to use way. This is a very
+powerful piece of functionality. If you're using this, there is an override you can use, to pull the tags into the context.
+All you need to do is add the following to your application's startup script:
 ```ruby
 require 'contextual_logger/overrides/active_support/tagged_logging/formatter'
 ```

lib/contextual_logger.rb

@@ -7,6 +7,16 @@
 require_relative './contextual_logger/context/handler'
 
 module ContextualLogger
+  LOG_LEVEL_NAMES_TO_SEVERITY =
+  {
+    debug:  Logger::Severity::DEBUG,
+    info:   Logger::Severity::INFO,
+    warn:   Logger::Severity::WARN,
+    error:  Logger::Severity::ERROR,
+    fatal:  Logger::Severity::FATAL,
+    unknown: Logger::Severity::UNKNOWN
+  }.freeze
+
   class << self
     def new(logger)
       logger.extend(LoggerMixin)
@@ -17,22 +27,8 @@ def normalize_log_level(log_level)
       if log_level.is_a?(Integer) && (Logger::Severity::DEBUG..Logger::Severity::UNKNOWN).include?(log_level)
         log_level
       else
-        case log_level.to_s.downcase
-        when 'debug'
-          Logger::Severity::DEBUG
-        when 'info'
-          Logger::Severity::INFO
-        when 'warn'
-          Logger::Severity::WARN
-        when 'error'
-          Logger::Severity::ERROR
-        when 'fatal'
-          Logger::Severity::FATAL
-        when 'unknown'
-          Logger::Severity::UNKNOWN
-        else
+        LOG_LEVEL_NAMES_TO_SEVERITY[log_level.to_s.downcase.to_sym] or
           raise ArgumentError, "invalid log level: #{log_level.inspect}"
-        end
       end
     end
 
@@ -72,45 +68,54 @@ def current_context_for_thread
       Context::Handler.current_context
     end
 
-    def debug(message = nil, context = {})
-      add(Logger::Severity::DEBUG, message.nil? && block_given? ? yield : message, **context)
-    end
-
-    def info(message = nil, context = {})
-      add(Logger::Severity::INFO, message.nil? && block_given? ? yield : message, **context)
-    end
+    # In the methods generated below, we assume that presence of context means new code that is
+    # aware of ContextualLogger...and that that code never uses progname.
+    # This is important because we only get 3 args total (not including &block) passed to `add`,
+    # in order to be compatible with classic implementations like in the plain ::Logger and
+    # ActiveSupport::Logger.broadcast.
 
-    def warn(message = nil, context = {})
-      add(Logger::Severity::WARN, message.nil? && block_given? ? yield : message, **context)
-    end
+    # Note that we can't yield before `add` because `add` might skip it based on log_level. And we can't check
+    # log_level here because we might be running in ActiveSupport::Logging.broadcast which has multiple
+    # loggers, each with their own log_level.
 
-    def error(message = nil, context = {})
-      add(Logger::Severity::ERROR, message.nil? && block_given? ? yield : message, **context)
-    end
-
-    def fatal(message = nil, context = {})
-      add(Logger::Severity::FATAL, message.nil? && block_given? ? yield : message, **context)
-    end
-
-    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)
+        def #{method_name}(arg = nil, **context, &block)
+          if context.empty?
+            add(#{log_level}, nil, arg, &block)
+          else
+            if arg.nil?
+              add(#{log_level}, nil, context, &block)
+            elsif block
+              add(#{log_level}, nil, context.merge(progname: arg), &block)
+            else
+              add(#{log_level}, arg, context)
+            end
+          end
+        end
+      EOS
     end
 
     def log_level_enabled?(severity)
       severity >= level
     end
 
-    def add(init_severity, message = nil, init_progname = nil, **context)   # Ruby will prefer to match hashes up to last ** argument
-      severity = init_severity || UNKNOWN
+    # Note that this interface needs to stay compatible with the underlying ::Logger#add interface,
+    # which is: def add(severity, message = nil, progname = nil)
+    def add(arg_severity, arg1 = nil, arg2 = nil, **context)   # Ruby will prefer to match hashes up to last ** argument
+      severity = arg_severity || UNKNOWN
       if log_level_enabled?(severity)
-        progname = init_progname || @progname
-        if message.nil?
+        if arg1.nil?
           if block_given?
             message = yield
+            progname = arg2 || context.delete(:progname) || @progname
           else
-            message = init_progname
+            message = arg2
             progname = @progname
           end
+        else
+          message = arg1
+          progname = arg2 || @progname
         end
         write_entry_to_log(severity, Time.now, progname, message, context: current_context_for_thread.deep_merge(context))
       end
@@ -133,22 +138,24 @@ def redactor
     end
 
     def format_message(severity, timestamp, progname, message, context: {})
+      normalized_message = ContextualLogger.normalize_message(message)
+      normalized_progname = ContextualLogger.normalize_message(progname) unless progname.nil?
       if @formatter
-        @formatter.call(severity, timestamp, progname, { message: ContextualLogger.normalize_message(message) }.merge!(context))
+        @formatter.call(severity, timestamp, normalized_progname, { message: normalized_message }.merge!(context))
       else
-        "#{basic_json_log_entry(severity, timestamp, progname, message, context: context)}\n"
+        "#{basic_json_log_entry(severity, timestamp, normalized_progname, normalized_message, context: context)}\n"
       end
     end
 
-    def basic_json_log_entry(severity, timestamp, progname, message, context:)
+    def basic_json_log_entry(severity, timestamp, normalized_progname, normalized_message, context:)
       message_hash = {
-        message:   ContextualLogger.normalize_message(message),
+        message: normalized_progname ? "#{normalized_progname}: #{normalized_message}" : normalized_message,
         severity:  severity,
         timestamp: timestamp
       }
-      message_hash[:progname] = progname if progname
+      message_hash[:progname] = normalized_progname if normalized_progname
 
-      # using merge! instead of merge for speed of operation
+      # merge! is faster and OK here since message_hash is still local only to this method
       message_hash.merge!(context).to_json
     end
   end

lib/contextual_logger/version.rb

@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 module ContextualLogger
-  VERSION = '0.9.1'
+  VERSION = '0.10.0.pre.1'
 end