Fix the BroadcastLogger being initialized too late:

[Edouard-chin]

Motivation / Background

An oversight of #48615 is that it changes the Rails.logger to be a broadcast logger after the app is booted. Anything referencing Rails.logger during the boot process will get a simple logger and ultimately resulting in logs not being broadcasted.

For example ActionController::Base.logger.info("abc") would just output logs in the development.log file, not on STDOUT.

Detail

The only solution I could think of is to create a BroadcastLogger earlier at boot, and add logger to that broadcast when needed (instead of modiyfing the Rails.logger variable).

Checklist

Before submitting the PR make sure the following are checked:

• This Pull Request is related to one change. Changes that are unrelated should be opened in separate PRs.
• Commit message has a detailed description of what changed and why. If this PR fixes a related issue include it in the commit message. Ex: [Fix #issue-number]
• Tests are added or updated if you fix a bug or add a feature.
• CHANGELOG files are updated for the changed libraries if there is a behavior change or additional feature. Minor bug fixes and documentation changes should not be included.

[skipkayhil]

I opened a PR a while ago for a different problem but I believe it would address this as well: #46170. Instead of applying the Broadcast after initialization I think it would be cleaner for Rails to apply it immediately when constructing the logger.

[Edouard-chin]

Thanks for the heads up, it makes sense to me! If that's ok I'd prefer fixing this in another PR. Trying to fix the remaining broken tests and also realising that the logger_outputs_to? thing don't work with a BroadcastLogger. Pulling in your changes might be a bit too much for this PR.

[Edouard-chin]

Not a big fan of this and that's basically how it used to work previously (custom method on the main logger wouldn't propagate to all loggers).

I'd rather iterate over all the loggers in the broadcast that responds to the method, but the problem is for the return value here which would necessarily be an enumerable, this would be confusing and also breaks a bunch of tests (see the snippet for example)

Decided to leave it as how it used to work

class MyCustomLogger < Logger
 def foo
   true
 end
end

# config/application.rb
config.logger = MyCustomLogger.new

# Rails.logger becomes a BroadcastLogger during [initialization](https://github.com/rails/rails/pull/49417/files#diff-55bc5dde25c29798e0e8fceb70e7391a67a262e0cc2550d179eefa0a3bbc4cffR61)
Rails.logger.foo # => [true]

[rafaelfranca]

In that case maybe we should remove the support to passing multiple loggers to the initializer since now we are making one logger special.

[Edouard-chin]

I figured an alternative that I think is a good compromise:

Return all returned values by the loggers as an array, or just the raw return value when a single logger in the broadcast could handle the method.

This should allow existing applications who have a custom logger to behave the same as before. For apps or libraries that will use the BroadcastLogger, it should be less confusing than having only one logger able to handle custom methods.

class MyLogger < Logger
  def foo
    true
  end
end

broadcast = BroadcastLogger.new(MyLogger.new)
broadcast.foo # => true

broadcast.broadcast_to(MyLogger.new)
broadcast.foo # => [true, true]

Let me know if that's ok, otherwise I'll revert and apply your suggestions. Thanks 🙇‍♂️

[Edouard-chin]

This method was not working properly even before. It was only checking if the main logger (the broadcast one) would output to sources but didn't consider that other loggers part of the broadcast could have.

[st0012]

Is it possible that when users already use ActiveSupport::BroadcastLogger in configs, and then they'd get an 2-level nested BroadcastLogger from this?

(I deleted my original comment on the commit as a PR comment should be more discoverable)

[Edouard-chin]

👋 That's indeed possible, and I remember seeing this in applications frequently. I made sure that it is supported

rails/activesupport/test/broadcast_logger_test.rb

Lines 163 to 175 in a5f113f

	test "#broadcast on another broadcasted logger" do
	@log3 = FakeLogger.new
	@log4 = FakeLogger.new
	@broadcast2 = ActiveSupport::BroadcastLogger.new(@log3, @log4)
	@logger.broadcast_to(@broadcast2)
	@logger.info("Hello")
	assert_equal([[1, "Hello", nil]], @log1.adds)
	assert_equal([[1, "Hello", nil]], @log2.adds)
	assert_equal([[1, "Hello", nil]], @log3.adds)
	assert_equal([[1, "Hello", nil]], @log4.adds)
	end

[st0012]

Sorry I wasn't clear. I didn't mean that the propagation wouldn't work. I meant the logger would be nested like this:

#<ActiveSupport::BroadcastLogger:0x0000000114b374b8
 @broadcasts=
  [#<ActiveSupport::BroadcastLogger:0x000000011367d9a0
    @broadcasts=
     [#<ActiveSupport::BroadcastLogger:0x00000001139b1770
       @broadcasts=
        [#<Logger:0x0000000113d76180 @default_formatter=#<Logger::Formatter:0x00000001139b1810 @datetime_format=nil>, @formatter=nil, @level=0, @logdev=nil, @progname=nil>,
         #<Logger:0x0000000113d76130 @default_formatter=#<Logger::Formatter:0x00000001139b17c0 @datetime_format=nil>, @formatter=nil, @level=0, @logdev=nil, @progname=nil>],
       @formatter=nil,
       @progname="Broadcast">],
    @formatter=nil,
    @progname="Broadcast">],
 @formatter=nil,
 @progname="Broadcast">

If the user manually configs broadcast logger like:

config.logger = ActiveSupport::BroadcastLogger.new(
  ::Logger.new(nil),
  ::Logger.new(nil)
)

I personally would be surprised if I see another single ActiveSupport::BroadcastLogger when calling Rails.logger.broadcasts in this case.

[Edouard-chin]

Ah sorry I misunderstood. Yeah good point, that feels wrong. I'll open a fix

[dustinbrownman]

I think related to this, I'm noticing an issue where the initially configured logger is being put into the BroadcastLogger, but attached ActionController::LogSubscriber methods are still logging to the original logger. For example:

broadcast_logger = ActiveSupport::BroadcastLogger.new(
  config.logger # <-- Logs via LogSubscriber are being logged to this logger and not others
)

I haven't been able to write a test that reproduces the behavior, so it could be a strange configuration in my own codebase. I thought it was worth calling out there anyway.

[rafaelfranca]

This issue is what this PR fixes, so maybe you are using a version without this fix?

[Edouard-chin]

You can also check if other loggers (e.g. ActiveRecord::Base.logger) have the same issue. If it's only ActionController::Base.logger it's maybe because your app or a library modifies that variable manually.

To help debug you could create 2 initializers and see the value of ActionController::Base.logger

# config/application.rb

initializer "debug_logger_before", before: "action_controller.set_configs" do
  puts ActionController::Base.logger # Should normally be nil
end

initializer "debug_logger_after", after: "action_controller.set_configs" do
  puts ActionController::Base.logger # Should be a `BroadcastLogger` instance.

  # If it's a `BroadcastLogger` instance, then something in your app or a gem
  # modifies it afterward.
  
  # If it's not a `BroadcastLogger`, it could be because the logger is overriden. 
  # Check if you have a line of code that looks like `config.action_controller.logger = ...`
end

[dustinbrownman]

This was very helpful, thank you! To confirm, it was an issue on our end, but not the way I thought it was.

We had a test that was stubbing add on ActionController::Base.logger. The trick is that add was never being sent to that logger, only info. This worked previously because internally the Ruby Logger calls add in info (and other such methods). But that add was never being called on the BroadcastLogger.

We updated our test to stub the correct method and it's working. Thanks again for this debugging help!