TECH-12593:make global_context global, but just for that logger instance

CHANGELOG.md

@@ -4,6 +4,12 @@ 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).
 
+## [1.2.0] - Unreleased
+### Changed
+- Changed global_context to be stored inside the logger.
+- Changed current_context to be stored in a Thread/Fiber-local variable that is unique per instance of the logger.
+- Changed `LoggerWithContext` to honor `with_context` on itself and the base logger.
+
 ## [1.1.1] - 2022-11-29
 ### Added
 - Bug fix for registering regex
@@ -99,15 +105,3 @@ are already passed to the formatter as arguments so that the formatter can decid
 ### Added
  - 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'.
-
-[1.0.0]: https://github.com/Invoca/contextual_logger/compare/v0.11.0...v1.0.0
-[0.11.0]: https://github.com/Invoca/contextual_logger/compare/v0.10.0...v0.11.0
-[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
-[0.7.0]: https://github.com/Invoca/contextual_logger/compare/v0.6.1...v0.7.0
-[0.6.1]: https://github.com/Invoca/contextual_logger/compare/v0.6.0...v0.6.1
-[0.6.0]: https://github.com/Invoca/contextual_logger/compare/v0.5.1...v0.6.0
-[0.5.1]: https://github.com/Invoca/contextual_logger/compare/v0.5.0...v0.5.1
-[0.5.0]: https://github.com/Invoca/contextual_logger/compare/v0.4.0...v0.5.0

Gemfile.lock

@@ -1,19 +1,19 @@
 PATH
   remote: .
   specs:
-    contextual_logger (1.1.1)
+    contextual_logger (1.2.0.colin.5)
       activesupport
       json
 
 GEM
   remote: https://rubygems.org/
   specs:
-    activesupport (7.0.4.3)
+    activesupport (7.0.7.2)
       concurrent-ruby (~> 1.0, >= 1.0.2)
       i18n (>= 1.6, < 2)
       minitest (>= 5.1)
       tzinfo (~> 2.0)
-    appraisal (2.4.1)
+    appraisal (2.5.0)
       bundler
       rake
       thor (>= 0.14.0)
@@ -29,18 +29,20 @@ GEM
       tins (~> 1.6)
     diff-lcs (1.5.0)
     docile (1.4.0)
-    i18n (1.12.0)
+    i18n (1.14.1)
       concurrent-ruby (~> 1.0)
     json (2.6.3)
     method_source (1.0.0)
-    minitest (5.18.0)
+    minitest (5.19.0)
     parallel (1.23.0)
-    parser (3.2.2.0)
+    parser (3.2.2.3)
       ast (~> 2.4.1)
+      racc
     powerpack (0.1.3)
     pry (0.14.2)
       coderay (~> 1.1)
       method_source (~> 1.0)
+    racc (1.7.1)
     rainbow (3.1.1)
     rake (13.0.6)
     rspec (3.12.0)
@@ -49,13 +51,13 @@ GEM
       rspec-mocks (~> 3.12.0)
     rspec-core (3.12.2)
       rspec-support (~> 3.12.0)
-    rspec-expectations (3.12.2)
+    rspec-expectations (3.12.3)
       diff-lcs (>= 1.2.0, < 2.0)
       rspec-support (~> 3.12.0)
-    rspec-mocks (3.12.5)
+    rspec-mocks (3.12.6)
       diff-lcs (>= 1.2.0, < 2.0)
       rspec-support (~> 3.12.0)
-    rspec-support (3.12.0)
+    rspec-support (3.12.1)
     rspec_junit_formatter (0.6.0)
       rspec-core (>= 2, < 4, != 2.12.0)
     rubocop (0.54.0)
@@ -79,7 +81,7 @@ GEM
     sync (0.5.0)
     term-ansicolor (1.7.1)
       tins (~> 1.0)
-    thor (1.2.1)
+    thor (1.2.2)
     tins (1.32.1)
       sync
     tzinfo (2.0.6)
@@ -105,4 +107,4 @@ DEPENDENCIES
   ruby-prof-flamegraph
 
 BUNDLED WITH
-   2.2.29
+   2.3.22

contextual_logger.gemspec

@@ -19,6 +19,6 @@ Gem::Specification.new do |spec|
     "allowed_push_host" => "https://rubygems.org"
   }
 
