Skip to content

Commit

Permalink
Refactor tagged logging and add a public API for broadcasting logs:
Browse files Browse the repository at this point in the history
- Opening this PR to get some first impression and feedback and see if
  that’s the path we want to take.

  ## Context

  While working on rails#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.

  TaggedLogging is another piece of this PR, while it’s not related
  to broadcasting, both features combined were a source of issues and
  confusion (see rails#38850, rails#27792, rails#45854 and some more).
  Broadcasting and tagged logging were a bit entangled and I felt it
  would be easier to have the bigger picture in a single PR.

  TaggedLogging is public and the new implementation doesn’t introduce
  any breaking change.

  Broadcasting is in a grey zone, it’s not referenced in our docs but
  I saw it often in apps and libraries. This refactor would break them.
  Happy to revisit that and find a way to make it compatible.

  ## Implementation

  The changes would make a lot of diff chunks, so to make it easier to
  review I opted to not modify the original files and free the constant
  name (Logger, TaggedLogging) for the new implementation that are
  inside new files.
  All code in this PR is new and uses code from the previous
  implementation that don’t appear in the diff. The goal would be to
  copy/paste the required code at the end of the review process.

  ---------------

  ### 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
  broadcast.broadcast_to(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)`

  ### Changing TaggedLogging

  Tagged logging is painful to implement because there is basically no
  good way to hook into the vanilla logger code. The easiest is to
  hook on the formatter but IMHO this is implemented at the wrong
  level.

  Adding tags on the formatter means:

  - Monkeypatching the formatter on the logger. With the broadcasting
    feature, that meant modifying all formatters on all loggers.
  - From its name, I would assume that a formatter job is just to
    format. Not add modify the logs and add extra information.

    What I felt was missing was an object responsible to process the
    logs just before it gets formatted. So I implemented a
    “LogProcessor” which seats just after the user pass a log,
    but before it gets formatted.
    I thought it is a good addition that would allow to have
    multiple processors in the case users or libraries need to pass
    their logs into multiple processors.
  • Loading branch information
Edouard-chin committed Jul 3, 2023
1 parent e34a777 commit f86529e
Show file tree
Hide file tree
Showing 7 changed files with 573 additions and 1 deletion.
4 changes: 3 additions & 1 deletion activesupport/lib/active_support.rb
Expand Up @@ -28,6 +28,8 @@
require "active_support/version"
require "active_support/deprecator"
require "active_support/logger"
require "active_support/new_logger"
require "active_support/broadcast_logger"
require "active_support/lazy_load_hooks"
require "active_support/core_ext/date_and_time/compatibility"

Expand Down Expand Up @@ -79,7 +81,7 @@ module ActiveSupport
autoload :OrderedOptions
autoload :StringInquirer
autoload :EnvironmentInquirer
autoload :TaggedLogging
autoload :TaggedLogging, "active_support/new_tagged_logging"
autoload :XmlMini
autoload :ArrayInquirer
end
Expand Down
195 changes: 195 additions & 0 deletions activesupport/lib/active_support/broadcast_logger.rb
@@ -0,0 +1,195 @@
# 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
# broadcast.broadcast_to(stdout_logger, file_logger)
#
# broadcast.info("Hello world!") # Writes the log to STDOUT and the development.log file.
#
# Modifying the log level to all broadcasted loggers.
#
# stdout_logger = Logger.new(STDOUT)
# file_logger = Logger.new("development.log")
# broadcast = BroadcastLogger.new
# broadcast.broadcast_to(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
# broadcast.broadcast_to(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.
#
# ====== A note on tagging logs while using the Broadcast logger
#
# It is quite frequent to tag logs using the `ActiveSupport::TaggedLogging` module
# while also broadcasting them (the default Rails.logger in development is
# configured in such a way).
# Tagging your logs can be done for the whole broadcast or for each sink independently.
#
# Tagging logs for the whole broadcast
#
# broadcast = BroadcastLogger.new.extend(ActiveSupport::TaggedLogging)
# broadcast.broadcast_to(stdout_logger, file_logger)
# broadcast.tagged("BMX") { broadcast.info("Hello world!") }
#
# Outputs: "[BMX] Hello world!" is written on both STDOUT and in the file.
#
# Tagging logs for a single logger
#
# stdout_logger.extend(ActiveSupport::TaggedLogging)
# stdout_logger.push_tags("BMX")
# broadcast = BroadcastLogger.new
# broadcast.broadcast_to(stdout_logger, file_logger)
# broadcast.info("Hello world!")
#
# Outputs: "[BMX] Hello world!" is written on STDOUT
# Outputs: "Hello world!" is written in the file
#
# Adding tags for the whole broadcast and adding extra tags on a specific logger
#
# stdout_logger.extend(ActiveSupport::TaggedLogging)
# stdout_logger.push_tags("BMX")
# broadcast = BroadcastLogger.new.extend(ActiveSupport::TaggedLogging)
# broadcast.broadcast_to(stdout_logger, file_logger)
# broadcast.tagged("APP") { broadcast.info("Hello world!") }
#
# Outputs: "[APP][BMX] Hello world!" is written on STDOUT
# Outputs: "[APP] Hello world!" is written in the file
class BroadcastLogger < Logger
# @return [Array<Logger>] All the logger that are part of this broadcast.
attr_reader :broadcasts

def initialize(logdev = File::NULL, *args, **kwargs)
@broadcasts = []

super(logdev, *args, **kwargs)
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

def <<(message)
dispatch { |logger| logger.<<(message) }
end

def add(*args, &block)
dispatch_with_processors do |logger|
logger.add(*args, &block)
end
end

def debug(*args, &block)
dispatch_with_processors do |logger|
logger.debug(*args, &block)
end
end

def info(*args, &block)
dispatch_with_processors do |logger|
logger.info(*args, &block)
end
end

def warn(*args, &block)
dispatch_with_processors do |logger|
logger.warn(*args, &block)
end
end

def error(*args, &block)
dispatch_with_processors do |logger|
logger.error(*args, &block)
end
end

def fatal(*args, &block)
dispatch_with_processors do |logger|
logger.fatal(*args, &block)
end
end

def unknown(*args, &block)
dispatch_with_processors do |logger|
logger.unknown(*args, &block)
end
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

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

private
def dispatch(&block)
@broadcasts.each { |logger| block.call(logger) }
end

def dispatch_with_processors(&block)
@broadcasts.each do |logger|
logger.extend(LogProcessor) unless logger.is_a?(LogProcessor)
logger.processors.unshift(processors)

block.call(logger)
ensure
logger.processors.shift(processors.count)
end
end
end
end
67 changes: 67 additions & 0 deletions activesupport/lib/active_support/new_logger.rb
@@ -0,0 +1,67 @@
# frozen_string_literal: true

require "logger"
require "active_support/logger_silence"

module ActiveSupport
module LogProcessor # :nodoc: ?
attr_accessor :processors

def self.extended(base)
base.processors = []
end

def initialize(*args, **kwargs)
super

self.processors = []
end

private
def format_message(severity, datetime, progname, msg)
processors.flatten.reverse_each do |processor|
msg = processor.call(msg, self)
end

super(severity, datetime, progname, msg)
end
end

# The ActiveSupport logger is a logger with couple enhanced functionalities.
#
# === Default formatter
#
# The formatter by default will just output the log message with no timestamp or PID.
#
# Using a vanilla Ruby Logger
# logger.info("hello") Outputs: "I, [2023-06-30T02:36:57.164173 #85447] INFO -- : hello"
#
# Using the ActiveSupport::Logger
# logger.info("hello") Outputs: "hello"
#
# === Silence
#
# The ActiveSupport Logger allows to silence logs up to a given severity. This is useful
# to silence DEBUG or INFO logs temporarily but keep more important logs at the ERROR or FATAL level.
#
# Silencing logs up to the ERROR severity
#
# logger.silence(Logger::ERROR) { logger.info("Hello") } Doesn't output anything
# logger.silence(Logger::ERROR) { logger.error("Hello") } Outputs: "Hello"
class Logger < ::Logger
SimpleFormatter = OldLogger::SimpleFormatter

include LoggerSilence
include LogProcessor

def self.logger_outputs_to?(logger, *sources)
OldLogger.logger_outputs_to?(logger, *sources)
end

def initialize(*args, **kwargs)
super

@formatter ||= Logger::SimpleFormatter.new
end
end
end

0 comments on commit f86529e

Please sign in to comment.