-
Notifications
You must be signed in to change notification settings - Fork 69
Description
The logger gem is notoriously simple to use, but hard to extend.
One can only observe a few of the gems that added tags / json / logstash formatting support to see the same functionality reimplemented in "same but different" ways. For example, logstash-logger and the activesupport logger handle tagging in virtually the same way. sidekiq has a (IMO) convoluted API to add per-job context to log message, which somewhat works as long as one does not need per-fiber contexts. Several other "log as JSON" gems fight with the same issues to deliver something that works, and either heavily patch the Logger or Logger::Formatter or circumvent its usage altogether.
At a company I worked for, an internal logging library, built on top of logger, even added support for context by allowing functions like #info to receive a hash (i.e. log.info(message: "foo", user_id: 2, ...)), something which was completely non-standard and couldn't possibly work with the log.info { "foo" } idiom.
I think that some of these patterns could be coalesced into the main logger gem in a way that extending it should be simpler than what it is right now.
For the record, the default formatter already supports per-message context, but that context is limited to a few "static" parameters (severity, current time, process id, progname) which are logged in a non-standard manner:
Logger.new(STDOUT).info("foo")
#=> I, [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
There is currently no way to add more parameters, or (if necessary) override the existing ones.
Context API
This is a proposal to extend the Logger API in a way that both per-scope or per-message context can be passed downstream to the formatter(s), and logged accordingly:
logger = Logger.new(STDOUT)
logger.info("foo") #=> I, [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
logger.info { "foo" } #=> I, [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
# per message context
logger.info("foo", user_id: 1) #=> I, [user_id=1] [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
logger.info(user_id: 1) { "foo" } #=> I, [user_id=1] [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
# or
logger.info("foo", "user_id=1") #=> I, [user_id=1] [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
# per message context
logger.with_context(a: 1) do
logger.info("foo") #=> I, [a=1] [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
end
logger.with_context(a: 1) do
logger.with_context(b: 2) do
logger.info("foo") #=> I, [a=1] [b=2] [2025-08-13T15:00:03.830782 #5374] INFO -- : foo
end
endThis API would achieve the same goal as the #tagged examples liked above, or the sidekiq Logger#with function, in a standard manner, where formatters would just receive them as a bunch of key-value pairs (or an array of "string-able" objects, both work for me).
I think that it builds on top of the earlier addition of Logger#with_level, which does the scope-based change in a similar way, but didn't go further than providing this functionality for other context variables (this proposal fixes that).
By standardizing this part, adding i.e. a JSON or logstash formatter would be way less "involved", as one of the limitations nowadays is that there's no way to pass this per-message context via its API (this is the main reason why the sidekiq formatter uses thread variables).
Drawbacks
One of the main benefits of using the log.info { "msg" } idiom is that the "msg" string never gets allocated if the logger severity level skips logging the message. In the current proposal, the context is always present, and will result in a few allocations bubbling downstream. I'm not sure how important or negligible this concern is though.
A concern here would be backwards compatibility, as currently, custom formatters do not expose a method signature which allows sending kwargs. Perhaps there's a way to introspect the formatter method to infer whether the signature supports kwargs, but even if it does, the check does have its cost.