-  spec.add_runtime_dependency 'json'
-  spec.add_runtime_dependency 'activesupport'
+  spec.add_dependency 'json'
+  spec.add_dependency 'activesupport'
 end

lib/contextual_logger.rb

@@ -4,7 +4,9 @@
 require 'active_support/core_ext/module/delegation'
 require 'json'
 require_relative './contextual_logger/redactor'
-require_relative './contextual_logger/context/handler'
+require_relative './contextual_logger/context'
+require_relative './contextual_logger/context_handler'
+require_relative './contextual_logger/global_context_lock_message'
 
 module ContextualLogger
   LOG_LEVEL_NAMES_TO_SEVERITY =
@@ -42,32 +44,49 @@ def normalize_message(message)
     end
   end
 
+  # Context Precedence when this is mixed into a logger:
+  # 1. inline **context passed to the logger method
+  # 2. `with_context` overrides on the logger object
+  # 3. `global_context` set on the logger passed to this constructor
   module LoggerMixin
+    include Context
+
     delegate :register_secret, :register_secret_regex, to: :redactor
 
+    def global_context
+      @global_context ||= Context::EMPTY_CONTEXT
+    end
+
     def global_context=(context)
-      Context::Handler.new(context).set!
+      if (global_context_lock_message = ::ContextualLogger.global_context_lock_message)
+        raise ::ContextualLogger::GlobalContextIsLocked, global_context_lock_message
+      end
+      @global_context = context.freeze
     end
 
-    def with_context(context)
-      context_handler = Context::Handler.new(current_context_for_thread.deep_merge(context))
-      context_handler.set!
+    def current_context
+      current_context_override || global_context
+    end
+
+    # TODO: Deprecate current_context_for_thread in v2.0.
+    alias current_context_for_thread current_context
+
+    def with_context(stacked_context)
+      context_handler = ContextHandler.new(self, self.current_context_override)
+      self.current_context_override = deep_merge_with_current_context(stacked_context)
+
       if block_given?
         begin
           yield
         ensure
           context_handler.reset!
         end
       else
-        # If no block given, the context handler is returned to the caller so they can handle reset! themselves.
+        # If no block given, return context handler to the caller so they can call reset! themselves.
         context_handler
       end
     end
 
