From 0f6da082dffaea1243693a005bf18fe3d31064f7 Mon Sep 17 00:00:00 2001 From: Edouard CHIN Date: Tue, 24 Oct 2023 17:34:04 +0200 Subject: [PATCH] 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 #49757 Fix #49745 Fix #46084 Fix #44668 I made a propose on the Ruby logger upstream in ruby/logger#90, but it hasn't been reviewed it. --- .../connection/tagged_logger_proxy.rb | 2 +- activejob/lib/active_job/logging.rb | 2 +- .../lib/active_support/broadcast_logger.rb | 65 ++++++++- .../lib/active_support/log_processor.rb | 26 ++++ activesupport/lib/active_support/logger.rb | 2 + .../lib/active_support/tagged_logging.rb | 49 ++++--- .../test/log_broadcast_and_tagging_test.rb | 137 ++++++++++++++++++ activesupport/test/tagged_logging_test.rb | 75 +++++++--- 8 files changed, 310 insertions(+), 48 deletions(-) create mode 100644 activesupport/lib/active_support/log_processor.rb create mode 100644 activesupport/test/log_broadcast_and_tagging_test.rb diff --git a/actioncable/lib/action_cable/connection/tagged_logger_proxy.rb b/actioncable/lib/action_cable/connection/tagged_logger_proxy.rb index d10778a34f7aa..6f66e21f61e78 100644 --- a/actioncable/lib/action_cable/connection/tagged_logger_proxy.rb +++ b/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 diff --git a/activejob/lib/active_job/logging.rb b/activejob/lib/active_job/logging.rb index 65f89e863fed7..36565d4491c5d 100644 --- a/activejob/lib/active_job/logging.rb +++ b/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 diff --git a/activesupport/lib/active_support/broadcast_logger.rb b/activesupport/lib/active_support/broadcast_logger.rb index 4d752faeed172..f36473e60b0fb 100644 --- a/activesupport/lib/active_support/broadcast_logger.rb +++ b/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) } diff --git a/activesupport/lib/active_support/log_processor.rb b/activesupport/lib/active_support/log_processor.rb new file mode 100644 index 0000000000000..681a353f251f4 --- /dev/null +++ b/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 diff --git a/activesupport/lib/active_support/logger.rb b/activesupport/lib/active_support/logger.rb index 99724f9921e39..54f9f841531e2 100644 --- a/activesupport/lib/active_support/logger.rb +++ b/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 # diff --git a/activesupport/lib/active_support/tagged_logging.rb b/activesupport/lib/active_support/tagged_logging.rb index 75e12e1e04540..486269e41b9ab 100644 --- a/activesupport/lib/active_support/tagged_logging.rb +++ b/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 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..7aaa24aa5bcc8 --- /dev/null +++ b/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 diff --git a/activesupport/test/tagged_logging_test.rb b/activesupport/test/tagged_logging_test.rb index 1f5dcd64c9b80..f8d7e39915901 100644 --- a/activesupport/test/tagged_logging_test.rb +++ b/activesupport/test/tagged_logging_test.rb @@ -16,15 +16,6 @@ def flush(*) @logger = ActiveSupport::TaggedLogging.new(MyLogger.new(@output)) end - test "sets logger.formatter if missing and extends it with a tagging API" do - logger = Logger.new(StringIO.new) - assert_nil logger.formatter - - other_logger = ActiveSupport::TaggedLogging.new(logger) - assert_not_nil other_logger.formatter - assert_respond_to other_logger.formatter, :tagged - end - test "tagged once" do @logger.tagged("BCX") { @logger.info "Funky time" } assert_equal "[BCX] Funky time\n", @output.string @@ -232,22 +223,66 @@ class TaggedLoggingWithoutBlockTest < ActiveSupport::TestCase assert_equal "[OMG] Broadcasting...\n", broadcast_output.string end - test "keeps formatter singleton class methods" do - plain_output = StringIO.new - plain_logger = Logger.new(plain_output) - plain_logger.formatter = Logger::Formatter.new - plain_logger.formatter.extend(Module.new { - def crozz_method - 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") - tagged_logger = ActiveSupport::TaggedLogging.new(plain_logger) - assert_respond_to tagged_logger.formatter, :tagged - assert_respond_to tagged_logger.formatter, :crozz_method + 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 "accepts non-String objects" do @logger.tagged("tag") { @logger.info [1, 2, 3] } assert_equal "[tag] [1, 2, 3]\n", @output.string end + + test "#new when passed a non TaggedLogging logger" do + io = StringIO.new + logger = Logger.new(io) + tagged_logger = ActiveSupport::TaggedLogging.new(logger) + + assert_same(logger, tagged_logger) + assert_kind_of(ActiveSupport::TaggedLogging, tagged_logger) + + tagged_logger.tagged("BMX").info("Hello") + + assert_equal("[BMX] Hello\n", io.string) + end + + test "#new when passed a TaggedLogging logger" do + io = StringIO.new + tagged_logger1 = ActiveSupport::TaggedLogging.new(Logger.new(io)) + tagged_logger2 = ActiveSupport::TaggedLogging.new(tagged_logger1) + + assert_not_same(tagged_logger1, tagged_logger2) + + tagged_logger1.tagged("1st Logger").info("Hello") + tagged_logger2.tagged("2nd Logger").info("Hello") + tagged_logger1.tagged("1st Logger").info("Hello") + + assert_equal(<<~EOM, io.string) + [1st Logger] Hello + [2nd Logger] Hello + [1st Logger] Hello + EOM + end end