From 6041bd04e8be0ec3b5e850f66fe932a8f5941237 Mon Sep 17 00:00:00 2001 From: Jared Armstrong Date: Mon, 30 Sep 2024 13:48:59 +1300 Subject: [PATCH] Refactor BroadcastLogger; only execute blocks once [Fixes #49745 #52876] [Related #51883 #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. --- .../lib/active_support/broadcast_logger.rb | 120 ++++++------------ activesupport/test/broadcast_logger_test.rb | 42 ++++-- railties/lib/rails/application/bootstrap.rb | 4 +- 3 files changed, 65 insertions(+), 101 deletions(-) diff --git a/activesupport/lib/active_support/broadcast_logger.rb b/activesupport/lib/active_support/broadcast_logger.rb index 4cc1e35914056..cc7dacb327658 100644 --- a/activesupport/lib/active_support/broadcast_logger.rb +++ b/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, ...) diff --git a/activesupport/test/broadcast_logger_test.rb b/activesupport/test/broadcast_logger_test.rb index 5f94480cb3db0..63d92c4c8e4fd 100644 --- a/activesupport/test/broadcast_logger_test.rb +++ b/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? diff --git a/railties/lib/rails/application/bootstrap.rb b/railties/lib/rails/application/bootstrap.rb index 95295522e7e85..eff76f9d8605a 100644 --- a/railties/lib/rails/application/bootstrap.rb +++ b/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