Fix TaggedLogging functionality when broadcasting:

- This PR fixes two issues with the Tagged Logging feature in
  conjunction with broadcasting logs.

  For the sake of clarity I'll define the "main logger" and
  the "broadcasted logger" in this snippet:

  ```ruby
    main_logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(io))
    broadcaster_logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(io))

    main_logger.extend(Activesupport::Logger.broadcast(broadcasted_logger))
  ```

  1) The first issue that this PR fixes, is that the tags on the "main logger"
     don't propagate to the "broadcasted logger" when you pass in a block.

     ```ruby
     main_logger.tagged("FOO") { |logger| logger.info("Hello") }

     # Outputs:
     # [Foo] Hello <- By the main logger
     # Hello       <- By the broadcasted logger
     ```

     A fix was made in 70af536b5d
     but that only works for the non block version

  2) It's quite common for the "broadcasted logger" to have a diffent
     log formatter that the "main logger". In example you'd want to
     output JSON logs in one and raw text in the other.

     That wasn't possible before. All loggers had to have the same
     instance of the formatter. The formatter was set on all loggers
     thanks to [this](3fc9d12875/activesupport/lib/active_support/logger.rb (L45-L48)) and it's [associated test](3fc9d12875/activesupport/test/broadcast_logger_test.rb (L58-L64))
     This requirement was needed to make the Tagged Logging feature
     work; the tags being set in a thread variable whose name
     uses the `object_id` 3fc9d12875/activesupport/lib/active_support/tagged_logging.rb (L59)
     (different formatter instance -> different object_id -> different variables)

     In this PR, I have removed the code that sets the same formatter
     instance on all logger. The "broadcaster logger" just need to
     have the `current_tags` point to the `current_tags` of the
     "main logger", I'm doing that by redefing the `current_tags`
     method each time the "main logger" uses a different formatter.

     The advantages by doing so is that custom made formatter
     can now call this `current_tags` method, which will return
     all the tags and process them the way they want.

     ```ruby
       class JSONLogFormatter
         def call(_, _, _, msg)
	   tags = current_tags # Can now retrieve the tags

	   { message: msg, tags: tags }.to_json
	 end
       end

       broadcasted_logger = Logger.new(io)
       broadcaster_logger.formatter = JSONLogFormatter.new
       main_logger = Logger.new(io)
       main_logger.extend(ActiveSupport::Logger.broadcast(broadcasted_logger))
     ```

     The behavior remains the same as before if a logger uses the
     Rails vanilla formatter or the Tagged Logging formatter.
This commit is contained in:
Edouard CHIN 2022-03-15 09:39:05 +01:00
parent 0ee85c7992
commit 75aa3a07ec
4 changed files with 77 additions and 13 deletions

View File

@ -22,6 +22,10 @@ module ActiveSupport
# Broadcasts logs to multiple loggers.
def self.broadcast(logger) # :nodoc:
Module.new do
define_singleton_method(:extended) do |base|
base.public_send(:broadcast_to, logger) if base.respond_to?(:broadcast_to)
end
define_method(:add) do |*args, &block|
logger.add(*args, &block)
super(*args, &block)
@ -42,11 +46,6 @@ module ActiveSupport
super(name)
end
define_method(:formatter=) do |formatter|
logger.formatter = formatter
super(formatter)
end
define_method(:level=) do |level|
logger.level = level
super(level)

View File

@ -1,6 +1,7 @@
# frozen_string_literal: true
require "active_support/core_ext/module/delegation"
require "active_support/core_ext/module/redefine_method"
require "active_support/core_ext/object/blank"
require "logger"
require "active_support/logger"
@ -94,6 +95,20 @@ module ActiveSupport
delegate :push_tags, :pop_tags, :clear_tags!, to: :formatter
def broadcast_to(other_logger) # :nodoc:
define_singleton_method(:formatter=) do |formatter|
other_logger.formatter ||= formatter
other_logger.formatter.singleton_class.redefine_method(:current_tags) do
formatter.current_tags
end
super(formatter)
end
self.formatter = self.formatter.clone
end
def tagged(*tags)
if block_given?
formatter.tagged(*tags) { yield self }

View File

@ -55,14 +55,6 @@ module ActiveSupport
assert_equal ::Logger::FATAL, log2.progname
end
test "#formatter= assigns to all the loggers" do
assert_nil logger.formatter
logger.formatter = ::Logger::FATAL
assert_equal ::Logger::FATAL, log1.formatter
assert_equal ::Logger::FATAL, log2.formatter
end
test "#local_level= assigns the local_level to all loggers" do
assert_equal ::Logger::DEBUG, logger.local_level
logger.local_level = ::Logger::FATAL

View File

@ -226,4 +226,62 @@ class TaggedLoggingWithoutBlockTest < ActiveSupport::TestCase
assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "[OMG] Broadcasting...\n", broadcast_output.string
end
test "keeps broadcasting functionality when passed a block" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::TaggedLogging.new(Logger.new(broadcast_output))
@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
@logger.tagged("OMG") { |logger| logger.info "Broadcasting..." }
assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "[OMG] Broadcasting...\n", broadcast_output.string
end
test "broadcasting when passing a block works and keeps formatter untouched" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::TaggedLogging.new(Logger.new(broadcast_output))
my_formatter = Class.new do
def call(_, _, _, msg)
ActiveSupport::JSON.encode(message: msg, tags: current_tags)
end
end
broadcast_logger.formatter = my_formatter.new
@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
@logger.tagged("OMG") { |logger| logger.info "Broadcasting..." }
assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "{\"message\":\"Broadcasting...\",\"tags\":[\"OMG\"]}", broadcast_output.string
end
test "broadcasting without passing a block works and keeps formatter untouched" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::TaggedLogging.new(Logger.new(broadcast_output))
my_formatter = Class.new do
def call(_, _, _, msg)
ActiveSupport::JSON.encode(message: msg, tags: current_tags)
end
end
broadcast_logger.formatter = my_formatter.new
@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
tagger_logger1 = @logger.tagged("OMG")
tagger_logger2 = tagger_logger1.tagged("FOO")
tagger_logger2.info("Broadcasting...")
assert_equal "[OMG] [FOO] Broadcasting...\n", @output.string
assert_equal "{\"message\":\"Broadcasting...\",\"tags\":[\"OMG\",\"FOO\"]}", broadcast_output.string
end
test "broadcasting on a non tagged logger" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::Logger.new(broadcast_output)
@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
@logger.tagged("OMG") { |logger| logger.info "Broadcasting..." }
assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "Broadcasting...\n", broadcast_output.string
end
end