Reimplement TaggedLogging: #49771

Edouard-chin · 2023-10-24T17:24:15Z

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 was also not very intuitive:
```
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 New feature to allow adding extra information to log 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

rails/activesupport/lib/active_support/tagged_logging.rb

Line 124 in d68e439

logger.formatter = ActiveSupport::Logger::SimpleFormatter.new

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

Edouard-chin · 2023-10-24T17:25:36Z

activesupport/test/log_broadcast_and_tagging_test.rb

+    assert_equal("[BMX] Hello\n", @sink2.string)
+  end
+
+  test "tag logs for the whole broadcast without a block" do


Regression test for #49757 and #49745

Edouard-chin · 2023-10-24T17:26:36Z

activesupport/test/log_broadcast_and_tagging_test.rb

+    @broadcast.broadcast_to(@logger1, @logger2)
+  end
+
+  test "tag logs for the whole broadcast with a block" do


Regression test for #49745 and #44668

Edouard-chin · 2023-10-24T17:29:28Z

activesupport/lib/active_support/tagged_logging.rb

+        if logger.formatter.nil?
+          logger.formatter ||= Logger::SimpleFormatter.new
+        end


Added this for backward compatibility (otherwise logs would be formatted differently). I'd like to deprecate it though (see PR description if that also makes sense to you).

Edouard-chin · 2023-10-24T17:53:07Z

activesupport/test/log_broadcast_and_tagging_test.rb

+    assert_equal("[BMX] [BROADCAST2] Hello\n", @sink4.string)
+  end
+
+  test "#silence works while broadcasting to tagged loggers" do


@davidstosik I saw your comment on #49745 (comment) , but I wasn't able to reproduce the bug.

I wrote this test which is passing, let me know if this is similar to what you had in mind.

Yes, that's what I had in mind.
I think I was experiencing issues with #silence because I was experimenting with my own implementation of BroadcastLogger that did not include LoggerSilence.

I wonder, if I have two loggers in my broadcast with different severity levels, will silence have an unexpected impact of those loggers' respective level? (Eg. equalize them.)

Update: I confirmed that it doesn't look like there is any problem:

logger = ActiveSupport::BroadcastLogger.new( ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new($stdout)), ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new($stdout)).tap { _1.level = :warn }, ) puts "levels= " + logger.broadcasts.map(&:level).join(",") logger.silence do logger.warn("warning") logger.info("info") puts "in logger.silence" end puts "levels= " + logger.broadcasts.map(&:level).join(",") # Output: # levels= 0,2 # in logger.silence # (only once 👍🏻) # levels= 0,2 # (no other unexpected log)

@Edouard-chin I'm having more doubts about #silence (I guess unrelated to this PR, but as we started the conversation here...)

require "active_support/isolated_execution_state" require "active_support/logger_silence" require "active_support/broadcast_logger" logger = ActiveSupport::BroadcastLogger.new(Logger.new(STDOUT), Logger.new(STDOUT)) logger.silence { logger.warn("Error") }; # W, [2023-10-27T11:14:11.425871 #59954] WARN -- : Error # W, [2023-10-27T11:14:11.425960 #59954] WARN -- : Error

Should silencing a BroadcastLogger silence all loggers it broadcasts to, or should it silence only the loggers that support silencing?

That's a good question. I'd have expect it to silence all logs, no matter if the loggers supports silencing. Worth noting that the behaviour now is the same as before:

# Rails 7.0 Rails.logger.extend(ActiveSupport::Logger.broadcast(Logger.new(STDOUT)) Rails.logger.silence { Rails.logger.info("hello") } # I, [2023-10-27T14:00:18.659473 #86197] INFO -- : hello

Maybe we can change this behaviour in another PR and silence the whole broadcast. What do you think?

I'm definitely not asking it to be done in this PR! 👍🏻
When it comes to PRs, the smaller the better. 👌🏻

Ah yeah no worries! I was just wondering if silencing the whole broadcast is the behaviour you would expect and whether we should change it.

Yes, that would be my own expectation too. BroadcastLogger is trying to be "transparent" to the user, so doing Rails.logger.silence should, without surprise, stop Rails.logger.log from outputting anything on all channels.
Be careful though that LoggerSilence achieves that by temporarily assigning a different log level (using log_at). Doing so on the BroadcastLogger itself could make it impossible to restore each logger to its original level.

activesupport/lib/active_support/tagged_logging.rb

theforestvn88 · 2023-12-31T03:18:31Z

activesupport/lib/active_support/tagged_logging.rb

-        logger.formatter.extend LocalTagStorage
-        logger.push_tags(*formatter.current_tags, *tags)
+        logger = clone
+        logger.tag_processor.extend(LocalTagStorage)


hi, could you also resolve the issue 48787 ?
the LocalTagStorage is cause that TagStack is leaked across threads because it prevents the Formatter module (you change to class TagProcessor) to get the IsolatedExecutionState TagStack in each separate thread.
I wonder what the purpose of this LocalTagStorage anyway ?

The issue 48787 also raise the confusion about when shared tagged-logs across threads and when not, could you also introduce a proposal to clear this confusion also in this PR ?
Perhaps we could introduce a based_tagged to store all share-tagged which will use acrcoss threads, so TagStack in each thread will be based_tagged + IsolatedExecutionState TagStack.
what do you think ?

Hey! I'd have to dig on #48787 and figure out the original intent to share tags across threads (thought from a quick glance this seems to be on purpose).
This PR is big enough and the mentioned issue isn't really related to the changes I'm proposing here, so this will potentially be changed in another patch.

rafaelfranca · 2024-01-16T20:19:27Z

activesupport/lib/active_support/broadcast_logger.rb

+  # 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


Suggested change

# Tagging logs for the whole broadcast

# Tagging logs for the whole broadcast:

rafaelfranca · 2024-01-16T20:19:38Z

activesupport/lib/active_support/broadcast_logger.rb

+  #
+  #   Outputs: "[BMX] Hello world!" is written on both STDOUT and in the file.
+  #
+  # Tagging logs for a single logger


Suggested change

# Tagging logs for a single logger

# Tagging logs for a single logger:

rafaelfranca · 2024-01-16T20:19:50Z

activesupport/lib/active_support/broadcast_logger.rb

+  #   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


Suggested change

# Adding tags for the whole broadcast and adding extra tags on a specific logger

# Adding tags for the whole broadcast and adding extra tags on a specific logger:

rafaelfranca · 2024-01-16T20:21:01Z

activesupport/lib/active_support/broadcast_logger.rb

@@ -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)


Can we extend the logger when creating the broadcast? Otherwise we will invalidate the method cache at runtime instead of boottime.

Ah yes, good point 👍

Moved this to the broadcast_to method (which gets called when creating the broadcast).
This is to support adding loggers to the broadcast after initialisation and keep the broadcasting functionality working.

- ### 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.

rails-bot bot added actioncable activejob activesupport labels Oct 24, 2023

Edouard-chin commented Oct 24, 2023

View reviewed changes

Edouard-chin force-pushed the ec-tagged-logging branch from 3a49be6 to db764a4 Compare October 24, 2023 21:10

davidstosik reviewed Oct 25, 2023

View reviewed changes

activesupport/lib/active_support/tagged_logging.rb Show resolved Hide resolved

Edouard-chin force-pushed the ec-tagged-logging branch from db764a4 to 0f6da08 Compare October 25, 2023 11:40

theforestvn88 reviewed Dec 31, 2023

View reviewed changes

rafaelfranca reviewed Jan 16, 2024

View reviewed changes

rafaelfranca added this to the 7.1.4 milestone Jan 16, 2024

Edouard-chin added 2 commits January 17, 2024 13:19

PR review

ac23c0d

Edouard-chin force-pushed the ec-tagged-logging branch from 0f6da08 to ac23c0d Compare January 17, 2024 12:35

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Reimplement TaggedLogging: #49771

Reimplement TaggedLogging: #49771

Edouard-chin commented Oct 24, 2023 •

edited

Edouard-chin Oct 24, 2023

Edouard-chin Oct 24, 2023

Edouard-chin Oct 24, 2023

Edouard-chin Oct 24, 2023

davidstosik Oct 25, 2023

davidstosik Oct 25, 2023 •

edited

davidstosik Oct 27, 2023 •

edited

Edouard-chin Oct 27, 2023

davidstosik Oct 30, 2023

Edouard-chin Oct 30, 2023

davidstosik Oct 30, 2023 •

edited

theforestvn88 Dec 31, 2023 •

edited

Edouard-chin Jan 2, 2024

rafaelfranca Jan 16, 2024

rafaelfranca Jan 16, 2024

rafaelfranca Jan 16, 2024

rafaelfranca Jan 16, 2024

Edouard-chin Jan 17, 2024

Edouard-chin Jan 17, 2024

	# Tagging logs for the whole broadcast
	# Tagging logs for the whole broadcast:

	# Tagging logs for a single logger
	# Tagging logs for a single logger:

	# Adding tags for the whole broadcast and adding extra tags on a specific logger
	# Adding tags for the whole broadcast and adding extra tags on a specific logger:

Reimplement TaggedLogging: #49771

Are you sure you want to change the base?

Reimplement TaggedLogging: #49771

Conversation

Edouard-chin commented Oct 24, 2023 • edited

Context

Solution

Deprecation

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidstosik Oct 25, 2023 • edited

Choose a reason for hiding this comment

davidstosik Oct 27, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidstosik Oct 30, 2023 • edited

Choose a reason for hiding this comment

theforestvn88 Dec 31, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Edouard-chin commented Oct 24, 2023 •

edited

davidstosik Oct 25, 2023 •

edited

davidstosik Oct 27, 2023 •

edited

davidstosik Oct 30, 2023 •

edited

theforestvn88 Dec 31, 2023 •

edited