Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Fix the BroadcastLogger being initialized too late: #49417

Merged
merged 1 commit into from Sep 29, 2023
Merged

Fix the BroadcastLogger being initialized too late: #49417

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
2 changes: 1 addition & 1 deletion activerecord/lib/active_record/railtie.rb
View file
Open in desktop
Expand Up @@ -67,7 +67,7 @@ class Railtie < Rails::Railtie # :nodoc:
unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, STDERR, STDOUT)
console = ActiveSupport::Logger.new(STDERR)
console.level = Rails.logger.level
Rails.logger = ActiveSupport::BroadcastLogger.new(Rails.logger, console)
Rails.logger.broadcast_to(console)
end
ActiveRecord.verbose_query_logs = false
end
Expand Down
12 changes: 12 additions & 0 deletions activesupport/lib/active_support/broadcast_logger.rb
View file
Open in desktop
Expand Up @@ -202,5 +202,17 @@ def fatal!
def dispatch(&block)
@broadcasts.each { |logger| block.call(logger) }
end

def method_missing(name, *args)
loggers = @broadcasts.select { |logger| logger.respond_to?(name) }

if loggers.none?
super(name, *args)
elsif loggers.one?
loggers.first.send(name, *args)
else
loggers.map { |logger| logger.send(name, *args) }
end
end
end
end
13 changes: 10 additions & 3 deletions activesupport/lib/active_support/logger.rb
View file
Open in desktop
Expand Up @@ -14,9 +14,16 @@ class Logger < ::Logger
# ActiveSupport::Logger.logger_outputs_to?(logger, STDOUT)
# # => true
def self.logger_outputs_to?(logger, *sources)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

logdev = logger.instance_variable_get(:@logdev)
logger_source = logdev.dev if logdev.respond_to?(:dev)
sources.any? { |source| source == logger_source }
loggers = if logger.is_a?(BroadcastLogger)
logger.broadcasts
else
[logger]
end

logdevs = loggers.map { |logger| logger.instance_variable_get(:@logdev) }
logger_sources = logdevs.filter_map { |logdev| logdev.dev if logdev.respond_to?(:dev) }

(sources & logger_sources).any?
end

def initialize(*args, **kwargs)
Expand Down
28 changes: 28 additions & 0 deletions activesupport/test/broadcast_logger_test.rb
View file
Open in desktop
Expand Up @@ -244,6 +244,30 @@ def info(msg, &block)
assert_not_predicate(@logger, :fatal?)
end

test "calling a method that no logger in the broadcast have implemented" do
assert_raises(NoMethodError) do
@logger.non_existing
end
end

test "calling a method when *one* logger in the broadcast has implemented it" do
logger = BroadcastLogger.new(CustomLogger.new)

assert(logger.foo)
end

test "calling a method when *multiple* loggers in the broadcast have implemented it" do
logger = BroadcastLogger.new(CustomLogger.new, CustomLogger.new)

assert_equal([true, true], logger.foo)
end

test "calling a method when a subset of loggers in the broadcast have implemented" do
logger = BroadcastLogger.new(CustomLogger.new, FakeLogger.new)

assert(logger.foo)
end

class CustomLogger
attr_reader :adds, :closed, :chevrons
attr_accessor :level, :progname, :formatter, :local_level
Expand All @@ -258,6 +282,10 @@ def initialize
@formatter = nil
end

def foo
true
end

def debug(message, &block)
add(::Logger::DEBUG, message, &block)
end
Expand Down
10 changes: 10 additions & 0 deletions activesupport/test/logger_test.rb
View file
Open in desktop
Expand Up @@ -28,6 +28,16 @@ def test_log_outputs_to
assert_not Logger.logger_outputs_to?(@logger, STDOUT, STDERR), "Expected logger_outputs_to? to STDOUT or STDERR to return false, but was true"
end

def test_log_outputs_to_with_a_broadcast_logger
logger = ActiveSupport::BroadcastLogger.new(Logger.new(STDOUT))

assert(Logger.logger_outputs_to?(logger, STDOUT))
assert_not(Logger.logger_outputs_to?(logger, STDERR))

logger.broadcast_to(Logger.new(STDERR))
assert(Logger.logger_outputs_to?(logger, STDERR))
end

def test_write_binary_data_to_existing_file
t = Tempfile.new ["development", "log"]
t.binmode
Expand Down
2 changes: 1 addition & 1 deletion guides/source/configuring.md
View file
Open in desktop
Expand Up @@ -3431,7 +3431,7 @@ Below is a comprehensive list of all the initializers found in Rails in the orde

* `load_active_support`: Requires `active_support/dependencies` which sets up the basis for Active Support. Optionally requires `active_support/all` if `config.active_support.bare` is un-truthful, which is the default.

* `initialize_logger`: Initializes the logger (an `ActiveSupport::Logger` object) for the application and makes it accessible at `Rails.logger`, provided that no initializer inserted before this point has defined `Rails.logger`.
* `initialize_logger`: Initializes the logger (an `ActiveSupport::BroadcastLogger` object) for the application and makes it accessible at `Rails.logger`, provided that no initializer inserted before this point has defined `Rails.logger`.

* `initialize_cache`: If `Rails.cache` isn't set yet, initializes the cache by referencing the value in `config.cache_store` and stores the outcome as `Rails.cache`. If this object responds to the `middleware` method, its middleware is inserted before `Rack::Runtime` in the middleware stack.

Expand Down
4 changes: 4 additions & 0 deletions railties/lib/rails/application/bootstrap.rb
View file
Open in desktop
Expand Up @@ -56,6 +56,10 @@ module Bootstrap
end
Rails.logger.level = ActiveSupport::Logger.const_get(config.log_level.to_s.upcase)

broadcast_logger = ActiveSupport::BroadcastLogger.new(Rails.logger)
Copy link
Contributor

@st0012 st0012 Oct 1, 2023 •
edited

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👋 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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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!

broadcast_logger.formatter = Rails.logger.formatter
Rails.logger = broadcast_logger

unless config.consider_all_requests_local
Rails.error.logger = Rails.logger
end
Expand Down
2 changes: 1 addition & 1 deletion railties/lib/rails/commands/server/server_command.rb
View file
Open in desktop
Expand Up @@ -80,7 +80,7 @@ def log_to_stdout
console.level = Rails.logger.level

unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, STDERR, STDOUT)
Rails.logger = ActiveSupport::BroadcastLogger.new(Rails.logger, console)
Rails.logger.broadcast_to(console)
end
end

Expand Down
20 changes: 20 additions & 0 deletions railties/test/engine/commands_test.rb
View file
Open in desktop
Expand Up @@ -3,6 +3,7 @@
require "abstract_unit"
require "console_helpers"
require "plugin_helpers"
require "net/http"

class Rails::Engine::CommandsTest < ActiveSupport::TestCase
include ConsoleHelpers
Expand Down Expand Up @@ -57,6 +58,25 @@ def test_server_command_work_inside_engine
ensure
kill(pid)
end

def test_server_command_broadcast_logs
primary, replica = PTY.open
pid = spawn_command("server", replica, env: { "RAILS_ENV" => "development" })
assert_output("Listening on", primary)

Net::HTTP.new("127.0.0.1", 3000).tap do |net|
net.get("/")
end

in_plugin_context(plugin_path) do
logs = File.read("test/dummy/log/development.log")
assert_match("Processing by Rails::WelcomeController", logs)
end

assert_output("Processing by Rails::WelcomeController", primary)
ensure
kill(pid)
end
end

private
Expand Down