-    def current_context_for_thread
-      Context::Handler.current_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`,
@@ -102,7 +121,7 @@ def log_level_enabled?(severity)
 
     # 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
+    def add(arg_severity, arg1 = nil, arg2 = nil, **context)   # Ruby will prefer to match hashes to last argument because of **
       severity = arg_severity || UNKNOWN
       if log_level_enabled?(severity)
         if arg1.nil?
@@ -117,7 +136,7 @@ def add(arg_severity, arg1 = nil, arg2 = nil, **context)   # Ruby will prefer to
           message = arg1
           progname = arg2 || @progname
         end
-        write_entry_to_log(severity, Time.now, progname, message, context: current_context_for_thread.deep_merge(context))
+        write_entry_to_log(severity, Time.now, progname, message, context: deep_merge_with_current_context(context))
       end
 
       true
@@ -141,7 +160,7 @@ 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, normalized_progname, { message: normalized_message }.merge!(context))
+        @formatter.call(severity, timestamp, normalized_progname, { message: normalized_message, **context })
       else
         "#{basic_json_log_entry(severity, timestamp, normalized_progname, normalized_message, context: context)}\n"
       end
@@ -151,12 +170,20 @@ def basic_json_log_entry(severity, timestamp, normalized_progname, normalized_me
       message_hash = {
         message: normalized_progname ? "#{normalized_progname}: #{normalized_message}" : normalized_message,
         severity:  severity,
-        timestamp: timestamp
+        timestamp: timestamp,
+        **context
       }
       message_hash[:progname] = normalized_progname if normalized_progname
 
-      # merge! is faster and OK here since message_hash is still local only to this method
-      message_hash.merge!(context).to_json
+      message_hash.to_json
+    end
+
+    def deep_merge_with_current_context(stacked_context)
+      if stacked_context.any?
+        current_context.deep_merge(stacked_context)
+      else
+        current_context
+      end
     end
   end
 end

lib/contextual_logger/context.rb

@@ -0,0 +1,21 @@
+# frozen_string_literal: true
+
+module ContextualLogger
+  module Context
+    EMPTY_CONTEXT = {}.freeze
+
+    def thread_context_key_for_logger_instance
+      # We include the object_id here to make these thread/fiber locals unique per logger instance.
+      @thread_context_key_for_logger_instance ||= "ContextualLogger::Context.context_for_#{object_id}".to_sym
+    end
+
+    def current_context_override
+      ContextualLogger.global_context_lock_message ||= "ContextualLogger::Context.current_context_override set for #{self.class.name} #{object_id}"
+      Thread.current[thread_context_key_for_logger_instance]
+    end
+
+    def current_context_override=(context_override)
+      Thread.current[thread_context_key_for_logger_instance] = context_override.freeze
+    end
+  end
+end

lib/contextual_logger/context_handler.rb

@@ -0,0 +1,14 @@
+# frozen_string_literal: true
+
+module ContextualLogger
+  class ContextHandler
+    def initialize(instance, previous_context_override)
+      @instance = instance
+      @previous_context_override = previous_context_override
+    end
+
+    def reset!
+      @instance.current_context_override = @previous_context_override
+    end
+  end
+end

lib/contextual_logger/global_context_lock_message.rb

@@ -0,0 +1,11 @@
+# frozen_string_literal: true
+
+module ContextualLogger
+  class << self
+    attr_accessor :global_context_lock_message # nil or a string indicating what locked the global context
+  end
+
+
+  class GlobalContextIsLocked < StandardError
+  end
+end

lib/contextual_logger/logger_with_context.rb

@@ -6,6 +6,13 @@ module ContextualLogger
   # A logger that deep_merges additional context and then delegates to the given logger.
   # Keeps it own log level (called override_level) that may be set independently of the logger it delegates to.
   # If override_level is non-nil, it takes precedence; if it is nil (the default), then it delegates to the logger.
+  #
+  # Context Precedence:
+  # 1. inline **context passed to the logger method
+  # 2. `with_context` overrides on this LoggerWithContext object
+  # 3. context passed to this LoggerWithContext constructor
+  # 4. `with_context` overrides on the logger passed to this constructor
+  # 5. `global_context` set on the logger passed to this constructor
   class LoggerWithContext
     include LoggerMixin
 
@@ -16,7 +23,13 @@ def initialize(logger, context, level: nil)
       @logger = logger
       self.level = level
       @context = normalize_context(context)
-      @merged_context_cache = {}  # so we don't have to merge every time
+    end
+
+    # TODO: It's a (small) bug that the global_context is memoized at this point. There's a chance that the @logger.current_context
+    # changes after this because of an enclosing @logger.with_context block. If that happens, we'll miss that extra context.
+    # The tradeoff is that we don't want to keep calling deep_merge.
+    def global_context
+      @global_context ||= @logger.current_context.deep_merge(@context) # this will include any with_context overrides on the `logger`
     end
 
     def level
@@ -29,10 +42,10 @@ def level=(override_level)
 
     def write_entry_to_log(severity, timestamp, progname, message, context:)
       merged_context =
-        if @merged_context_cache.size >= 1000 # keep this cache memory use finite
-          @merged_context_cache[context] || @context.deep_merge(context)
+        if context.any?
+          current_context.deep_merge(context)
         else
-          @merged_context_cache[context] ||= @context.deep_merge(context)
+          current_context
         end
 
       @logger.write_entry_to_log(severity, timestamp, progname, message, context: merged_context)

lib/contextual_logger/version.rb

@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 module ContextualLogger
-  VERSION = '1.1.1'
+  VERSION = '1.2.0.colin.5'
 end