Add a public API for broadcasting logs:

- ## 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
    ```

  To keep the contract unchanged on what Rails.logger returns, the new
  BroadcastLogger class implement duck typing with all methods
  that has the vanilla Ruby Logger class.

  It's a simple and boring PORO that keeps an array of all the loggers
  that are part of the broadcast and iterate over whenever a log is
  sent.
  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)`
This commit is contained in:
Edouard CHIN 2023-06-30 02:09:47 +02:00 committed by Rafael Mendonça França
parent d99e355390
commit 1fbd812c47
No known key found for this signature in database
GPG Key ID: FC23B6D0F1EEE948
9 changed files with 400 additions and 89 deletions

View File

@ -67,7 +67,7 @@ module ActiveRecord
unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, STDERR, STDOUT)
console = ActiveSupport::Logger.new(STDERR)
console.level = Rails.logger.level
Rails.logger.extend ActiveSupport::Logger.broadcast console
Rails.logger = ActiveSupport::BroadcastLogger.new(Rails.logger, console)
end
ActiveRecord.verbose_query_logs = false
end

View File

@ -1,3 +1,38 @@
* Add a new public API for broadcasting logs
This feature existed for a while but was until now a private API.
Broadcasting log allows to send log message to difference sinks (STDOUT, a file ...) and
is used by default in the development environment to write logs both on STDOUT and in the
"development.log" file.
Basic usage:
```ruby
stdout_logger = Logger.new(STDOUT)
file_logger = Logger.new("development.log")
broadcast = ActiveSupport::BroadcastLogger.new(stdout_logger, file_logger)
broadcast.info("Hello!") # The "Hello!" message is written on STDOUT and in the log file.
```
Adding other sink(s) to the broadcast:
```ruby
broadcast = ActiveSupport::BroadcastLogger.new
broadcast.broadcast_to(Logger.new(STDERR))
```
Remove a sink from the broadcast:
```ruby
stdout_logger = Logger.new(STDOUT)
broadcast = ActiveSupport::BroadcastLogger.new(stdout_logger)
broadcast.stop_broadcasting_to(stdout_logger)
```
*Edouard Chin*
* Fix Range#overlap? not taking empty ranges into account on Ruby < 3.3
*Nobuyoshi Nakada*, *Shouichi Kamiya*, *Hartley McGuire*

View File

@ -28,6 +28,7 @@ require "active_support/dependencies/autoload"
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"

View File

@ -0,0 +1,206 @@
# frozen_string_literal: true
module ActiveSupport
# = Active Support Broadcast Logger
#
# 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
# Returns all the logger that are part of this broadcast.
attr_reader :broadcasts
attr_reader :formatter
attr_accessor :progname
def initialize(*loggers)
@broadcasts = []
@progname = "Broadcast"
broadcast_to(*loggers)
end
# Add logger(s) to the broadcast.
#
# broadcast_logger = ActiveSupport::BroadcastLogger.new
# broadcast_logger.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.
#
# sink = Logger.new(STDOUT)
# broadcast_logger = ActiveSupport::BroadcastLogger.new
#
# broadcast_logger.stop_broadcasting_to(sink)
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(*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 }
@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
end
def close
dispatch { |logger| logger.close }
end
# +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 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
private
def dispatch(&block)
@broadcasts.each { |logger| block.call(logger) }
end
end
end

View File

@ -19,64 +19,6 @@ module ActiveSupport
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

View File

@ -9,8 +9,7 @@ module ActiveSupport
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|
@ -40,23 +39,40 @@ module ActiveSupport
end
test "#level= assigns the level to all loggers" do
assert_equal ::Logger::DEBUG, logger.level
assert_equal ::Logger::DEBUG, log1.level
logger.level = ::Logger::FATAL
assert_equal ::Logger::FATAL, log1.level
assert_equal ::Logger::FATAL, log2.level
end
test "#progname= assigns to all the loggers" do
assert_nil logger.progname
logger.progname = ::Logger::FATAL
test "#level returns the level of the logger with the lowest level" do
log1.level = Logger::DEBUG
assert_equal ::Logger::FATAL, log1.progname
assert_equal ::Logger::FATAL, log2.progname
assert_equal(Logger::DEBUG, logger.level)
log1.level = Logger::FATAL
log2.level = Logger::INFO
assert_equal(Logger::INFO, logger.level)
end
test "#progname returns Broadcast literally when the user didn't change the progname" do
assert_equal("Broadcast", logger.progname)
end
test "#progname= sets the progname on the Broadcast logger but doesn't modify the inner loggers" do
assert_nil(log1.progname)
assert_nil(log2.progname)
logger.progname = "Foo"
assert_equal("Foo", logger.progname)
assert_nil(log1.progname)
assert_nil(log2.progname)
end
test "#formatter= assigns to all the loggers" do
assert_nil logger.formatter
logger.formatter = ::Logger::FATAL
assert_equal ::Logger::FATAL, log1.formatter
@ -64,24 +80,42 @@ module ActiveSupport
end
test "#local_level= assigns the local_level to all loggers" do
assert_equal ::Logger::DEBUG, logger.local_level
assert_equal ::Logger::DEBUG, log1.local_level
logger.local_level = ::Logger::FATAL
assert_equal ::Logger::FATAL, log1.local_level
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"
custom_logger.unknown "from unknown"
logger.silence do
logger.error "from error"
logger.unknown "from unknown"
end
assert_equal [[::Logger::ERROR, "from error", nil], [::Logger::UNKNOWN, "from unknown", nil]], custom_logger.adds
@ -117,6 +151,99 @@ module ActiveSupport
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

View File

@ -176,13 +176,13 @@ class LoggerTest < ActiveSupport::TestCase
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|
assert_kind_of ActiveSupport::Logger, logger
@logger.debug "FAILURE"
@logger.error "CORRECT ERROR"
logger.debug "CORRECT DEBUG"
logger.silence do |logger|
assert_kind_of ActiveSupport::BroadcastLogger, logger
logger.debug "FAILURE"
logger.error "CORRECT ERROR"
end
assert_includes @output.string, "CORRECT DEBUG"
@ -198,13 +198,13 @@ class LoggerTest < ActiveSupport::TestCase
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|
assert_kind_of ActiveSupport::Logger, logger
@logger.debug "FAILURE"
@logger.error "CORRECT ERROR"
logger.debug "CORRECT DEBUG"
logger.silence do |logger|
assert_kind_of ActiveSupport::BroadcastLogger, logger
logger.debug "FAILURE"
logger.error "CORRECT ERROR"
end
assert_includes @output.string, "CORRECT DEBUG"

View File

@ -222,10 +222,10 @@ class TaggedLoggingWithoutBlockTest < ActiveSupport::TestCase
test "keeps broadcasting functionality" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::TaggedLogging.new(Logger.new(broadcast_output))
@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
broadcast_logger = ActiveSupport::BroadcastLogger.new(Logger.new(broadcast_output), @logger)
logger_with_tags = ActiveSupport::TaggedLogging.new(broadcast_logger)
tagged_logger = @logger.tagged("OMG")
tagged_logger = logger_with_tags.tagged("OMG")
tagged_logger.info "Broadcasting..."
assert_equal "[OMG] Broadcasting...\n", @output.string

View File

@ -80,7 +80,7 @@ module Rails
console.level = Rails.logger.level
unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, STDERR, STDOUT)
Rails.logger.extend(ActiveSupport::Logger.broadcast(console))
Rails.logger = ActiveSupport::BroadcastLogger.new(Rails.logger, console)
end
end