Rails.logger.tagged will execute block as many times as the number of tagged loggers in the broadcast
#49745
Comments
davidstosik
changed the title
Rails.logger.tagged will execute block as many times as I have tagged loggers in the broadcastRails.logger.tagged will execute block as many times as the number of tagged loggers in the broadcast
|
Here's an idea: implement a "recursive" module ActiveSupport
class BroadcastLogger
# ...
def tagged(*tags, &block)
if block_given?
recursive_tagged(broadcasts, *tags, &block)
else
loggers = broadcasts.map do |logger|
if logger.respond_to?(:tagged)
logger.tagged(*tags)
else
logger
end
end
# probably could use Andrew's deep_dup
self.class.new(*loggers).tap do |broadcast_logger|
broadcast_logger.formatter = formatter
broadcast_logger.progname = progname
end
end
end
private
def recursive_tagged(loggers, *tags, &block)
return block.call if loggers.empty?
if loggers.first.respond_to?(:tagged)
loggers.first.tagged(*tags) do
recursive_tagged(loggers[1..-1], *tags, &block)
end
else # skip logger if it doesn't support tagging
recursive_tagged(loggers[1..-1], *tags, &block)
end
end
end
end
|
|
For the record, I tried a brand new Rails 7.1.1 application: rails new testlog --minimal
cd testlog
vim config/environments/development.rbAdd this: loggers = [
STDOUT,
"log/development.log",
].map do |output|
ActiveSupport::Logger.new(output)
.tap { |logger| logger.formatter = ::Logger::Formatter.new }
.then { |logger| ActiveSupport::TaggedLogging.new(logger) }
end
config.logger = ActiveSupport::BroadcastLogger.new(*loggers)Start Rails server, browse to the root, and receive this error.(If I change my code to broadcast to a single logger, then it works.) Here:
[
[200, ..., ...], # Rack::Headers and Rack::BodyProxy
[200, ..., ...] # Rack::Headers and Rack::BodyProxy
]This is caused by this line: rails/railties/lib/rails/rack/logger.rb Line 24 in 08473e3 (In the current state of things, |
Here's an executable test case reproducing the error I described manually in my previous comment.# frozen_string_literal: true
require "bundler/inline"
gemfile(true) do
source "https://rubygems.org"
gem "rails", github: "rails/rails", branch: "main"
end
require "action_controller/railtie"
class TestApp < Rails::Application
config.root = __dir__
config.hosts << "example.org"
config.secret_key_base = "secret_key_base"
routes.draw do
get "/" => "test#index"
end
end
class TestController < ActionController::Base
include Rails.application.routes.url_helpers
def index
render plain: "Home"
end
end
# Run Rails' initialize_logger initializer, defined here:
# https://github.com/rails/rails/blob/1f8f2fb9f5c4aa7250281e0bdd386129e06248a9/railties/lib/rails/application/bootstrap.rb#L35-L68
Rails.application.initializers
.find { _1.name == :initialize_logger }
.run(Rails.application)
require "minitest/autorun"
require "rack/test"
class BugTest < Minitest::Test
include Rack::Test::Methods
def test_returns_success
get "/"
assert last_response.ok?
Rails.logger.broadcast_to(
ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new($stdout))
)
get "/"
assert last_response.ok?
end
private
def app
Rails.application
end
endAnd the output. |
|
hey @Edouard-chin I saw that you mentioned you saw this one on the other issue so I assigned this to you too. Let us know if you need more information. |
|
Perfect, thanks @eileencodes 👍 |
|
@Edouard-chin Hi there! 👋🏻 Just a quick comment to mention that I noticed around the end of my day earlier, that Might want to consider what |
Edouard-chin
added a commit
to Edouard-chin/rails
that referenced
this issue
Oct 25, 2023
- ### 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.
Edouard-chin
added a commit
to Edouard-chin/rails
that referenced
this issue
Jan 17, 2024
- ### 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.
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Steps to reproduce
Expected behavior
When I do
Rails.logger.tagged("MY TAG") { do_something }, I expectdo_somethingto be called once, regardless of how many loggers Rails is broadcasting to.I also expect my log to be tagged and displayed in each logger. (I should see "[TEST] Doing something" once in the first log sink, and once in the second log sink.)
I don't know how common this is, but I've seen many applications (starting with Shopify), passing rather long blocks to
#tagged, expecting all logs produced by the code in that block to be tagged. This becomes a problem if we for example do database operations in that block.Actual behavior
The block passed to
taggedis run as many times as there are loggers broadcasted to.The log messages get multiplied too (obviously), and only one for each logger is tagged.
System configuration
Rails version:
HEADRuby version: 3.2.1
Still working on a graceful but quick solution to handle this. Suggestions welcome!
The text was updated successfully, but these errors were encountered: