New feature to allow adding extra information to log

- ### Context

  It's quite common to add extra info to each log messages to make
  debugging easier.
  For instance, adding a request ID to trace the request more easily
  if an exception occurs. Or add user information for various needs.

  Right now, the easiest way to implement this is to create a custom
  formatter.

  ### Problem

  I believe formatting the log and adding extra information are two
  distincts features that should be handled with different objects.
  Moreover, because libraries or frameworks usually provide this
  feature, it makes things hard for them to not conflict with
  each others. As well as conflicting with the potential
  formatter set by an application.
  It ends up in a cascade of monkeypatch and doesn't allow
  much flexibility for the end user.

  ### Solution

  I'd like to introduce the concept of a log processor who's interface
  is similar to the formatter but its responsibility is to only
  add extra info to the message.
  More importantly, a logger can have multiple processors, each
  defining the logic within their scope.

  This should allow for a lot more flexibility (applications can
  now easily re-order processors, remove or add them on the fly,
  change their formatter afterward without breaking libraries
  functionalities).

  It will also make things easier for libraries and provide a cleaner
  way to hook into the logger.

  This change is fully backward compatible.

Author: Edouard-chin

lib/logger.rb

@@ -473,6 +473,51 @@ def datetime_format
   #
   attr_accessor :formatter
 
+  # Sets or retrieves the logger entries processors.
+  #
+  # A processor allows to add extra information to your log. For instance, to trace a
+  # request more easily, a processor can be added to add a request ID on each log.
+  # Multiple processors can be added to a logger, each passing the processed log
+  # to the next one.
+  #
+  # A processor can either be a proc or a class that responds to `call` and gets
+  # called with four arguments:
+  #
+  # - +severity+: The severity of the entry.
+  # - +time+: A Time object representing the entry's timestamp.
+  # - +progname+: The program name for the entry.
+  # - +msg+: The message for the entry (string or string-convertible object).
+  #
+  # A processor should return a string containing the processed entry.
+  #
+  # Example to add extra information of the request and user to each log.
+  #
+  #   class UserLogProcessor
+  #     def call(severity, time, progname, msg)
+  #       "[User login: #{user.login}] #{msg}"
+  #     end
+  #
+  #     def user
+  #       # Implement to get the user for the current session
+  #     end
+  #   end
+  #
+  #   class RequestLogProcessor
+  #     def call(severity, time, progname, msg)
+  #       "[#{request.uuid}] [#{request.ip}] #{msg}"
+  #     end
+  #   end
+  #
+  #   logger = Logger.new($stdout)
+  #   logger.processors << RequestLogProcessor.new << UserLogprocessor.new
+  #   logger.add(Logger::INFO, "hello \n ''")
+  #
+  # Output:
+  #
+  #   I, [2022-05-13T13:16:29.637488 #8492]  INFO -- : [John] [0000-1111] [192.168.0.1] hello
+  #
+  attr_accessor :processors
+
   alias sev_threshold level
   alias sev_threshold= level=
 
@@ -584,6 +629,7 @@ def initialize(logdev, shift_age = 0, shift_size = 1048576, level: DEBUG,
     @default_formatter = Formatter.new
     self.datetime_format = datetime_format
     self.formatter = formatter
+    self.processors = []
     @logdev = nil
     @level_override = {}
     if logdev && logdev != File::NULL
@@ -665,6 +711,7 @@ def add(severity, message = nil, progname = nil)
         progname = @progname
       end
     end
+    message = process_message(format_severity(severity), Time.now, progname, message)
     @logdev.write(
       format_message(format_severity(severity), Time.now, progname, message))
     true
@@ -742,6 +789,14 @@ def format_severity(severity)
     SEV_LABEL[severity] || 'ANY'
   end
 
+  def process_message(severity, datetime, progname, msg)
+    (processors || []).reverse_each do |processor|
+      msg = processor.call(severity, datetime, progname, msg)
+    end
+
+    msg
+  end
+
   def format_message(severity, datetime, progname, msg)
     (@formatter || @default_formatter).call(severity, datetime, progname, msg)
   end

test/logger/test_logger.rb

@@ -161,6 +161,37 @@ def o.call(severity, timestamp, progname, msg)
     assert_equal("<""<INFO-foo>>\n", line)
   end
 
+  def test_processors
+    dummy = STDERR
+    logger = Logger.new(dummy)
+    # default
+    log = log(logger, :info, "foo")
+    assert_equal("foo\n", log.msg)
+    # config
+    user_info_processor = proc { |severity, timestamp, progname, msg|
+      "[User ID: 123] [User Login: John] #{msg}\n"
+    }
+    logger.processors << user_info_processor
+    log = log(logger, :info, "foo")
+    assert_equal("[User ID: 123] [User Login: John] foo\n\n", log.msg)
+    # again
+    request_info_processor = Object.new
+    def request_info_processor.call(severity, timestamp, progname, msg)
+      "[Request ID: 1234] #{msg}"
+    end
+    logger.processors << request_info_processor
+    log = log(logger, :info, "foo")
+    assert_equal("[User ID: 123] [User Login: John] [Request ID: 1234] foo\n\n", log.msg)
+    # reset
+    logger.processors.clear
+    log = log(logger, :info, "foo")
+    assert_equal("foo\n", log.msg)
+    # again
+    logger.processors = nil
+    log = log(logger, :info, "foo")
+    assert_equal("foo\n", log.msg)
+  end
+
   def test_initialize
     logger = Logger.new(STDERR)
     assert_nil(logger.progname)