Skip to content

Commit

Permalink
Fix TaggedLogging functionality when broadcasting:
Browse files Browse the repository at this point in the history
- This PR fixes two issues with the Tagged Logging feature in
  conjunction with broadcasting logs.

  For the sake of clarity I'll define the "main logger" and
  the "broadcasted logger" in this snippet:

  ```ruby
    main_logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(io))
    broadcaster_logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(io))

    main_logger.extend(Activesupport::Logger.broadcast(broadcasted_logger))
  ```

  1) The first issue that this PR fixes, is that the tags on the "main logger"
     don't propagate to the "broadcasted logger" when you pass in a block.

     ```ruby
     main_logger.tagged("FOO") { |logger| logger.info("Hello") }

     # Outputs:
     # [Foo] Hello <- By the main logger
     # Hello       <- By the broadcasted logger
     ```

     A fix was made in 70af536
     but that only works for the non block version

  2) It's quite common for the "broadcasted logger" to have a diffent
     log formatter that the "main logger". In example you'd want to
     output JSON logs in one and raw text in the other.

     That wasn't possible before. All loggers had to have the same
     instance of the formatter. The formatter was set on all loggers
     thanks to [this](https://github.com/rails/rails/blob/3fc9d12875dd434e454f74472da02014f6fa5d72/activesupport/lib/active_support/logger.rb#L45-L48) and it's [associated test](https://github.com/rails/rails/blob/3fc9d12875dd434e454f74472da02014f6fa5d72/activesupport/test/broadcast_logger_test.rb#L58-L64)
     This requirement was needed to make the Tagged Logging feature
     work; the tags being set in a thread variable whose name
     uses the `object_id` https://github.com/rails/rails/blob/3fc9d12875dd434e454f74472da02014f6fa5d72/activesupport/lib/active_support/tagged_logging.rb#L59
     (different formatter instance -> different object_id -> different variables)

     In this PR, I have removed the code that sets the same formatter
     instance on all logger. The "broadcaster logger" just need to
     have the `current_tags` point to the `current_tags` of the
     "main logger", I'm doing that by redefing the `current_tags`
     method each time the "main logger" uses a different formatter.

     The advantages by doing so is that custom made formatter
     can now call this `current_tags` method, which will return
     all the tags and process them the way they want.

     ```ruby
       class JSONLogFormatter
         def call(_, _, _, msg)
	   tags = current_tags # Can now retrieve the tags

	   { message: msg, tags: tags }.to_json
	 end
       end

       broadcasted_logger = Logger.new(io)
       broadcaster_logger.formatter = JSONLogFormatter.new
       main_logger = Logger.new(io)
       main_logger.extend(ActiveSupport::Logger.broadcast(broadcasted_logger))
     ```

     The behavior remains the same as before if a logger uses the
     Rails vanilla formatter or the Tagged Logging formatter.
  • Loading branch information
Edouard-chin committed Mar 15, 2022
1 parent 0ee85c7 commit 75aa3a0
Show file tree
Hide file tree
Showing 4 changed files with 77 additions and 13 deletions.
9 changes: 4 additions & 5 deletions activesupport/lib/active_support/logger.rb
Expand Up @@ -22,6 +22,10 @@ def self.logger_outputs_to?(logger, *sources)
# Broadcasts logs to multiple loggers.
def self.broadcast(logger) # :nodoc:
Module.new do
define_singleton_method(:extended) do |base|
base.public_send(:broadcast_to, logger) if base.respond_to?(:broadcast_to)
end

define_method(:add) do |*args, &block|
logger.add(*args, &block)
super(*args, &block)
Expand All @@ -42,11 +46,6 @@ def self.broadcast(logger) # :nodoc:
super(name)
end

define_method(:formatter=) do |formatter|
logger.formatter = formatter
super(formatter)
end

define_method(:level=) do |level|
logger.level = level
super(level)
Expand Down
15 changes: 15 additions & 0 deletions activesupport/lib/active_support/tagged_logging.rb
@@ -1,6 +1,7 @@
# frozen_string_literal: true

require "active_support/core_ext/module/delegation"
require "active_support/core_ext/module/redefine_method"
require "active_support/core_ext/object/blank"
require "logger"
require "active_support/logger"
Expand Down Expand Up @@ -94,6 +95,20 @@ def self.new(logger)

delegate :push_tags, :pop_tags, :clear_tags!, to: :formatter

def broadcast_to(other_logger) # :nodoc:
define_singleton_method(:formatter=) do |formatter|
other_logger.formatter ||= formatter

other_logger.formatter.singleton_class.redefine_method(:current_tags) do
formatter.current_tags
end

super(formatter)
end

self.formatter = self.formatter.clone
end

def tagged(*tags)
if block_given?
formatter.tagged(*tags) { yield self }
Expand Down
8 changes: 0 additions & 8 deletions activesupport/test/broadcast_logger_test.rb
Expand Up @@ -55,14 +55,6 @@ class BroadcastLoggerTest < TestCase
assert_equal ::Logger::FATAL, 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
assert_equal ::Logger::FATAL, log2.formatter
end

test "#local_level= assigns the local_level to all loggers" do
assert_equal ::Logger::DEBUG, logger.local_level
logger.local_level = ::Logger::FATAL
Expand Down
58 changes: 58 additions & 0 deletions activesupport/test/tagged_logging_test.rb
Expand Up @@ -226,4 +226,62 @@ class TaggedLoggingWithoutBlockTest < ActiveSupport::TestCase
assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "[OMG] Broadcasting...\n", broadcast_output.string
end

test "keeps broadcasting functionality when passed a block" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::TaggedLogging.new(Logger.new(broadcast_output))
@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))

@logger.tagged("OMG") { |logger| logger.info "Broadcasting..." }

assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "[OMG] Broadcasting...\n", broadcast_output.string
end

test "broadcasting when passing a block works and keeps formatter untouched" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::TaggedLogging.new(Logger.new(broadcast_output))
my_formatter = Class.new do
def call(_, _, _, msg)
ActiveSupport::JSON.encode(message: msg, tags: current_tags)
end
end
broadcast_logger.formatter = my_formatter.new

@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
@logger.tagged("OMG") { |logger| logger.info "Broadcasting..." }

assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "{\"message\":\"Broadcasting...\",\"tags\":[\"OMG\"]}", broadcast_output.string
end

test "broadcasting without passing a block works and keeps formatter untouched" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::TaggedLogging.new(Logger.new(broadcast_output))
my_formatter = Class.new do
def call(_, _, _, msg)
ActiveSupport::JSON.encode(message: msg, tags: current_tags)
end
end
broadcast_logger.formatter = my_formatter.new

@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
tagger_logger1 = @logger.tagged("OMG")
tagger_logger2 = tagger_logger1.tagged("FOO")
tagger_logger2.info("Broadcasting...")

assert_equal "[OMG] [FOO] Broadcasting...\n", @output.string
assert_equal "{\"message\":\"Broadcasting...\",\"tags\":[\"OMG\",\"FOO\"]}", broadcast_output.string
end

test "broadcasting on a non tagged logger" do
broadcast_output = StringIO.new
broadcast_logger = ActiveSupport::Logger.new(broadcast_output)

@logger.extend(ActiveSupport::Logger.broadcast(broadcast_logger))
@logger.tagged("OMG") { |logger| logger.info "Broadcasting..." }

assert_equal "[OMG] Broadcasting...\n", @output.string
assert_equal "Broadcasting...\n", broadcast_output.string
end
end

0 comments on commit 75aa3a0

Please sign in to comment.