Fix dev initializer logs not going to stdout

[skipkayhil]

Motivation / Background

Previously, the Rails server and console commands would broadcast logs to STDOUT if the Rails.logger was not already logging to STDOUT/STDERR. However, the broadcast was setup after initialization had finished, so some logs may not have been broadcast. More specifically, anything logged during initialization after the :initialize_logger initializer would not be logged to STDOUT.

This is an issue especially because of how common it is for deprecation warnings to be logged during initialization. Very important deprecation warnings such as :warn_if_autoloaded in Rails 6/6.1 would not be logged to STDOUT even though application logs after initialization would.

This is very confusing because users most likely assumed that development logs were identical between STDOUT and log/development.log when they were actually not.

Detail

This commit fixes the issue by broadcasting when the logger is set up, so that STDOUT and log/development.log will both log everything.

Additional information

Ref #44800 as this also fixes the STDERR/STDOUT duplicate logs if Rails.logger is configured to output to STDERR

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.
• There are no typos in commit messages and comments.
• 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]
• Feature branch is up-to-date with main (if not - rebase it).
• Pull request only contains one commit for bug fixes and small features. If it's a larger feature, multiple commits are permitted but must be descriptive.
• Tests are added 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.
• PR is not in a draft state.
• CI is passing.

[p8]

So this method is still used by other commands like destroy and help.
These other commands will not log to stdout?

[skipkayhil]

The reason I only included server and console is those are the only commands that are broadcasted to STDOUT right now. However, I definitely agree that users could expect other commands to output to STDOUT as well. Maybe the answer would be to always broadcast to STDOUT in development?

That would also have the benefit of simplifying this change as it wouldn't need the log_to_stdout config at all.

Edit: I remembered that the server command also uses --log-to-stdout, it just gets enabled by default in development unless the server is daemonized. I wonder how many people use --no-log-to-stdout in development because they don't want STDOUT logs

[p8]

Hmm, not sure where this method is defined and why it's no longer necessary. Any idea? 😄

[skipkayhil]

Good question!

wrapped_app comes from Rack::Server here: https://github.com/rack/rack/blob/abca7d59c566320f1b60d1f5224beac9d201fa3b/lib/rack/server.rb#L421

Rack calls wrapped_app on its own here: https://github.com/rack/rack/blob/abca7d59c566320f1b60d1f5224beac9d201fa3b/lib/rack/server.rb#L327

However, if you want to modify the application (like making the logger broadcast), then you have to "touch the app". All this does is load the app a bit earlier than Rack would normally so that things like initializers have a change to run first.

[p8]

This does seem to belong here with the other setup of the Rails.logger.
Also nice that it removes the duplication.

[Edouard-chin]

Tried your branch after rebasing and it LGTM !

There is a lot of moving parts on the logger configuration and I find a end to end test to be more robust. There is already one that make sure things get logged on STDOUT and in the file, but maybe we could add another one to see if deprecations are correctly output. Feel free to grab this patch if you agree.

diff --git a/railties/test/application/server_test.rb b/railties/test/application/server_test.rb
index 982b3f4f6e..3ea35a6254 100644
--- a/railties/test/application/server_test.rb
+++ b/railties/test/application/server_test.rb
@@ -66,6 +66,32 @@ def teardown
       end
     end

+    test "deprecation messages are displayed at boot time when server runs" do
+      skip "PTY unavailable" unless available_pty?
+
+      File.open("#{app_path}/config/boot.rb", "w") do |f|
+        f.puts "ENV['BUNDLE_GEMFILE'] = '#{Bundler.default_gemfile}'"
+        f.puts 'require "bundler/setup"'
+      end
+
+      add_to_config(<<~CODE)
+        initializer :deprecation, after: :initialize_logger do
+          ActiveSupport.deprecator.warn("Something something")
+        end
+      CODE
+
+      primary, replica = PTY.open
+      pid = nil
+
+      Bundler.with_original_env do
+        pid = Process.spawn("bin/rails server", chdir: app_path, in: replica, out: primary, err: replica)
+        assert_output("DEPRECATION WARNING: Something something", primary)
+        assert_output("Listening on", primary)
+      ensure
+        kill(pid) if pid
+      end
+    end
+
     private
       def kill(pid)
         Process.kill("TERM", pid)