From b2b07591269616f4fc8c131c9da5d6e60694960c Mon Sep 17 00:00:00 2001 From: Edouard CHIN Date: Wed, 5 Jul 2023 19:08:36 +0200 Subject: [PATCH] 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. --- lib/logger.rb | 55 ++++++++++++++++++++++++++++++++++++++ test/logger/test_logger.rb | 31 +++++++++++++++++++++ 2 files changed, 86 insertions(+) diff --git a/lib/logger.rb b/lib/logger.rb index 25e2c27..36afb7f 100644 --- a/lib/logger.rb +++ b/lib/logger.rb @@ -472,6 +472,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_reader :processors + alias sev_threshold level alias sev_threshold= level= @@ -601,6 +646,7 @@ def initialize(logdev, shift_age = 0, shift_size = 1048576, level: DEBUG, @default_formatter = Formatter.new self.datetime_format = datetime_format self.formatter = formatter + @processors= [] @logdev = nil @level_override = {} if logdev && logdev != File::NULL @@ -684,6 +730,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 @@ -779,6 +826,14 @@ def level_key Fiber.current 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 diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb index ea27fba..3202eb3 100644 --- a/test/logger/test_logger.rb +++ b/test/logger/test_logger.rb @@ -170,6 +170,37 @@ def o.call(severity, timestamp, progname, msg) assert_equal("<"">\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.clear + log = log(logger, :info, "foo") + assert_equal("foo\n", log.msg) + end + def test_initialize logger = Logger.new(STDERR) assert_nil(logger.progname)