Reimplement TaggedLogging:

- ### Context

  The Tagged Logging functionality has been a source of a few
  issues over the years, especially when combined with the
  broadcasting feature.
  Initializating a Tagged Logger wasn't very intuitive:

  ```ruby
    logger = Logger.new(STDOUT)
    tagged_logger = ActiveSupport::TaggedLogging.new(logger)
    # Would expect the `tagged_logger` to be an instance of `AS::TaggedLogging`
    # but it's a clone of the `logger`.

    tagged_logger.formatter = ->(_, _, _, message) do
      { message: message }
    end
    # Modifies the formatter to output JSON formatted logs.
    # This breaks tagged logging.
  ```

  I believe the main reason of those issues is because tagged logging
  is implemented at the wrong level.

  ### Solution

  I made a proposal on the Ruby logger upstream in ruby/logger#90 to help
  solve this but it hasn't been reviewed yet. So I thought about adding
  it here for now.
  The TL;DR is to decouple formatting and adding extra information to
  logs (which is what tagged logging does).

  ### Deprecation

  Since TaggedLogging will no longer access the formatter, there is a
  few things I'd like to deprecate (such as setting a default
  formatter https://github.com/rails/rails/blob/d68e43922bc11829c52ad9f736ad5549fc97631b/activesupport/lib/active_support/tagged_logging.rb#L124)
  but doing so in this PR would increase the size of the diff
  significantly and would maybe distract for PR reviews.

  Another thing that I believe should be deprecated is
  `ActiveSupport::TaggedLogging.new`. Adding tagging
  functionality to a logger should be done using
  a more ruby approach such as `logger.extend(AS::TaggedLogging)`.

  Fix rails#49757
  Fix rails#49745
  Fix rails#46084
  Fix rails#44668

I made a propose on the Ruby logger upstream in ruby/logger#90,
  but it hasn't been reviewed it.

Author: Edouard-chin

actioncable/lib/action_cable/connection/tagged_logger_proxy.rb

@@ -22,7 +22,7 @@ def add_tags(*tags)
 
       def tag(logger, &block)
         if logger.respond_to?(:tagged)
-          current_tags = tags - logger.formatter.current_tags
+          current_tags = tags - logger.tag_processor.current_tags
           logger.tagged(*current_tags, &block)
         else
           yield

activejob/lib/active_job/logging.rb

@@ -29,7 +29,7 @@ def tag_logger(*tags, &block)
       end
 
       def logger_tagged_by_active_job?
-        logger.formatter.current_tags.include?("ActiveJob")
+        logger.tag_processor.current_tags.include?("ActiveJob")
       end
   end
 end

activesupport/lib/active_support/broadcast_logger.rb

@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+require "active_support/tagged_logging"
+
 module ActiveSupport
   # = Active Support Broadcast Logger
   #
@@ -71,6 +73,40 @@ module ActiveSupport
   #   logger.broadcast_to(MyLogger.new(STDOUT))
   #   puts logger.broadcasts # => [MyLogger, MyLogger]
   #   logger.loggable? # [true, true]
+  #
+  # ====== 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(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(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(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
     include ActiveSupport::LoggerSilence
 
@@ -80,6 +116,8 @@ class BroadcastLogger
     attr_accessor :progname
 
     def initialize(*loggers)
+      extend ActiveSupport::TaggedLogging
+
       @broadcasts = []
       @progname = "Broadcast"
 
@@ -114,32 +152,32 @@ def <<(message)
     end
 
     def add(*args, &block)
-      dispatch { |logger| logger.add(*args, &block) }
+      dispatch_with_processors { |logger| logger.add(*args, &block) }
     end
     alias_method :log, :add
 
     def debug(*args, &block)
-      dispatch { |logger| logger.debug(*args, &block) }
+      dispatch_with_processors { |logger| logger.debug(*args, &block) }
     end
 
     def info(*args, &block)
