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.

Author: armstrjare

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,36 @@ 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(...) }
+    def local_level=(level)
+      @broadcasts.each do |logger|
+        logger.local_level = level if logger.respond_to?(:local_level=)
+      end
     end
 
-    def formatter=(formatter)
-      dispatch { |logger| logger.formatter = formatter }
-
-      @formatter = formatter
-    end
+    def local_level
+      loggers = @broadcasts.select { |logger| logger.respond_to?(:local_level) }
 
-    def level=(level)
-      dispatch { |logger| logger.level = level }
+      loggers.map do |logger|
+        logger.local_level
+      end.first
     end
-    alias_method :sev_threshold=, :level=
 
-    def local_level=(level)
-      dispatch do |logger|
-        logger.local_level = level if logger.respond_to?(:local_level=)
-      end
+    LOGGER_METHODS = %w[
+      << log add debug info warn error fatal unknown
+      level= sev_threshold= close
+      formatter formatter=
+    ] # :nodoc:
+    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
@@ -171,7 +144,7 @@ def debug?
 
     # Sets the log level to +Logger::DEBUG+ for the whole broadcast.
     def debug!
-      dispatch { |logger| logger.debug! }
+      dispatch(:debug!)
     end
 
     # True if the log level allows entries with severity +Logger::INFO+ to be written
@@ -182,7 +155,7 @@ def info?
 
     # Sets the log level to +Logger::INFO+ for the whole broadcast.
     def info!
-      dispatch { |logger| logger.info! }
+      dispatch(:info!)
     end
 
     # True if the log level allows entries with severity +Logger::WARN+ to be written
@@ -193,7 +166,7 @@ def warn?
 
     # Sets the log level to +Logger::WARN+ for the whole broadcast.
     def warn!
-      dispatch { |logger| logger.warn! }
+      dispatch(:warn!)
     end
 
     # True if the log level allows entries with severity +Logger::ERROR+ to be written
@@ -204,7 +177,7 @@ def error?
 
     # Sets the log level to +Logger::ERROR+ for the whole broadcast.
     def error!
-      dispatch { |logger| logger.error! }
+      dispatch(:error!)
     end
 
     # True if the log level allows entries with severity +Logger::FATAL+ to be written
@@ -215,21 +188,35 @@ def fatal?
 
     # Sets the log level to +Logger::FATAL+ for the whole broadcast.
     def fatal!
-      dispatch { |logger| logger.fatal! }
+      dispatch(: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|
+          logger.send(method, *args, **kwargs, &block)
+        }.first
       end
 
       def method_missing(name, ...)

activesupport/test/broadcast_logger_test.rb

@@ -268,14 +268,28 @@ def info(msg, &block)
       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 +370,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 +399,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

@@ -59,9 +59,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