Skip to content

Commit

Permalink
BroadcastLogger should support TaggedLogging correctly.
Browse files Browse the repository at this point in the history
[Fixes rails#49745 rails#52876]
[Related rails#51883 rails#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)
    }
  }
  ```
  • Loading branch information
armstrjare committed Sep 30, 2024
1 parent ba468db commit fe87449
Show file tree
Hide file tree
Showing 2 changed files with 91 additions and 0 deletions.
26 changes: 26 additions & 0 deletions activesupport/lib/active_support/tagged_logging.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -155,3 +179,5 @@ def flush
end
end
end

ActiveSupport::BroadcastLogger.include ActiveSupport::TaggedLogging::Broadcasting
65 changes: 65 additions & 0 deletions activesupport/test/tagged_logging_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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

0 comments on commit fe87449

Please sign in to comment.