From 40cb50e06e1bec28d8219b8af815a3b395f08088 Mon Sep 17 00:00:00 2001 From: Edouard CHIN Date: Thu, 28 Sep 2023 15:53:28 +0200 Subject: [PATCH] Fix the BroadcastLogger being initialized too late: - 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. ---- 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). --- activerecord/lib/active_record/railtie.rb | 2 +- .../lib/active_support/broadcast_logger.rb | 12 ++++++++ activesupport/lib/active_support/logger.rb | 13 +++++++-- activesupport/test/broadcast_logger_test.rb | 28 +++++++++++++++++++ activesupport/test/logger_test.rb | 10 +++++++ guides/source/configuring.md | 2 +- railties/lib/rails/application/bootstrap.rb | 4 +++ .../rails/commands/server/server_command.rb | 2 +- railties/test/engine/commands_test.rb | 20 +++++++++++++ 9 files changed, 87 insertions(+), 6 deletions(-) diff --git a/activerecord/lib/active_record/railtie.rb b/activerecord/lib/active_record/railtie.rb index fc2f6fdc3f060..6d0581fc77e7d 100644 --- a/activerecord/lib/active_record/railtie.rb +++ b/activerecord/lib/active_record/railtie.rb @@ -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 diff --git a/activesupport/lib/active_support/broadcast_logger.rb b/activesupport/lib/active_support/broadcast_logger.rb index e5c9efbccc92d..33255902d03dd 100644 --- a/activesupport/lib/active_support/broadcast_logger.rb +++ b/activesupport/lib/active_support/broadcast_logger.rb @@ -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 diff --git a/activesupport/lib/active_support/logger.rb b/activesupport/lib/active_support/logger.rb index 09a295f287090..99724f9921e39 100644 --- a/activesupport/lib/active_support/logger.rb +++ b/activesupport/lib/active_support/logger.rb @@ -14,9 +14,16 @@ class Logger < ::Logger # ActiveSupport::Logger.logger_outputs_to?(logger, STDOUT) # # => true def self.logger_outputs_to?(logger, *sources) - 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) diff --git a/activesupport/test/broadcast_logger_test.rb b/activesupport/test/broadcast_logger_test.rb index d326f13ed1324..1c6d3bd37c77a 100644 --- a/activesupport/test/broadcast_logger_test.rb +++ b/activesupport/test/broadcast_logger_test.rb @@ -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 @@ -258,6 +282,10 @@ def initialize @formatter = nil end + def foo + true + end + def debug(message, &block) add(::Logger::DEBUG, message, &block) end diff --git a/activesupport/test/logger_test.rb b/activesupport/test/logger_test.rb index f9849aae3db34..9962426ad71f6 100644 --- a/activesupport/test/logger_test.rb +++ b/activesupport/test/logger_test.rb @@ -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 diff --git a/guides/source/configuring.md b/guides/source/configuring.md index 9903c78a6b20d..41e1ce803488c 100644 --- a/guides/source/configuring.md +++ b/guides/source/configuring.md @@ -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. diff --git a/railties/lib/rails/application/bootstrap.rb b/railties/lib/rails/application/bootstrap.rb index d0dc1c242382c..5dd580f372aba 100644 --- a/railties/lib/rails/application/bootstrap.rb +++ b/railties/lib/rails/application/bootstrap.rb @@ -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) + broadcast_logger.formatter = Rails.logger.formatter + Rails.logger = broadcast_logger + unless config.consider_all_requests_local Rails.error.logger = Rails.logger end diff --git a/railties/lib/rails/commands/server/server_command.rb b/railties/lib/rails/commands/server/server_command.rb index a2ba490482f91..ca13a63bb0b63 100644 --- a/railties/lib/rails/commands/server/server_command.rb +++ b/railties/lib/rails/commands/server/server_command.rb @@ -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 diff --git a/railties/test/engine/commands_test.rb b/railties/test/engine/commands_test.rb index bc9211ce967d5..3e888ce0d86b5 100644 --- a/railties/test/engine/commands_test.rb +++ b/railties/test/engine/commands_test.rb @@ -3,6 +3,7 @@ require "abstract_unit" require "console_helpers" require "plugin_helpers" +require "net/http" class Rails::Engine::CommandsTest < ActiveSupport::TestCase include ConsoleHelpers @@ -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