From ab4dc5ad5e58eac42e5ca7008e5acab49e17126f Mon Sep 17 00:00:00 2001 From: HoneyryderChuck Date: Wed, 13 Aug 2025 15:46:22 +0100 Subject: [PATCH 1/6] add support in default formatter to receive extra context as kwargs --- lib/logger/formatter.rb | 31 ++++++++++++++++++++++++++++--- test/logger/test_formatter.rb | 29 ++++++++++++++++++++++++++++- 2 files changed, 56 insertions(+), 4 deletions(-) diff --git a/lib/logger/formatter.rb b/lib/logger/formatter.rb index c634dbf..5c903c9 100644 --- a/lib/logger/formatter.rb +++ b/lib/logger/formatter.rb @@ -3,7 +3,7 @@ class Logger # Default formatter for log messages. class Formatter - Format = "%.1s, [%s #%d] %5s -- %s: %s\n" + Format = "%.1s, %s[%s #%d] %5s -- %s: %s\n" DatetimeFormat = "%Y-%m-%dT%H:%M:%S.%6N" attr_accessor :datetime_format @@ -12,16 +12,41 @@ def initialize @datetime_format = nil end - def call(severity, time, progname, msg) - sprintf(Format, severity, format_datetime(time), Process.pid, severity, progname, msg2str(msg)) + def call(severity, time, progname, msg, context: nil) + context_str = format_context(context) + + context_str << " " unless context_str.empty? + + sprintf(Format, severity, context_str, format_datetime(time), Process.pid, severity, progname, msg2str(msg)) end private + def format_context(context) + case context + when Hash + filter_map_join(context) { |k, v| "[#{k}=#{v}]" unless v.nil? } + when Array + filter_map_join(context) { |v| "[#{v}]" unless v.nil? } + else + context.to_s.dup + end + end + def format_datetime(time) time.strftime(@datetime_format || DatetimeFormat) end + if RUBY_VERSION >= "2.7.0" + def filter_map_join(context, &blk) + context.filter_map(&blk).join(" ") + end + else + def filter_map_join(context, &blk) + context = context.map(&blk).compact.join(" ") + end + end + def msg2str(msg) case msg when ::String diff --git a/test/logger/test_formatter.rb b/test/logger/test_formatter.rb index 9465722..4af976a 100644 --- a/test/logger/test_formatter.rb +++ b/test/logger/test_formatter.rb @@ -9,14 +9,41 @@ def test_call progname = 'ruby' msg = 'This is a test' formatter = Logger::Formatter.new + time_matcher = /\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}/ result = formatter.call(severity, time, progname, msg) - time_matcher = /\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}/ matcher = /#{severity[0..0]}, \[#{time_matcher} #\d+\] #{severity} -- #{progname}: #{msg}\n/ assert_match(matcher, result) end + def test_call_with_context + severity = 'INFO' + time = Time.now + progname = 'ruby' + msg = 'This is a test' + formatter = Logger::Formatter.new + time_matcher = /\d{4}\-\d{2}\-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}/ + + # context as hash + result = formatter.call(severity, time, progname, msg, context: { foo: "bar" }) + matcher = /#{severity[0..0]}, \[foo=bar\] \[#{time_matcher} #\d+\] #{severity} -- #{progname}: #{msg}\n/ + assert_match(matcher, result) + + # context as array + result = formatter.call(severity, time, progname, msg, context: ["tag"]) + matcher = /#{severity[0..0]}, \[tag\] \[#{time_matcher} #\d+\] #{severity} -- #{progname}: #{msg}\n/ + assert_match(matcher, result) + + # context as nil + result = formatter.call(severity, time, progname, msg, context: nil) + matcher = /#{severity[0..0]}, \[#{time_matcher} #\d+\] #{severity} -- #{progname}: #{msg}\n/ + assert_match(matcher, result) + + # unsupported context + assert_raise(Logger::Error) { formatter.call(severity, time, progname, msg, context: Object.new) } + end + class CustomFormatter < Logger::Formatter def call(time) format_datetime(time) From 60146b70d4c2127fce52f1708ff1c589dc3de9be Mon Sep 17 00:00:00 2001 From: HoneyryderChuck Date: Wed, 13 Aug 2025 15:48:18 +0100 Subject: [PATCH 2/6] add support in logger API (only #info for now) to pass context down to the formatter as kwargs --- lib/logger.rb | 22 +++++++++++----------- test/logger/test_logger.rb | 29 ++++++++++++++++++++--------- 2 files changed, 31 insertions(+), 20 deletions(-) diff --git a/lib/logger.rb b/lib/logger.rb index be00457..16c0984 100644 --- a/lib/logger.rb +++ b/lib/logger.rb @@ -685,7 +685,7 @@ def reopen(logdev = nil, shift_age = nil, shift_size = nil, shift_period_suffix: # - #fatal. # - #unknown. # - def add(severity, message = nil, progname = nil) + def add(severity, message = nil, progname = nil, context: nil) severity ||= UNKNOWN if @logdev.nil? or severity < level return true @@ -702,7 +702,7 @@ def add(severity, message = nil, progname = nil) end end @logdev.write( - format_message(format_severity(severity), Time.now, progname, message)) + format_message(format_severity(severity), Time.now, progname, message, context: context)) true end alias log add @@ -724,37 +724,37 @@ def <<(msg) # Equivalent to calling #add with severity Logger::DEBUG. # - def debug(progname = nil, &block) + def debug(progname = nil, context: nil, &block) add(DEBUG, nil, progname, &block) end # Equivalent to calling #add with severity Logger::INFO. # - def info(progname = nil, &block) - add(INFO, nil, progname, &block) + def info(progname = nil, context: nil, &block) + add(INFO, nil, progname, context: context, &block) end # Equivalent to calling #add with severity Logger::WARN. # - def warn(progname = nil, &block) + def warn(progname = nil, context: nil, &block) add(WARN, nil, progname, &block) end # Equivalent to calling #add with severity Logger::ERROR. # - def error(progname = nil, &block) + def error(progname = nil, context: nil, &block) add(ERROR, nil, progname, &block) end # Equivalent to calling #add with severity Logger::FATAL. # - def fatal(progname = nil, &block) + def fatal(progname = nil, context: nil, &block) add(FATAL, nil, progname, &block) end # Equivalent to calling #add with severity Logger::UNKNOWN. # - def unknown(progname = nil, &block) + def unknown(progname = nil, context: nil, &block) add(UNKNOWN, nil, progname, &block) end @@ -796,7 +796,7 @@ def level_key Fiber.current end - def format_message(severity, datetime, progname, msg) - (@formatter || @default_formatter).call(severity, datetime, progname, msg) + def format_message(severity, datetime, progname, msg, **kwargs) + (@formatter || @default_formatter).call(severity, datetime, progname, msg, **kwargs) end end diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb index 75a0f74..e838cb2 100644 --- a/test/logger/test_logger.rb +++ b/test/logger/test_logger.rb @@ -11,25 +11,25 @@ def setup end class Log - attr_reader :label, :datetime, :pid, :severity, :progname, :msg + attr_reader :label, :context, :datetime, :pid, :severity, :progname, :msg def initialize(line) - /\A(\w+), \[([^#]*) #(\d+)\]\s+(\w+) -- (\w*): ([\x0-\xff]*)/ =~ line - @label, @datetime, @pid, @severity, @progname, @msg = $1, $2, $3, $4, $5, $6 + /\A(\w+),(?: ([^ ]+))? \[([^#]*) #(\d+)\]\s+(\w+) -- (\w*): ([\x0-\xff]*)/ =~ line + @label, @context, @datetime, @pid, @severity, @progname, @msg = $1, $2, $3, $4, $5, $6, $7 end end - def log_add(logger, severity, msg, progname = nil, &block) - log(logger, :add, severity, msg, progname, &block) + def log_add(logger, severity, msg, progname = nil, **kwargs, &block) + log(logger, :add, severity, msg, progname, **kwargs, &block) end - def log(logger, msg_id, *arg, &block) - Log.new(log_raw(logger, msg_id, *arg, &block)) + def log(logger, msg_id, *arg, **kwargs, &block) + Log.new(log_raw(logger, msg_id, *arg, **kwargs, &block)) end - def log_raw(logger, msg_id, *arg, &block) + def log_raw(logger, msg_id, *arg, **kwargs, &block) Tempfile.create(File.basename(__FILE__) + '.log') {|logdev| logger.instance_eval { @logdev = Logger::LogDevice.new(logdev) } - logger.__send__(msg_id, *arg, &block) + logger.__send__(msg_id, *arg, **kwargs, &block) logdev.rewind logdev.read } @@ -144,6 +144,17 @@ def test_datetime_format $VERBOSE = verbose end + def test_context + dummy = STDERR + logger = Logger.new(dummy) + log = log_add(logger, INFO, "bang", context: { foo: "bar" }) + assert_equal("[foo=bar]", log.context) + log = log_add(logger, INFO, "bang", context: ["tag"]) + assert_equal("[tag]", log.context) + log = log_add(logger, INFO, "bang", context: nil) + assert_equal(nil, log.context) + end + def test_formatter dummy = STDERR logger = Logger.new(dummy) From 3910bf913588275f23e1cbd52aa86f1adc9cec46 Mon Sep 17 00:00:00 2001 From: HoneyryderChuck Date: Wed, 13 Aug 2025 15:49:04 +0100 Subject: [PATCH 3/6] add support for Logger.with_context(context) {} for per-scope message context --- lib/logger.rb | 48 +++++++++++++++++++++++++++++++++-- test/logger/test_formatter.rb | 3 --- test/logger/test_logger.rb | 46 +++++++++++++++++++++++++++++++-- 3 files changed, 90 insertions(+), 7 deletions(-) diff --git a/lib/logger.rb b/lib/logger.rb index 16c0984..0910098 100644 --- a/lib/logger.rb +++ b/lib/logger.rb @@ -418,6 +418,33 @@ def with_level(severity) end end + def with_context(context) + fiber = Fiber.current + begin + prev_context = @context_store[fiber] + @context_store[fiber] = if prev_context.nil? + context + else + case context + when Hash + prev_context.merge(context) + when Array + prev_context + context + else + context + end + end + + yield + ensure + if prev_context.nil? + @context_store.delete(fiber) + else + @context_store[fiber] = prev_context + end + end + end + # Program name to include in log messages. attr_accessor :progname @@ -607,6 +634,7 @@ def initialize(logdev, shift_age = 0, shift_size = 1048576, level: DEBUG, self.formatter = formatter @logdev = nil @level_override = {} + @context_store = {}.compare_by_identity return unless logdev case logdev when File::NULL @@ -796,7 +824,23 @@ def level_key Fiber.current end - def format_message(severity, datetime, progname, msg, **kwargs) - (@formatter || @default_formatter).call(severity, datetime, progname, msg, **kwargs) + def format_message(severity, datetime, progname, msg, context: nil) + current_context = @context_store[Fiber.current] + formatter = @formatter || @default_formatter + + case context + when nil + context = current_context + when Hash + context = current_context.merge(context) if current_context + when Array + context = current_context + context if current_context + end + + if context.nil? + formatter.call(severity, datetime, progname, msg) + else + formatter.call(severity, datetime, progname, msg, context: context) + end end end diff --git a/test/logger/test_formatter.rb b/test/logger/test_formatter.rb index 4af976a..0bd0a7b 100644 --- a/test/logger/test_formatter.rb +++ b/test/logger/test_formatter.rb @@ -39,9 +39,6 @@ def test_call_with_context result = formatter.call(severity, time, progname, msg, context: nil) matcher = /#{severity[0..0]}, \[#{time_matcher} #\d+\] #{severity} -- #{progname}: #{msg}\n/ assert_match(matcher, result) - - # unsupported context - assert_raise(Logger::Error) { formatter.call(severity, time, progname, msg, context: Object.new) } end class CustomFormatter < Logger::Formatter diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb index e838cb2..5178536 100644 --- a/test/logger/test_logger.rb +++ b/test/logger/test_logger.rb @@ -13,8 +13,8 @@ def setup class Log attr_reader :label, :context, :datetime, :pid, :severity, :progname, :msg def initialize(line) - /\A(\w+),(?: ([^ ]+))? \[([^#]*) #(\d+)\]\s+(\w+) -- (\w*): ([\x0-\xff]*)/ =~ line - @label, @context, @datetime, @pid, @severity, @progname, @msg = $1, $2, $3, $4, $5, $6, $7 + /\A(\w+), ((?:\[[^\]]+\] )+)?\[([^#]*) #(\d+)\]\s+(\w+) -- (\w*): ([\x0-\xff]*)/ =~ line + @label, @context, @datetime, @pid, @severity, @progname, @msg = $1, $2&.strip, $3, $4, $5, $6, $7 end end @@ -240,6 +240,48 @@ def test_initialize_with_datetime_format assert_match(/^\d\d\w\w\w\d\d\d\d@\d\d:\d\d:\d\d$/, log.datetime) end + def test_with_context + # default + logger = Logger.new(STDERR) + log = log(logger, :info, "foo") + assert_equal(nil, log.context) + assert_equal("foo\n", log.msg) + # with hash context + logger.with_context(foo: "bar") do + log = log(logger, :info, "foo") + assert_equal("[foo=bar]", log.context) + assert_equal("foo\n", log.msg) + logger.with_context(ying: "yang") do + log = log(logger, :info, "foo") + assert_equal("[foo=bar] [ying=yang]", log.context) + assert_equal("foo\n", log.msg) + end + logger.with_context(foo: "bar2") do + log = log(logger, :info, "foo") + assert_equal("[foo=bar2]", log.context) + assert_equal("foo\n", log.msg) + end + end + log = log(logger, :info, "foo") + assert_equal(nil, log.context) + assert_equal("foo\n", log.msg) + + logger.with_context(["tag1"]) do + log = log(logger, :info, "foo") + assert_equal("[tag1]", log.context) + assert_equal("foo\n", log.msg) + logger.with_context(["tag2"]) do + log = log(logger, :info, "foo") + assert_equal("[tag1] [tag2]", log.context) + assert_equal("foo\n", log.msg) + end + end + + log = log(logger, :info, "foo") + assert_equal(nil, log.context) + assert_equal("foo\n", log.msg) + end + def test_reopen logger = Logger.new(STDERR) logger.reopen(STDOUT) From a01137130d8164269c7529a24ff7b72553c7cf26 Mon Sep 17 00:00:00 2001 From: HoneyryderChuck Date: Tue, 21 Oct 2025 12:18:09 +0100 Subject: [PATCH 4/6] putting context store interactions under private overridable functions --- lib/logger.rb | 45 +++++++++++++++++++++++++++++---------------- 1 file changed, 29 insertions(+), 16 deletions(-) diff --git a/lib/logger.rb b/lib/logger.rb index 0910098..4780af5 100644 --- a/lib/logger.rb +++ b/lib/logger.rb @@ -419,13 +419,12 @@ def with_level(severity) end def with_context(context) - fiber = Fiber.current begin - prev_context = @context_store[fiber] - @context_store[fiber] = if prev_context.nil? - context + prev_context = current_context + if prev_context.nil? + set_context(context) else - case context + context = case context when Hash prev_context.merge(context) when Array @@ -433,15 +432,12 @@ def with_context(context) else context end + set_context(context) end yield ensure - if prev_context.nil? - @context_store.delete(fiber) - else - @context_store[fiber] = prev_context - end + set_context(prev_context) end end @@ -623,10 +619,15 @@ def fatal!; self.level = FATAL; end # when creating a new log file. The default is +false+, meaning # the header will be written as usual. # + # - +context_store+: where the logging context is stored. default value is + # an hash which expects fiber objects as keys. + # See {Logging Context}[rdoc-ref:Logger@Logging+Context]: + # def initialize(logdev, shift_age = 0, shift_size = 1048576, level: DEBUG, progname: nil, formatter: nil, datetime_format: nil, binmode: false, shift_period_suffix: '%Y%m%d', - reraise_write_errors: [], skip_header: false) + reraise_write_errors: [], skip_header: false, + context_store: {}.compare_by_identity) self.level = level self.progname = progname @default_formatter = Formatter.new @@ -634,7 +635,7 @@ def initialize(logdev, shift_age = 0, shift_size = 1048576, level: DEBUG, self.formatter = formatter @logdev = nil @level_override = {} - @context_store = {}.compare_by_identity + @context_store = context_store return unless logdev case logdev when File::NULL @@ -799,6 +800,18 @@ def close private + def current_context + @context_store[Fiber.current] + end + + def set_context(val) + if val.nil? + @context_store.delete(Fiber.current) + else + @context_store[Fiber.current] = val + end + end + # \Severity label for logging (max 5 chars). SEV_LABEL = %w(DEBUG INFO WARN ERROR FATAL ANY).freeze @@ -825,16 +838,16 @@ def level_key end def format_message(severity, datetime, progname, msg, context: nil) - current_context = @context_store[Fiber.current] + current_ctx = current_context formatter = @formatter || @default_formatter case context when nil - context = current_context + context = current_ctx when Hash - context = current_context.merge(context) if current_context + context = current_ctx.merge(context) if current_ctx when Array - context = current_context + context if current_context + context = current_ctx + context if current_ctx end if context.nil? From feeba963d868ddb85e237711cdccdf42d10cc4c1 Mon Sep 17 00:00:00 2001 From: HoneyryderChuck Date: Tue, 21 Oct 2025 12:18:21 +0100 Subject: [PATCH 5/6] adding docs --- lib/logger.rb | 55 +++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 55 insertions(+) diff --git a/lib/logger.rb b/lib/logger.rb index 4780af5..37abd60 100644 --- a/lib/logger.rb +++ b/lib/logger.rb @@ -367,6 +367,61 @@ # see details and suggestions at # {Time#strftime}[https://docs.ruby-lang.org/en/master/Time.html#method-i-strftime]. # +# == Logging Context +# +# The logging context stores relevant data which should be written, as part of the +# formatted data, in log entries. The context data should be indexed by execution +# context. +# +# logger = Logger.new($stdout) +# logger.info('inline context', context: { foo: 'bar' }) +# # => I, [foo=bar] [2025-10-21T12:03:28.319551 #86131] INFO -- : inline context +# logger.info(context: { foo: 'bar' }) { 'block inline' } +# # => I, [foo=bar] [2025-10-21T12:03:53.568226 #86131] INFO -- : block inline +# logger.with_context(foo: "bar") do +# logger.info('one') +# logger.info('two') +# end +# I, [foo=bar] [2025-10-21T12:04:32.762566 #86131] INFO -- : one +# I, [foo=bar] [2025-10-21T12:04:32.762641 #86131] INFO -- : two +# +# The default store is a hash which indexes context by a (the current) fiber object. +# This means that context isn't shared across threads, and across fibers. +# +# logger = Logger.new($stdout) +# +# logger.with_context(foo: "bar") do +# Thread.start { logger.info('one') } +# logger.info('two') +# end +# I, [2025-10-21T12:08:04.614978 #86131] INFO -- : one +# I, [foo=bar] [2025-10-21T12:04:32.762641 #86131] INFO -- : two +# +# This could an issue in situations where propagating the context from the parent +# thread or fiber is desired. In such cases, you can pass a storage object, and +# override the functions required to support it. For example, this is how you could +# use the Fiber storage (ruby +3.2): +# +# class FiberLogger < Logger +# private +# +# def current_context +# context = Fiber[:fiber_logger_logging_context] ||= {}.compary_by_identity +# context[self] +# end +# +# def set_context(val) +# current_context = val +# end +# end +# +# logger = FiberLogger.new($stdout) +# +# Alternatively, you can have your own store object implementing #[](Fiber), +# #[]=(Fiber, untyped) and #delete(Fiber): +# +# logger = Logger.new($stdout, context_store: MyContext.new) +# class Logger _, name, rev = %w$Id$ if name From 71dba302161c12dcaa2f9b56a1be5c63ea3636a6 Mon Sep 17 00:00:00 2001 From: HoneyryderChuck Date: Tue, 21 Oct 2025 12:24:01 +0100 Subject: [PATCH 6/6] make the default context store a weak map --- lib/logger.rb | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/lib/logger.rb b/lib/logger.rb index 37abd60..606f9da 100644 --- a/lib/logger.rb +++ b/lib/logger.rb @@ -434,6 +434,14 @@ class Logger include Severity + # Must respond to .new and return a Hash-like object. + # The returned object must respond to #[], #[]=, #delete. + # + # ObjectSpace::WeakKeyMap when supported. + OverrideMap = + defined?(ObjectSpace::WeakKeyMap) ? ObjectSpace::WeakKeyMap : Hash + private_constant :OverrideMap + # Logging severity threshold (e.g. Logger::INFO). def level level_override[level_key] || @level @@ -682,7 +690,7 @@ def initialize(logdev, shift_age = 0, shift_size = 1048576, level: DEBUG, progname: nil, formatter: nil, datetime_format: nil, binmode: false, shift_period_suffix: '%Y%m%d', reraise_write_errors: [], skip_header: false, - context_store: {}.compare_by_identity) + context_store: OverrideMap.new) self.level = level self.progname = progname @default_formatter = Formatter.new