From 75aa3a07ecc00e659fcec5656d25bfff54cdf205 Mon Sep 17 00:00:00 2001 From: Edouard CHIN Date: Tue, 15 Mar 2022 09:39:05 +0100 Subject: [PATCH] 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 https://github.com/rails/rails/commit/70af536b5d6e57800cb6b6b9a10f33b39192113e 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](https://github.com/rails/rails/blob/3fc9d12875dd434e454f74472da02014f6fa5d72/activesupport/lib/active_support/logger.rb#L45-L48) and it's [associated test](https://github.com/rails/rails/blob/3fc9d12875dd434e454f74472da02014f6fa5d72/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` https://github.com/rails/rails/blob/3fc9d12875dd434e454f74472da02014f6fa5d72/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. --- activesupport/lib/active_support/logger.rb | 9 ++- .../lib/active_support/tagged_logging.rb | 15 +++++ activesupport/test/broadcast_logger_test.rb | 8 --- activesupport/test/tagged_logging_test.rb | 58 +++++++++++++++++++ 4 files changed, 77 insertions(+), 13 deletions(-) diff --git a/activesupport/lib/active_support/logger.rb b/activesupport/lib/active_support/logger.rb index 1e241c13ac9ef..131fecc0e2d0e 100644 --- a/activesupport/lib/active_support/logger.rb +++ b/activesupport/lib/active_support/logger.rb @@ -22,6 +22,10 @@ def self.logger_outputs_to?(logger, *sources) # 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 @@ def self.broadcast(logger) # :nodoc: super(name) end - define_method(:formatter=) do |formatter| - logger.formatter = formatter - super(formatter) - end - define_method(:level=) do |level| logger.level = level super(level) diff --git a/activesupport/lib/active_support/tagged_logging.rb b/activesupport/lib/active_support/tagged_logging.rb index 26852e590ac05..3e2389805ac17 100644 --- a/activesupport/lib/active_support/tagged_logging.rb +++ b/activesupport/lib/active_support/tagged_logging.rb @@ -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 @@ def self.new(logger) 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 } diff --git a/activesupport/test/broadcast_logger_test.rb b/activesupport/test/broadcast_logger_test.rb index 4dd461037db55..f3714387d8fa5 100644 --- a/activesupport/test/broadcast_logger_test.rb +++ b/activesupport/test/broadcast_logger_test.rb @@ -55,14 +55,6 @@ class BroadcastLoggerTest < TestCase 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 diff --git a/activesupport/test/tagged_logging_test.rb b/activesupport/test/tagged_logging_test.rb index fb9aca78e3f40..2bd4b92eed0ec 100644 --- a/activesupport/test/tagged_logging_test.rb +++ b/activesupport/test/tagged_logging_test.rb @@ -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