From 2ea54e1aebcdb969cb2b760146c747a6b9889e13 Mon Sep 17 00:00:00 2001 From: Edouard CHIN Date: Fri, 30 Jun 2023 02:09:47 +0200 Subject: [PATCH] Add a public API for broadcasting logs: MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - ## Context While working on https://github.com/rails/rails/pull/44695, I realised that Broadcasting was still a private API, although it’s commonly used. Rafael mentioned that making it public would require some refactor because of the original implementation which was hard to understand and maintain. ### Changing how broadcasting works: Broadcasting in a nutshell worked by “transforming” an existing logger into a broadcasted one. The logger would then be responsible to log and format its own messages as well as passing the message along to other logger it broadcasts to. The problem with this approach was the following: - Heavy use of metaprogramming. - Accessing the loggers in the broadcast wasn’t possible. Removing a logger from the broadcast either. - More importantly, modifying the main logger (the one that broadcasts logs to the others) wasn’t possible and the main source of misunderstanding. ```ruby logger = Logger.new(STDOUT) stderr_logger = Logger.new(STDER)) logger.extend(AS::Logger.broadcast(stderr_logger)) logger.level = DEBUG # This modifies the level on all other loggers logger.formatter = … # Modified the formatter on all other loggers ``` -> New approach To keep the contract unchanged on what Rails.logger returns, the new implementation is still a subclass of Logger. The difference is that now the broadcast logger just delegate al methods to all the other loggers it’s broadcasting to. It’s simple and boring and it’s now just an array that gets iterated over. Now, users can access all loggers inside the broadcast and modify them on the fly. They can also remove any logger from the broadcast at any time. ```ruby # Before stdout_logger = Logger.new(STDOUT) stderr_logger = Logger.new(STDER) file_logger = Logger.new(“development.log”) stdout_logger.extend(AS::Logger.broadcast(stderr_logger)) stdout_logger.extend(AS::Logger.broadcast(file_logger)) # After broadcast = BroadcastLogger.new(stdout_logger, stderr_logger, file_logger) ``` I also think that now, it should be more clear for users that the broadcast sole job is to pass everything to the whole loggers in the broadcast. So there should be no surprise that all loggers in the broadcast get their level modified when they call `broadcast.level = DEBUG` . It’s also easier to wrap your head around more complex setup such as broadcasting logs to another broadcast: `broadcast.broadcast_to(stdout_logger, other_broadcast)` --- activesupport/lib/active_support.rb | 1 + .../lib/active_support/broadcast_logger.rb | 204 ++++++++++++++++++ activesupport/lib/active_support/logger.rb | 58 ----- activesupport/test/broadcast_logger_test.rb | 116 +++++++++- .../test/log_broadcast_and_tagging_test.rb | 75 +++++++ activesupport/test/logger_test.rb | 4 +- activesupport/test/tagged_logging_test.rb | 52 +++++ 7 files changed, 447 insertions(+), 63 deletions(-) create mode 100644 activesupport/lib/active_support/broadcast_logger.rb create mode 100644 activesupport/test/log_broadcast_and_tagging_test.rb diff --git a/activesupport/lib/active_support.rb b/activesupport/lib/active_support.rb index 203a234c2d01f..e17864fe81a3a 100644 --- a/activesupport/lib/active_support.rb +++ b/activesupport/lib/active_support.rb @@ -28,6 +28,7 @@ require "active_support/version" require "active_support/deprecator" require "active_support/logger" +require "active_support/broadcast_logger" require "active_support/lazy_load_hooks" require "active_support/core_ext/date_and_time/compatibility" diff --git a/activesupport/lib/active_support/broadcast_logger.rb b/activesupport/lib/active_support/broadcast_logger.rb new file mode 100644 index 0000000000000..2fb2f6bc98574 --- /dev/null +++ b/activesupport/lib/active_support/broadcast_logger.rb @@ -0,0 +1,204 @@ +# frozen_string_literal: true + +module ActiveSupport + # The Broadcast logger is a logger used to write messages to multiple IO. It is commonly used + # in development to display messages on STDOUT and also write them to a file (development.log). + # With the Broadcast logger, you can broadcast your logs to a unlimited number of sinks. + # + # The BroadcastLogger acts as a standard logger and all methods you are used to are available. + # However, all the methods on this logger will propagate and be delegated to the other loggers + # that are part of the broadcast. + # + # Broadcasting your logs. + # + # stdout_logger = Logger.new(STDOUT) + # file_logger = Logger.new("development.log") + # broadcast = BroadcastLogger.new(stdout_logger, file_logger) + # + # broadcast.info("Hello world!") # Writes the log to STDOUT and the development.log file. + # + # Add a logger to the broadcast. + # + # stdout_logger = Logger.new(STDOUT) + # broadcast = BroadcastLogger.new(stdout_logger) + # file_logger = Logger.new("development.log") + # broadcast.broadcast_to(file_logger) + # + # broadcast.info("Hello world!") # Writes the log to STDOUT and the development.log file. + # + # Modifying the log level for all broadcasted loggers. + # + # stdout_logger = Logger.new(STDOUT) + # file_logger = Logger.new("development.log") + # broadcast = BroadcastLogger.new(stdout_logger, file_logger) + # + # broadcast.level = Logger::FATAL # Modify the log level for the whole broadcast. + # + # Stop broadcasting log to a sink. + # + # stdout_logger = Logger.new(STDOUT) + # file_logger = Logger.new("development.log") + # broadcast = BroadcastLogger.new(stdout_logger, file_logger) + # broadcast.info("Hello world!") # Writes the log to STDOUT and the development.log file. + # + # broadcast.stop_broadcasting_to(file_logger) + # broadcast.info("Hello world!") # Writes the log *only* to STDOUT. + # + # At least one sink has to be part of the broadcast. Otherwise, your logs will not + # be written anywhere. For instance: + # + # broadcast = BroadcastLogger.new + # broadcast.info("Hello world") # The log message will appear nowhere. + class BroadcastLogger + include ActiveSupport::LoggerSilence + + # @return [Array] All the logger that are part of this broadcast. + attr_reader :broadcasts + + def initialize(*loggers) + @broadcasts = [] + + broadcast_to(*loggers) + end + + # Add logger(s) to the broadcast. + # + # @param loggers [Logger] Loggers that will be part of this broadcast. + # + # @example Broadcast yours logs to STDOUT and STDERR + # broadcast.broadcast_to(Logger.new(STDOUT), Logger.new(STDERR)) + def broadcast_to(*loggers) + @broadcasts.concat(loggers) + end + + # Remove a logger from the broadcast. When a logger is removed, messages sent to + # the broadcast will no longer be written to its sink. + # + # @param logger [Logger] + def stop_broadcasting_to(logger) + @broadcasts.delete(logger) + end + + # Implemented for duck typing. + def progname; end + + # Implemented for duck typing. + def level; end + + def <<(message) + dispatch { |logger| logger.<<(message) } + end + + def add(*args, &block) + dispatch { |logger| logger.add(*args, &block) } + end + alias_method :log, :add + + def debug(*args, &block) + dispatch { |logger| logger.debug(*args, &block) } + end + + def info(*args, &block) + dispatch { |logger| logger.info(*args, &block) } + end + + def warn(*args, &block) + dispatch { |logger| logger.warn(*args, &block) } + end + + def error(*args, &block) + dispatch { |logger| logger.error(*args, &block) } + end + + def fatal(*args, &block) + dispatch { |logger| logger.fatal(*args, &block) } + end + + def unknown(*args, &block) + dispatch { |logger| logger.unknown(*args, &block) } + end + + def formatter=(formatter) + dispatch { |logger| logger.formatter = formatter } + end + + def progname=(progname) + dispatch { |logger| logger.progname = progname } + 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 + end + + def close + dispatch { |logger| logger.close } + end + + # @return [Boolean] +True+ if the log level allows entries with severity Logger::DEBUG to be written + # to at least one broadcast. +False+ otherwise. + def debug? + @broadcasts.any? { |logger| logger.debug? } + end + + # Sets the log level to Logger::DEBUG for the whole brodcast. + def debug! + dispatch { |logger| logger.debug! } + end + + # @return [Boolean] +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 brodcast. + def info! + dispatch { |logger| logger.info! } + end + + # @return [Boolean] +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 brodcast. + def warn! + dispatch { |logger| logger.warn! } + end + + # @return [Boolean] +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 brodcast. + def error! + dispatch { |logger| logger.error! } + end + + # @return [Boolean] +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 brodcast. + def fatal! + dispatch { |logger| logger.fatal! } + end + + private + def dispatch(&block) + @broadcasts.each { |logger| block.call(logger) } + end + end +end diff --git a/activesupport/lib/active_support/logger.rb b/activesupport/lib/active_support/logger.rb index 1f62e61d86562..09a295f287090 100644 --- a/activesupport/lib/active_support/logger.rb +++ b/activesupport/lib/active_support/logger.rb @@ -19,64 +19,6 @@ def self.logger_outputs_to?(logger, *sources) sources.any? { |source| source == logger_source } end - # Broadcasts logs to multiple loggers. - def self.broadcast(logger) # :nodoc: - Module.new do - define_method(:add) do |*args, &block| - logger.add(*args, &block) - super(*args, &block) - end - - define_method(:<<) do |x| - logger << x - super(x) - end - - define_method(:close) do - logger.close - super() - end - - define_method(:progname=) do |name| - logger.progname = name - super(name) - end - - define_method(:formatter=) do |formatter| - logger.formatter = formatter - super(formatter) - end - - define_method(:level=) do |level| - logger.level = level - super(level) - end - - define_method(:local_level=) do |level| - logger.local_level = level if logger.respond_to?(:local_level=) - super(level) if respond_to?(:local_level=) - end - - define_method(:silence) do |level = Logger::ERROR, &block| - if logger.respond_to?(:silence) - logger.silence(level) do - if defined?(super) - super(level, &block) - else - block.call(self) - end - end - else - if defined?(super) - super(level, &block) - else - block.call(self) - end - end - end - end - end - def initialize(*args, **kwargs) super @formatter ||= SimpleFormatter.new diff --git a/activesupport/test/broadcast_logger_test.rb b/activesupport/test/broadcast_logger_test.rb index 2080af76a96fd..70144c9e048b4 100644 --- a/activesupport/test/broadcast_logger_test.rb +++ b/activesupport/test/broadcast_logger_test.rb @@ -9,8 +9,7 @@ class BroadcastLoggerTest < TestCase setup do @log1 = FakeLogger.new @log2 = FakeLogger.new - @log1.extend Logger.broadcast @log2 - @logger = @log1 + @logger = BroadcastLogger.new(@log1, @log2) end Logger::Severity.constants.each do |level_name| @@ -71,13 +70,31 @@ class BroadcastLoggerTest < TestCase assert_equal ::Logger::FATAL, log2.local_level end + test "severity methods get called on all loggers" do + my_logger = Class.new(::Logger) do + attr_reader :info_called + + def info(msg, &block) + @info_called = true + end + end.new(StringIO.new) + + @logger.broadcast_to(my_logger) + + assert_changes(-> { my_logger.info_called }, from: nil, to: true) do + @logger.info("message") + end + ensure + @logger.stop_broadcasting_to(my_logger) + end + test "#silence does not break custom loggers" do new_logger = FakeLogger.new custom_logger = CustomLogger.new assert_respond_to new_logger, :silence assert_not_respond_to custom_logger, :silence - custom_logger.extend(Logger.broadcast(new_logger)) + logger = BroadcastLogger.new(custom_logger, new_logger) custom_logger.silence do custom_logger.error "from error" @@ -117,6 +134,99 @@ class BroadcastLoggerTest < TestCase assert_equal [[::Logger::FATAL, "seen", nil]], log2.adds end + test "stop broadcasting to a logger" do + @logger.stop_broadcasting_to(@log2) + + @logger.info("Hello") + + assert_equal([[1, "Hello", nil]], @log1.adds) + assert_empty(@log2.adds) + end + + test "#broadcast on another broadcasted logger" do + @log3 = FakeLogger.new + @log4 = FakeLogger.new + @broadcast2 = ActiveSupport::BroadcastLogger.new(@log3, @log4) + + @logger.broadcast_to(@broadcast2) + @logger.info("Hello") + + assert_equal([[1, "Hello", nil]], @log1.adds) + assert_equal([[1, "Hello", nil]], @log2.adds) + assert_equal([[1, "Hello", nil]], @log3.adds) + assert_equal([[1, "Hello", nil]], @log4.adds) + end + + test "#debug? is true when at least one logger's level is at or above DEBUG level" do + @log1.level = Logger::DEBUG + @log2.level = Logger::FATAL + + assert_predicate(@logger, :debug?) + end + + test "#debug? is false when all loggers are below DEBUG level" do + @log1.level = Logger::ERROR + @log2.level = Logger::FATAL + + assert_not_predicate(@logger, :debug?) + end + + test "#info? is true when at least one logger's level is at or above INFO level" do + @log1.level = Logger::DEBUG + @log2.level = Logger::FATAL + + assert_predicate(@logger, :info?) + end + + test "#info? is false when all loggers are below INFO" do + @log1.level = Logger::ERROR + @log2.level = Logger::FATAL + + assert_not_predicate(@logger, :info?) + end + + test "#warn? is true when at least one logger's level is at or above WARN level" do + @log1.level = Logger::DEBUG + @log2.level = Logger::FATAL + + assert_predicate(@logger, :warn?) + end + + test "#warn? is false when all loggers are below WARN" do + @log1.level = Logger::ERROR + @log2.level = Logger::FATAL + + assert_not_predicate(@logger, :warn?) + end + + test "#error? is true when at least one logger's level is at or above ERROR level" do + @log1.level = Logger::DEBUG + @log2.level = Logger::FATAL + + assert_predicate(@logger, :error?) + end + + test "#error? is false when all loggers are below ERROR" do + @log1.level = Logger::FATAL + @log2.level = Logger::FATAL + + assert_not_predicate(@logger, :error?) + end + + test "#fatal? is true when at least one logger's level is at or above FATAL level" do + @log1.level = Logger::DEBUG + @log2.level = Logger::FATAL + + assert_predicate(@logger, :fatal?) + end + + test "#fatal? is false when all loggers are below FATAL" do + @log1.level = Logger::UNKNOWN + @log2.level = Logger::UNKNOWN + + assert_not_predicate(@logger, :fatal?) + end + class CustomLogger attr_reader :adds, :closed, :chevrons attr_accessor :level, :progname, :formatter, :local_level diff --git a/activesupport/test/log_broadcast_and_tagging_test.rb b/activesupport/test/log_broadcast_and_tagging_test.rb new file mode 100644 index 0000000000000..c7b05cd5165dd --- /dev/null +++ b/activesupport/test/log_broadcast_and_tagging_test.rb @@ -0,0 +1,75 @@ +# frozen_string_literal: true + +require_relative "abstract_unit" + +class LogBroadcastAndTaggingTest < ActiveSupport::TestCase + setup do + @sink1 = StringIO.new + @sink2 = StringIO.new + @logger1 = Logger.new(@sink1, formatter: ActiveSupport::Logger::SimpleFormatter.new) + @logger2 = Logger.new(@sink2, formatter: ActiveSupport::Logger::SimpleFormatter.new) + + @broadcast = ActiveSupport::BroadcastLogger.new(@logger1, @logger2) + end + + test "tag logs for the whole broadcast with a block" do + @broadcast.extend(ActiveSupport::TaggedLogging) + + @broadcast.tagged("BMX") { @broadcast.info("Hello") } + + assert_equal("[BMX] Hello\n", @sink1.string) + assert_equal("[BMX] Hello\n", @sink2.string) + end + + test "tag logs for the whole broadcast without a block" do + @broadcast.extend(ActiveSupport::TaggedLogging) + + @broadcast.tagged("BMX").info("Hello") + + assert_equal("[BMX] Hello\n", @sink1.string) + assert_equal("[BMX] Hello\n", @sink2.string) + end + + test "tag logs only for one sink" do + @logger1.extend(ActiveSupport::TaggedLogging) + @logger1.push_tags("BMX") + + @broadcast.info { "Hello" } + + assert_equal("[BMX] Hello\n", @sink1.string) + assert_equal("Hello\n", @sink2.string) + end + + test "tag logs for the whole broadcast and extra tags are added to one sink" do + @broadcast.extend(ActiveSupport::TaggedLogging) + @logger1.extend(ActiveSupport::TaggedLogging) + @logger1.push_tags("APP") + + @broadcast.tagged("BMX") { @broadcast.info("Hello") } + + assert_equal("[BMX] [APP] Hello\n", @sink1.string) + assert_equal("[BMX] Hello\n", @sink2.string) + end + + test "can broadcast to another broadcast logger with tagging functionalities" do + @sink3 = StringIO.new + @sink4 = StringIO.new + @logger3 = Logger.new(@sink3, formatter: ActiveSupport::Logger::SimpleFormatter.new) + @logger4 = Logger.new(@sink4, formatter: ActiveSupport::Logger::SimpleFormatter.new) + @broadcast2 = ActiveSupport::BroadcastLogger.new(@logger3, @logger4) + + @broadcast.broadcast_to(@broadcast2) + + @broadcast.extend(ActiveSupport::TaggedLogging) + @broadcast2.extend(ActiveSupport::TaggedLogging) + + @broadcast2.push_tags("BROADCAST2") + + @broadcast.tagged("BMX") { @broadcast.info("Hello") } + + assert_equal("[BMX] Hello\n", @sink1.string) + assert_equal("[BMX] Hello\n", @sink2.string) + assert_equal("[BMX] [BROADCAST2] Hello\n", @sink3.string) + assert_equal("[BMX] [BROADCAST2] Hello\n", @sink4.string) + end +end diff --git a/activesupport/test/logger_test.rb b/activesupport/test/logger_test.rb index c0f831ddee8fd..66891016f8c32 100644 --- a/activesupport/test/logger_test.rb +++ b/activesupport/test/logger_test.rb @@ -176,7 +176,7 @@ def test_logger_silencing_works_for_broadcast another_output = StringIO.new another_logger = ActiveSupport::Logger.new(another_output) - @logger.extend ActiveSupport::Logger.broadcast(another_logger) + logger = ActiveSupport::BroadcastLogger.new(@logger, another_logger) @logger.debug "CORRECT DEBUG" @logger.silence do |logger| @@ -198,7 +198,7 @@ def test_broadcast_silencing_does_not_break_plain_ruby_logger another_output = StringIO.new another_logger = ::Logger.new(another_output) - @logger.extend ActiveSupport::Logger.broadcast(another_logger) + logger = ActiveSupport::BroadcastLogger.new(@logger, another_logger) @logger.debug "CORRECT DEBUG" @logger.silence do |logger| diff --git a/activesupport/test/tagged_logging_test.rb b/activesupport/test/tagged_logging_test.rb index 64d84fdb2c2da..10c4f50e31098 100644 --- a/activesupport/test/tagged_logging_test.rb +++ b/activesupport/test/tagged_logging_test.rb @@ -232,6 +232,33 @@ class TaggedLoggingWithoutBlockTest < ActiveSupport::TestCase assert_equal "[OMG] Broadcasting...\n", broadcast_output.string end + test "#tagged without a block doesn't leak to other loggers" do + sink1 = StringIO.new + logger1 = ActiveSupport::Logger.new(sink1).extend(ActiveSupport::TaggedLogging) + sink2 = StringIO.new + logger2 = ActiveSupport::Logger.new(sink2).extend(ActiveSupport::TaggedLogging) + broadcast_logger = ActiveSupport::BroadcastLogger.new.extend(ActiveSupport::TaggedLogging) + broadcast_logger.broadcast_to(logger1, logger2) + + broadcast_logger.tagged("tag") + broadcast_logger.info("text") + + assert_equal("text\n", sink1.string) + assert_equal("text\n", sink2.string) + end + + test "keeps broadcasting functionality when passed a block" do + output = StringIO.new + logger = Logger.new(output) + broadcast_logger = ActiveSupport::BroadcastLogger.new.extend(ActiveSupport::TaggedLogging) + broadcast_logger.broadcast_to(@logger, logger) + + broadcast_logger.tagged("OMG") { |logger| logger.info "Broadcasting..." } + + assert_equal "[OMG] Broadcasting...\n", @output.string + assert_equal "[OMG] Broadcasting...\n", output.string + end + test "keeps formatter singleton class methods" do plain_output = StringIO.new plain_logger = Logger.new(plain_output) @@ -250,4 +277,29 @@ def crozz_method @logger.tagged("tag") { @logger.info [1, 2, 3] } assert_equal "[tag] [1, 2, 3]\n", @output.string end + + # test "setting a default formatter is deprecated" do + # output = StringIO.new + # logger = Logger.new(output).extend(ActiveSupport::TaggedLogging) + + # assert_deprecated(/will no longer set a default formatter on your logger/) do + # logger.info("hello") + # end + # end + + # test "#new is deprecated to create a new logger" do + # logger = Logger.new(STDOUT) + + # assert_deprecated(/To create a new Logger instance with tagging functionalities, extend/) do + # ActiveSupport::TaggedLogging.new(logger) + # end + # end + + # test "#new is deprecated when cloning a logger" do + # tagged_logger = Logger.new(STDOUT).extend(ActiveSupport::TaggedLogging) + + # assert_deprecated(/To create a new logger from an existing logger, use/) do + # ActiveSupport::TaggedLogging.new(tagged_logger) + # end + # end end