-      dispatch { |logger| logger.info(*args, &block) }
+      dispatch_with_processors { |logger| logger.info(*args, &block) }
     end
 
     def warn(*args, &block)
-      dispatch { |logger| logger.warn(*args, &block) }
+      dispatch_with_processors { |logger| logger.warn(*args, &block) }
     end
 
     def error(*args, &block)
-      dispatch { |logger| logger.error(*args, &block) }
+      dispatch_with_processors { |logger| logger.error(*args, &block) }
     end
 
     def fatal(*args, &block)
-      dispatch { |logger| logger.fatal(*args, &block) }
+      dispatch_with_processors { |logger| logger.fatal(*args, &block) }
     end
 
     def unknown(*args, &block)
-      dispatch { |logger| logger.unknown(*args, &block) }
+      dispatch_with_processors { |logger| logger.unknown(*args, &block) }
     end
 
     def formatter=(formatter)
@@ -218,7 +256,7 @@ def fatal!
       dispatch { |logger| logger.fatal! }
     end
 
-    def initialize_copy(other)
+    def initialize_dup(other)
       @broadcasts = []
       @progname = other.progname.dup
       @formatter = other.formatter.dup
@@ -231,6 +269,17 @@ 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
+
       def method_missing(name, *args, **kwargs, &block)
         loggers = @broadcasts.select { |logger| logger.respond_to?(name) }
 

activesupport/lib/active_support/log_processor.rb

@@ -0,0 +1,26 @@
+# frozen_string_literal: true
+
+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
+end

activesupport/lib/active_support/logger.rb

@@ -2,11 +2,13 @@
 
 require "active_support/logger_silence"
 require "active_support/logger_thread_safe_level"
+require "active_support/log_processor"
 require "logger"
 
 module ActiveSupport
   class Logger < ::Logger
     include LoggerSilence
+    include LogProcessor
 
     # Returns true if the logger destination matches one of the sources
     #

activesupport/lib/active_support/tagged_logging.rb

@@ -28,10 +28,13 @@ module ActiveSupport
   # it easy to stamp log lines with subdomains, request ids, and anything else
   # to aid debugging of multi-user production applications.
   module TaggedLogging
-    module Formatter # :nodoc:
-      # This method is invoked when a log event occurs.
-      def call(severity, timestamp, progname, msg)
-        super(severity, timestamp, progname, tag_stack.format_message(msg))
+    class TagProcessor # :nodoc:
+      def call(msg, logger)
+        if logger.formatter.nil?
+          logger.formatter ||= Logger::SimpleFormatter.new
+        end
+
+        tag_stack.format_message(msg)
       end
 
       def tagged(*tags)
@@ -114,29 +117,39 @@ def self.extended(base)
       end
     end
 
-    def self.new(logger)
-      logger = logger.clone
-
-      if logger.formatter
-        logger.formatter = logger.formatter.clone
+    def self.new(logger) # :nodoc:
+      if logger.is_a?(TaggedLogging)
+        logger.clone
       else
-        # Ensure we set a default formatter so we aren't extending nil!
-        logger.formatter = ActiveSupport::Logger::SimpleFormatter.new
+        logger.extend(TaggedLogging)
       end
+    end
+
+    def self.extended(base)
+      base.tag_processor = TagProcessor.new
+      base.extend(ActiveSupport::LogProcessor)
 
-      logger.formatter.extend Formatter
-      logger.extend(self)
+      base.processors << base.tag_processor
     end
 
-    delegate :push_tags, :pop_tags, :clear_tags!, to: :formatter
+    def initialize_clone(_)
+      self.tag_processor = TagProcessor.new
+      self.processors = [tag_processor]
+
+      super
+    end
+
+    delegate :push_tags, :pop_tags, :clear_tags!, to: :tag_processor
+    attr_accessor :tag_processor
 
     def tagged(*tags)
       if block_given?
