From fe8744950c953b95e18571122f020e83aef60811 Mon Sep 17 00:00:00 2001 From: Jared Armstrong Date: Mon, 30 Sep 2024 13:42:45 +1300 Subject: [PATCH] BroadcastLogger should support TaggedLogging correctly. [Fixes #49745 #52876] [Related #51883 #49771] This commit extends BroadcastLogger when TaggedLogging is loaded in order to ensure that BroadcastLogger#tagged behaves as expected when there are multiple loggers being broadcast to. TaggedLogging provides two related, but distinct interfaces: 1. Calling `logger.tagged(*tags)` without a block returns a new Logger with the provided tags pushed to its tag stack. 2. Calling `logger.tagged(*tags) { |logger| ... }` with a block pushes the tags to the existing Logger and yields the logger to block. Previously, BroadcastLogger would only function as expected if there was just one Logger being broadcast to. When there were multiple loggers: when calling `tagged` with a block, it would yield a block multiple times, once for each logger; when called without a block, it would call `tagged` on each logger and return an Array of the results. This inconsistent behaviour has caused issues such as those referenced above. In development environments in particular, logger configuration can often result in a BroadcastLogger with two loggers, since the `bin/rails server` command will always broadcast to STDOUT, resulting in confusing behaviour. This commit provides a `BroadcastLogger#tagged` implementation that, for the non-block form returns a new BroadcastLogger broadcasting to the new tagged Loggers, and for the block-form, it 'wraps' the user-provided block within nested calls to `TaggedLogging#logged`. The user-provided block is only executed in the innermost call. For example: ```ruby # BroadcastLogger with two Loggers being broadcasted to broadcaster.tagged("FOO") { |logger| ... } ``` Would execute similarly to: ```ruby broadcasts[0].tagged("FOO") { broadcasts[1].tagged("FOO") { yield(broadcaster) } } ``` --- .../lib/active_support/tagged_logging.rb | 26 ++++++++ activesupport/test/tagged_logging_test.rb | 65 +++++++++++++++++++ 2 files changed, 91 insertions(+) diff --git a/activesupport/lib/active_support/tagged_logging.rb b/activesupport/lib/active_support/tagged_logging.rb index 594ea30e056c3..b7c3660eb02d3 100644 --- a/activesupport/lib/active_support/tagged_logging.rb +++ b/activesupport/lib/active_support/tagged_logging.rb @@ -27,6 +27,30 @@ module ActiveSupport # it easy to stamp log lines with subdomains, request ids, and anything else # to aid debugging of multi-user production applications. module TaggedLogging + # This module is included in ActiveSupport::BroadcastLogger to enable + # broadcasting to tagged loggers with equivalent semantics. + module Broadcasting + def tagged(*tags, &block) + return super unless broadcasts.any? { |logger| logger.respond_to?(:tagged) } + + if block_given? + # `tagged(...) { |logger| ... }` yields itself to the block + broadcasts.inject(block) do |block, logger| + if logger.respond_to?(:tagged) + proc { logger.tagged(*tags) { block.call(self) } } + else + block + end + end.call + else + # `tagged(...) returns a new logger with the tags pushed + self.class.new(*broadcasts.map { |logger| + logger.respond_to?(:tagged) ? logger.tagged(*tags) : logger + }) + end + end + end + module Formatter # :nodoc: # This method is invoked when a log event occurs. def call(severity, timestamp, progname, msg) @@ -155,3 +179,5 @@ def flush end end end + +ActiveSupport::BroadcastLogger.include ActiveSupport::TaggedLogging::Broadcasting diff --git a/activesupport/test/tagged_logging_test.rb b/activesupport/test/tagged_logging_test.rb index 3cae39ab56522..6e4289e7e4bf9 100644 --- a/activesupport/test/tagged_logging_test.rb +++ b/activesupport/test/tagged_logging_test.rb @@ -259,3 +259,68 @@ def crozz_method assert_equal "[tag] [1, 2, 3]\n", @output.string end end + +class TaggedLoggingBroadcastingTest < ActiveSupport::TestCase + setup do + @output1 = StringIO.new + @output2 = StringIO.new + @logger1 = ActiveSupport::TaggedLogging.new(Logger.new(@output1)) + @logger2 = ActiveSupport::TaggedLogging.new(Logger.new(@output2)) + @logger = ActiveSupport::BroadcastLogger.new(@logger1, @logger2) + end + + test "tags with a block" do + @logger.tagged("BCX") { @logger.info "Funky time" } + assert_equal "[BCX] Funky time\n", @output1.string + assert_equal "[BCX] Funky time\n", @output1.string + end + + test "yields the logger to the block" do + @logger.tagged("BCX") do |logger| + assert_equal @logger, logger + end + end + + test "returns the return value of the block" do + return_value = @logger.tagged("BCX") do + "Cool story" + end + assert_equal "Cool story", return_value + end + + test "it returns a tagged logger without a block" do + logger = @logger.tagged("BCX") + logger.info "Funky time" + assert_equal "[BCX] Funky time\n", @output1.string + assert_equal "[BCX] Funky time\n", @output2.string + end + + test "it doesn't tag the original logger without a block" do + @logger.tagged("BCX") + @logger.info "Funky time" + assert_equal "Funky time\n", @output1.string + assert_equal "Funky time\n", @output2.string + end + + test "it ignores non-tagged loggers with a block" do + plain_output = StringIO.new + plain_logger = ActiveSupport::Logger.new(plain_output) + @logger.broadcast_to(plain_logger) + + @logger.tagged("BCX") { @logger.info "Block funky time" } + @logger.tagged("BCX").info "Chain cool story" + assert_equal(<<~STR, plain_output.string) + Block funky time + Chain cool story + STR + end + + test "it ignores non-tagged loggers without a block" do + plain_output = StringIO.new + plain_logger = ActiveSupport::Logger.new(plain_output) + @logger.broadcast_to(plain_logger) + + @logger.tagged("BCX").info "Cool story" + assert_equal "Cool story\n", plain_output.string + end +end