Refactor BroadcastLogger; only execute blocks once

[Fixes rails#49745 rails#52876]
[Related rails#51883 rails#49771]

This commit refactors the implementation of dispatching method calls
to broadcasted loggers. The updated implementation ensures that any
block is only executed once. The first logger would recieve the block
as per normal, but subsequent loggers would only yield the result of
the initial execution.

The updated implementation of `dispatch` opened up an opportunity to
refactor the way each Logger method is delegatated to broadcasted
loggers - simplifying the delegator definitions.

Prior to these changes, BroadcastLoggers would iterate each broadcast
and re-execute the user provided block for each.

The consumer of any Logger would reasonably expect than when calling a
method with a block, that the block would only execute a single time.
That is, the fact that a Logger is a BroadcastLogger should be
irrelevant to consumer.

The most common example of this is when using
ActiveSupport::TaggedLogging and wrapping behaviour in a
`tagged(*tags) { }` block. But this also applies when using the block
form `info`, `warn` etc. If a BroadcastLogger is used, and there are
multiple loggers being broadcast to, then calling one of these methods
with a block would result in the block being executed multiple times.

For example:

```ruby
  broadcasts = ActiveSupport::BroadcastLogger.new(
    *Array.new(2) { ActiveSupport::Logger.new(STDOUT) }
  )
  number = 0
  broadcasts.info {
    number += 1
    "Updated number to #{number}"
  }
  # Expected:
  # Updated number to 1
  # Updated number to 1
  #
  # Actual:
  # Updated number to 1
  # Updated number to 2
```

After these changes, the behaviour of BroadcastLogger reflects the
expected behaviour above.

activesupport/lib/active_support/broadcast_logger.rb

@@ -76,7 +76,6 @@ class BroadcastLogger
 
     # Returns all the logger that are part of this broadcast.
     attr_reader :broadcasts
-    attr_reader :formatter
     attr_accessor :progname
 
     def initialize(*loggers)
@@ -105,62 +104,24 @@ def stop_broadcasting_to(logger)
       @broadcasts.delete(logger)
     end
 
-    def level
-      @broadcasts.map(&:level).min
-    end
-
-    def <<(message)
-      dispatch { |logger| logger.<<(message) }
-    end
-
-    def add(...)
-      dispatch { |logger| logger.add(...) }
-    end
-    alias_method :log, :add
-
-    def debug(...)
-      dispatch { |logger| logger.debug(...) }
-    end
-
-    def info(...)
-      dispatch { |logger| logger.info(...) }
-    end
-
-    def warn(...)
-      dispatch { |logger| logger.warn(...) }
-    end
-
-    def error(...)
-      dispatch { |logger| logger.error(...) }
-    end
-
-    def fatal(...)
-      dispatch { |logger| logger.fatal(...) }
-    end
-
-    def unknown(...)
-      dispatch { |logger| logger.unknown(...) }
-    end
-
-    def formatter=(formatter)
-      dispatch { |logger| logger.formatter = formatter }
-
-      @formatter = formatter
-    end
-
-    def level=(level)
-      dispatch { |logger| logger.level = level }
-    end
-    alias_method :sev_threshold=, :level=
-
-    def local_level=(level)
-      dispatch do |logger|
-        logger.local_level = level if logger.respond_to?(:local_level=)
-      end
+    # Forward all standard Logger methods to each logger in the broadcast.
+    LOGGER_METHODS = %w[
+      << log add debug info warn error fatal unknown
+      debug! info! warn! error! fatal!
+      level= sev_threshold= local_level local_level= close
+      formatter formatter=
+    ]
+    LOGGER_METHODS.each do |method|
+      class_eval <<-RUBY, __FILE__, __LINE__ + 1
+        def #{method}(...)
+          dispatch(:#{method}, ...)
+        end
+      RUBY
     end
 
-    def close
-      dispatch { |logger| logger.close }
+    # Returns the lowest level of all the loggers in the broadcast.
+    def level
+      @broadcasts.map(&:level).min
     end
 
     # +True+ if the log level allows entries with severity Logger::DEBUG to be written
@@ -169,67 +130,58 @@ def debug?
       @broadcasts.any? { |logger| logger.debug? }
     end
 
-    # Sets the log level to Logger::DEBUG for the whole broadcast.
-    def debug!
-      dispatch { |logger| logger.debug! }
-    end
-
     # +True+ if the log level allows entries with severity Logger::INFO to be written
     # to at least one broadcast. +False+ otherwise.
     def info?
       @broadcasts.any? { |logger| logger.info? }
     end
 
-    # Sets the log level to Logger::INFO for the whole broadcast.
-    def info!
-      dispatch { |logger| logger.info! }
-    end
-
     # +True+ if the log level allows entries with severity Logger::WARN to be written
     # to at least one broadcast. +False+ otherwise.
     def warn?
       @broadcasts.any? { |logger| logger.warn? }
     end
 
-    # Sets the log level to Logger::WARN for the whole broadcast.
-    def warn!
-      dispatch { |logger| logger.warn! }
-    end
-
     # +True+ if the log level allows entries with severity Logger::ERROR to be written
     # to at least one broadcast. +False+ otherwise.
     def error?
       @broadcasts.any? { |logger| logger.error? }
     end
 
-    # Sets the log level to Logger::ERROR for the whole broadcast.
-    def error!
-      dispatch { |logger| logger.error! }
-    end
-
     # +True+ if the log level allows entries with severity Logger::FATAL to be written
     # to at least one broadcast. +False+ otherwise.
     def fatal?
       @broadcasts.any? { |logger| logger.fatal? }
     end
 
-    # Sets the log level to Logger::FATAL for the whole broadcast.
-    def fatal!
-      dispatch { |logger| logger.fatal! }
-    end
-
     def initialize_copy(other)
       @broadcasts = []
       @progname = other.progname.dup
-      @formatter = other.formatter.dup
 
       broadcast_to(*other.broadcasts.map(&:dup))
     end
 
     private
-      def dispatch(&block)
-        @broadcasts.each { |logger| block.call(logger) }
-        true
+      def dispatch(method, *args, **kwargs, &block)
+        if block_given?
+          # Maintain semantics that the first logger yields the block
+          # as normal, but subsequent loggers won't re-execute the block.
+          # Instead, the initial result is immediately returned.
+          called, result = false, nil
+          block = proc { |*args, **kwargs|
+            if called then result
+            else
+              called = true
+              result = yield(*args, **kwargs)
+            end
+          }
+        end
+
+        @broadcasts.map { |logger|
+          if logger.respond_to?(method)
+            logger.send(method, *args, **kwargs, &block)
+          end
+        }.first
       end
 
       def method_missing(name, ...)

activesupport/test/broadcast_logger_test.rb

@@ -264,18 +264,31 @@ def info(msg, &block)
 
     test "calling a method when a subset of loggers in the broadcast have implemented" do
       logger = BroadcastLogger.new(CustomLogger.new, FakeLogger.new)
-
       assert(logger.foo)
     end
 
-    test "calling a method that accepts a block" do
-      logger = BroadcastLogger.new(CustomLogger.new)
+    test "methods are called on each logger" do
+      calls = 0
+      loggers = [CustomLogger.new, FakeLogger.new, CustomLogger.new].each do |logger|
+        logger.define_singleton_method(:special_method) do
+          calls += 1
+        end
+      end
+      logger = BroadcastLogger.new(*loggers)
+      logger.special_method
+      assert_equal(3, calls)
+    end
 
-      called = false
-      logger.bar do
-        called = true
+    test "calling a method that accepts a block is yielded only once" do
+      called = 0
+      logger.info do
+        called += 1
+        "Hello"
       end
-      assert(called)
+
+      assert_equal 1, called, "block should be called just once"
+      assert_equal [[::Logger::INFO, "Hello", nil]], log1.adds
+      assert_equal [[::Logger::INFO, "Hello", nil]], log2.adds
     end
 
     test "calling a method that accepts args" do
@@ -356,27 +369,27 @@ def qux(param:)
         true
       end
 
-      def debug(message, &block)
+      def debug(message = nil, &block)
         add(::Logger::DEBUG, message, &block)
       end
 
-      def info(message, &block)
+      def info(message = nil, &block)
         add(::Logger::INFO, message, &block)
       end
 
-      def warn(message, &block)
+      def warn(message = nil, &block)
         add(::Logger::WARN, message, &block)
       end
 
-      def error(message, &block)
+      def error(message = nil, &block)
         add(::Logger::ERROR, message, &block)
       end
 
-      def fatal(message, &block)
+      def fatal(message = nil, &block)
         add(::Logger::FATAL, message, &block)
       end
 
-      def unknown(message, &block)
+      def unknown(message = nil, &block)
         add(::Logger::UNKNOWN, message, &block)
       end
 
@@ -385,7 +398,8 @@ def <<(x)
       end
 
       def add(message_level, message = nil, progname = nil, &block)
-        @adds << [message_level, message, progname] if message_level >= local_level
+        @adds << [message_level, block_given? ? block.call : message, progname] if message_level >= local_level
+        true
       end
 
       def debug?

railties/lib/rails/application/bootstrap.rb

@@ -60,9 +60,7 @@ module Bootstrap
           end
         else
           Rails.logger.level = ActiveSupport::Logger.const_get(config.log_level.to_s.upcase)
-          broadcast_logger = ActiveSupport::BroadcastLogger.new(Rails.logger)
-          broadcast_logger.formatter = Rails.logger.formatter
-          Rails.logger = broadcast_logger
+          Rails.logger = ActiveSupport::BroadcastLogger.new(Rails.logger)
         end
       end