diff --git a/actioncable/lib/action_cable/connection/tagged_logger_proxy.rb b/actioncable/lib/action_cable/connection/tagged_logger_proxy.rb index b7d97afb09eee..c8fbab62603b7 100644 --- a/actioncable/lib/action_cable/connection/tagged_logger_proxy.rb +++ b/actioncable/lib/action_cable/connection/tagged_logger_proxy.rb @@ -25,7 +25,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 016fd6ed7a5ec..f133a8546d631 100644 --- a/activejob/lib/active_job/logging.rb +++ b/activejob/lib/active_job/logging.rb @@ -43,7 +43,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 4cc1e35914056..74bc4d82b7e99 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" @@ -91,6 +129,10 @@ def initialize(*loggers) # broadcast_logger = ActiveSupport::BroadcastLogger.new # broadcast_logger.broadcast_to(Logger.new(STDOUT), Logger.new(STDERR)) def broadcast_to(*loggers) + loggers.each do |logger| + logger.extend(LogProcessor) unless logger.is_a?(LogProcessor) + end + @broadcasts.concat(loggers) end @@ -114,32 +156,32 @@ def <<(message) end def add(...) - dispatch { |logger| logger.add(...) } + dispatch_with_processors { |logger| logger.add(...) } end alias_method :log, :add def debug(...) - dispatch { |logger| logger.debug(...) } + dispatch_with_processors { |logger| logger.debug(...) } end def info(...) - dispatch { |logger| logger.info(...) } + dispatch_with_processors { |logger| logger.info(...) } end def warn(...) - dispatch { |logger| logger.warn(...) } + dispatch_with_processors { |logger| logger.warn(...) } end def error(...) - dispatch { |logger| logger.error(...) } + dispatch_with_processors { |logger| logger.error(...) } end def fatal(...) - dispatch { |logger| logger.fatal(...) } + dispatch_with_processors { |logger| logger.fatal(...) } end def unknown(...) - dispatch { |logger| logger.unknown(...) } + dispatch_with_processors { |logger| logger.unknown(...) } end def formatter=(formatter) @@ -218,7 +260,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 @@ -232,6 +274,18 @@ def dispatch(&block) true end + def dispatch_with_processors(&block) + @broadcasts.each do |logger| + logger.processors.unshift(processors) + + block.call(logger) + ensure + logger.processors.shift(processors.count) + end + + true + end + def method_missing(name, ...) 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 09ea81f58eaab..5c9c76fb3e29b 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 594ea30e056c3..505fc1bc8e179 100644 --- a/activesupport/lib/active_support/tagged_logging.rb +++ b/activesupport/lib/active_support/tagged_logging.rb @@ -27,10 +27,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) @@ -118,33 +121,43 @@ def self.logger(*args, **kwargs) new ActiveSupport::Logger.new(*args, **kwargs) end - def self.new(logger) - logger = logger.clone - - if logger.formatter - logger.formatter = logger.formatter.clone + def self.new(logger) # :nodoc: + # Workaround for https://bugs.ruby-lang.org/issues/20250 + # Can be removed when Ruby 3.4 is the least supported version. + logger.formatter.object_id if logger.formatter.is_a?(Proc) - # Workaround for https://bugs.ruby-lang.org/issues/20250 - # Can be removed when Ruby 3.4 is the least supported version. - logger.formatter.object_id if logger.formatter.is_a?(Proc) + 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..92a91185adfb6 --- /dev/null +++ b/activesupport/test/log_broadcast_and_tagging_test.rb @@ -0,0 +1,144 @@ +# 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 + log_count = 0 + + @broadcast.tagged("BMX") do + @broadcast.info("Hello") + + log_count += 1 + end + + assert_equal(1, log_count) + 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 3cae39ab56522..13024130f7575 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 @@ -240,22 +231,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 diff --git a/railties/test/rack_logger_test.rb b/railties/test/rack_logger_test.rb index 290a9c91f0d1e..d879172c42e5f 100644 --- a/railties/test/rack_logger_test.rb +++ b/railties/test/rack_logger_test.rb @@ -128,20 +128,20 @@ def test_logger_pushes_tags logger_middleware = TestLogger.new(@logger, taggers: taggers) do # We can't really assert on logging something with the tags, because the MockLogger implementation # does not call the formatter (which is responsible for appending the tags) - assert_equal(["tag1", "tag2"], @logger.formatter.current_tags) + assert_equal(["tag1", "tag2"], @logger.tag_processor.current_tags) end block_sub = @notifier.subscribe "request.action_dispatch" do |_event| - assert_equal(["tag1", "tag2"], @logger.formatter.current_tags) + assert_equal(["tag1", "tag2"], @logger.tag_processor.current_tags) end # Call the app - it should log the inside app message response_body = logger_middleware.call("REQUEST_METHOD" => "GET").last # The tags should still be open as long as the request body isn't closed - assert_equal(["tag1", "tag2"], @logger.formatter.current_tags) + assert_equal(["tag1", "tag2"], @logger.tag_processor.current_tags) # And now should fire the request.action_dispatch event and call the event handler response_body.close # And it should also clear the tag stack. - assert_equal([], @logger.formatter.current_tags) + assert_equal([], @logger.tag_processor.current_tags) ensure @notifier.unsubscribe block_sub end