diff --git a/lib/logger.rb b/lib/logger.rb
index be00457..606f9da 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
@@ -379,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
@@ -418,6 +481,29 @@ def with_level(severity)
end
end
+ def with_context(context)
+ begin
+ prev_context = current_context
+ if prev_context.nil?
+ set_context(context)
+ else
+ context = case context
+ when Hash
+ prev_context.merge(context)
+ when Array
+ prev_context + context
+ else
+ context
+ end
+ set_context(context)
+ end
+
+ yield
+ ensure
+ set_context(prev_context)
+ end
+ end
+
# Program name to include in log messages.
attr_accessor :progname
@@ -596,10 +682,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: OverrideMap.new)
self.level = level
self.progname = progname
@default_formatter = Formatter.new
@@ -607,6 +698,7 @@ def initialize(logdev, shift_age = 0, shift_size = 1048576, level: DEBUG,
self.formatter = formatter
@logdev = nil
@level_override = {}
+ @context_store = context_store
return unless logdev
case logdev
when File::NULL
@@ -685,7 +777,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 +794,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 +816,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
@@ -771,6 +863,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
@@ -796,7 +900,23 @@ 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, context: nil)
+ current_ctx = current_context
+ formatter = @formatter || @default_formatter
+
+ case context
+ when nil
+ context = current_ctx
+ when Hash
+ context = current_ctx.merge(context) if current_ctx
+ when Array
+ context = current_ctx + context if current_ctx
+ 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/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..0bd0a7b 100644
--- a/test/logger/test_formatter.rb
+++ b/test/logger/test_formatter.rb
@@ -9,14 +9,38 @@ 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)
+ end
+
class CustomFormatter < Logger::Formatter
def call(time)
format_datetime(time)
diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb
index 75a0f74..5178536 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&.strip, $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)
@@ -229,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)