-        formatter.tagged(*tags) { yield self }
+        tag_processor.tagged(*tags) { yield(self) }
       else
-        logger = ActiveSupport::TaggedLogging.new(self)
-        logger.formatter.extend LocalTagStorage
-        logger.push_tags(*formatter.current_tags, *tags)
+        logger = clone
+        logger.tag_processor.extend(LocalTagStorage)
+        logger.tag_processor.push_tags(*tag_processor.current_tags, *tags)
+
         logger
       end
     end

activesupport/test/log_broadcast_and_tagging_test.rb

@@ -0,0 +1,137 @@
+# 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
+    @broadcast.broadcast_to(@logger1, @logger2)
+  end
+
+  test "tag logs for the whole broadcast with a block" do
+    @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.tagged("BMX").info("Hello")
+
+    assert_equal("[BMX] Hello\n", @sink1.string)
+    assert_equal("[BMX] Hello\n", @sink2.string)
+
+    @sink1.reopen
+    @sink2.reopen
+    @broadcast.info("Hello")
+
+    assert_equal("Hello\n", @sink1.string)
+    assert_equal("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 multiple sinks" do
+    @logger1.extend(ActiveSupport::TaggedLogging)
+    @logger1.push_tags("BMX")
+
+    @logger2.extend(ActiveSupport::TaggedLogging)
+    @logger2.push_tags("APP")
+
+    @broadcast.info { "Hello" }
+
+    assert_equal("[BMX] Hello\n", @sink1.string)
+    assert_equal("[APP] Hello\n", @sink2.string)
+  end
+
+  test "tag logs for the whole broadcast and extra tags are added to one sink (block version)" do
+    @logger1.extend(ActiveSupport::TaggedLogging)
+    @logger1.push_tags("APP1")
+
+    @logger2.extend(ActiveSupport::TaggedLogging)
+    @logger2.push_tags("APP2")
+
+    @broadcast.tagged("BMX") { @broadcast.info("Hello") }
+
+    assert_equal("[BMX] [APP1] Hello\n", @sink1.string)
+    assert_equal("[BMX] [APP2] Hello\n", @sink2.string)
+  end
+
+  test "tag logs for the whole broadcast and extra tags are added to one sink (non-block version)" do
+    @logger1.extend(ActiveSupport::TaggedLogging)
+    @logger1.push_tags("APP1")
+
+    @logger2.extend(ActiveSupport::TaggedLogging)
+    @logger2.push_tags("APP2")
+
+    @broadcast.tagged("BMX").info("Hello")
+
+    assert_equal("[BMX] [APP1] Hello\n", @sink1.string)
+    assert_equal("[BMX] [APP2] Hello\n", @sink2.string)
+
+    @sink1.reopen
+    @sink2.reopen
+    @broadcast.info("Hello")
+
+    assert_equal("[APP1] Hello\n", @sink1.string)
+    assert_equal("[APP2] 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
+
+    @broadcast2.broadcast_to(@logger3, @logger4)
+    @broadcast.broadcast_to(@broadcast2)
+
+    @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
+
+  test "#silence works while broadcasting to tagged loggers" do
+    my_logger = Class.new(::Logger) do
+      include ActiveSupport::LoggerSilence
+    end
+
+    logger1_io = StringIO.new
+    logger2_io = StringIO.new
+
+    logger1 = my_logger.new(logger1_io).extend(ActiveSupport::TaggedLogging)
+    logger2 = my_logger.new(logger2_io).extend(ActiveSupport::TaggedLogging)
+
+    broadcast = ActiveSupport::BroadcastLogger.new(logger1, logger2)
+
+    broadcast.tagged("TEST") do
+      broadcast.silence do
+        broadcast.info("Silenced")
+      end
+
+      broadcast.info("Not silenced")
+    end
+
+    assert_equal("[TEST] Not silenced\n", logger1_io.string)
+    assert_equal("[TEST] Not silenced\n", logger2_io.string)
+  end
+end