Merge 8cb6574 into 0e91096

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,52 @@ 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 2 args total 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) { "\#{arg}: \#{block.call}" }
+            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
+    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 || @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

spec/lib/contextual_logger_spec.rb

@@ -155,6 +155,74 @@ def expect_log_line_to_be_written(log_line)
     end
   end
 
+  context 'with no context' do
+    let(:expected_log_hash) do
+      {
+        message: 'this is a test',
+        timestamp: Time.now,
+        progname: 'request'
+      }
+    end
+
+    it 'handles both progname and message block (no inline context)' do
+      expect_log_line_to_be_written(expected_log_hash.merge(severity: 'INFO').to_json)
+      expect(logger.info('request') { 'this is a test' }).to eq(true)
+    end
+
+    context "when log level isn't enabled" do
+      before { logger.level = Logger::Severity::ERROR }
+
+      it "does not call message block" do
+        block_called = false
+        logger.info('request') { block_called = true }
+        expect(block_called).to be_falsey
+      end
+    end
+  end
+
+  context 'inline context' do
+    let(:message) { 'this is a test' }
+    let(:expected_log_hash) do
+      {
+        severity: 'INFO',
+        message: message,
+        timestamp: Time.now,
+        service: 'test_service'
+      }
+    end
+
+    it 'handles message block (inline context) with nil progname' do
+      expect_log_line_to_be_written(expected_log_hash.to_json)
+      expect(logger.info(nil, service: 'test_service') { 'this is a test' }).to eq(true)
+    end
+
+    it 'handles message block (inline context) with no progname' do
+      expect_log_line_to_be_written(expected_log_hash.to_json)
+      expect(logger.info(service: 'test_service') { 'this is a test' }).to eq(true)
+    end
+
+    context 'with progname and message' do
+      let(:message) { 'request: this is a test' }
+
+      it 'handles message block (inline context) with progname' do
+        expect_log_line_to_be_written(expected_log_hash.to_json)
+        expect(logger.info('request', service: 'test_service') { 'this is a test' }).to eq(true)
+      end
+    end
+
+    context "when log level isn't enabled" do
+      before { logger.level = Logger::Severity::UNKNOWN }
+
+      [:debug, :info, :warn, :error, :fatal].each do |level|
+        it "does not call message block (#{level})" do
+          block_called = false
+          logger.send(level, nil, service: 'test_service') { block_called = true }
+          expect(block_called).to be_falsey
+        end
+      end
+    end
+  end
+
   describe 'inline context' do
     let(:expected_log_hash) do
       {
@@ -359,6 +427,11 @@ def expect_log_line_to_be_written(log_line)
       expect(log_stream.string).to match(/\{"message":"info message","severity":"INFO","timestamp":".*"\}/)
     end
 
+    it "preserves the Logger interface with non-nil progname & block" do
+      expect(logger.add(Logger::Severity::INFO, nil, 'request') { "info message" }).to eq(true)
+      expect(log_stream.string).to match(/\{"message":"info message","severity":"INFO","timestamp":".*","progname":"request"\}/)
+    end
+
     it "preserves the Logger interface with nil message & message in progname spot" do
       expect(logger.add(Logger::Severity::INFO, nil, "info message")).to eq(true)
       expect(log_stream.string).to match(/\{"message":"info message","severity":"INFO","timestamp":".*"\}/)