logging: The mismatch of timing of replaceing the Rails default logger with Google::Cloud::Logging::Logger

Overview

WhenLogging.configure.set_default_logger_on_rails_init is false
various loggers in Rails framework(such as ActiveRecord::Base.logger) will not be replaced with Google::Cloud::Logging::Logger.
This may be because it is too late to replace the Rails default logger with Google::Cloud::Logging::Logger.

parhaps related: https://github.com/googleapis/google-cloud-ruby/issues/4510

On the other hand, when Logging.configure.set_default_logger_on_rails_init is true,
it is too early to replace the Rails default logger.
We got an error trying to reference Rails.logger.level when Rails.logger is uninitialized.

Detail

When rails app requires google/cloud/logging/rails, the cloud logging initializer will be set as Railtie#initializer.

This initializer runs init_middleware. In init_middleware method,

1. If Logging.configure.set_default_logger_on_rails_init = false(default)

set_default_logger will be called later.

Google::Cloud::Logging::Middleware will be loaded into rack middleware. After rack middlewares were build, then init_callback will be called, and Rails.logger will be replaced with Google::Cloud::Logging::Logger in set_default_logger method.

However, when init_callback is called, various loggers in Rails framework are already initialized and never will be replaced.

for example:

• https://github.com/rails/rails/blob/v6.1.4.1/activerecord/lib/active_record/railtie.rb#L77-L79
• https://github.com/rails/rails/blob/v6.1.4.1/actionview/lib/action_view/railtie.rb#L58-L60

This is perhaps because Rack middlewares are loaded after Railtie#initializer .
https://github.com/rails/rails/blob/90357af08048ef5076730505f6e7b14a81f33d0c/railties/lib/rails/application.rb#L48-L59

2. If Logging.configure.set_default_logger_on_rails_init = true

set_default_logger is called immediately.

https://github.com/googleapis/google-cloud-ruby/blob/5da8dc88a4c0b6f101043c8b35ec4ae8627f0b31/google-cloud-logging/lib/google/cloud/logging/rails.rb#L82

But at this point, Rails.logger is undefined, because init_middleware is called before initialize_logger.
So NoMethodError: undefined method level' for nil:NilClass` is raised here.

https://github.com/googleapis/google-cloud-ruby/blob/5da8dc88a4c0b6f101043c8b35ec4ae8627f0b31/google-cloud-logging/lib/google/cloud/logging/rails.rb#L120

Environment details

• OS: ruby:3.0.2-slim-buster
• Ruby version: 3.0.2
• Rails version: 6.1.4.1
• Gem name and version: google-cloud-logging (2.2.2)

Steps to reproduce

1. If Logging.configure.set_default_logger_on_rails_init = false(default)

1. bundle exec rails new sample -d mysql --api
2. cd sample
3. bundle add google-cloud-logging
4. make some controller/action
5. require in config/application.rb before Bundler.require

require "google/cloud/logging/rails"

6. configure in config/environments/development.rb

  config.google_cloud.use_logging = true
  config.google_cloud.project_id = "someproject"
  config.google_cloud.keyfile = "/opt/config.json"
  config.google_cloud.logging.log_name = "some_name"

7. run server and access the url
8. Got log in Cloud Logging: Started GET "/" for 127.0.0.1 at 2021-12-02 07:34:43 +0000, but got other logs in local log/development.log

2. Logging.configure.set_default_logger_on_rails_init = true

9. add config.google_cloud.logging.set_default_logger_on_rails_init = true in config/environments/development.rb
10. run server, and got Error:

/usr/local/bundle/gems/google-cloud-logging-2.2.2/lib/google/cloud/logging/rails.rb:120:in `set_default_logger': undefined method `level' for nil:NilClass (NoMethodError)
        from /usr/local/bundle/gems/google-cloud-logging-2.2.2/lib/google/cloud/logging/rails.rb:82:in `init_middleware'
        from /usr/local/bundle/gems/google-cloud-logging-2.2.2/lib/google/cloud/logging/rails.rb:59:in `block in <class:Railtie>'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/initializable.rb:32:in `instance_exec'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/initializable.rb:32:in `run'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/initializable.rb:61:in `block in run_initializers'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:228:in `block in tsort_each'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:422:in `block (2 levels) in each_strongly_connected_component_from'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:431:in `each_strongly_connected_component_from'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:421:in `block in each_strongly_connected_component_from'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/initializable.rb:50:in `each'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/initializable.rb:50:in `tsort_each_child'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:415:in `call'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:415:in `each_strongly_connected_component_from'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:349:in `block in each_strongly_connected_component'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:347:in `each'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:347:in `call'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:347:in `each_strongly_connected_component'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:226:in `tsort_each'
        from /usr/local/lib/ruby/3.0.0/tsort.rb:205:in `tsort_each'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/initializable.rb:60:in `run_initializers'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/application.rb:391:in `initialize!'
        from /app/sample/config/environment.rb:5:in `<main>'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `require'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `block in require_with_bootsnap_lfi'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/loaded_features_index.rb:100:in `register'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require_with_bootsnap_lfi'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:31:in `require'
        from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/kernel.rb:35:in `require'
        from /usr/local/bundle/gems/activesupport-6.1.4.1/lib/active_support/dependencies.rb:332:in `block in require'
        from /usr/local/bundle/gems/activesupport-6.1.4.1/lib/active_support/dependencies.rb:299:in `load_dependency'
        from /usr/local/bundle/gems/activesupport-6.1.4.1/lib/active_support/dependencies.rb:332:in `require'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:54:in `require_relative'
        from config.ru:3:in `block in <main>'
        from /usr/local/bundle/gems/rack-2.2.3/lib/rack/builder.rb:116:in `eval'
        from /usr/local/bundle/gems/rack-2.2.3/lib/rack/builder.rb:116:in `new_from_string'
        from /usr/local/bundle/gems/rack-2.2.3/lib/rack/builder.rb:105:in `load_file'
        from /usr/local/bundle/gems/rack-2.2.3/lib/rack/builder.rb:66:in `parse_file'
        from /usr/local/bundle/gems/rack-2.2.3/lib/rack/server.rb:349:in `build_app_and_options_from_config'
        from /usr/local/bundle/gems/rack-2.2.3/lib/rack/server.rb:249:in `app'
        from /usr/local/bundle/gems/rack-2.2.3/lib/rack/server.rb:422:in `wrapped_app'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/commands/server/server_command.rb:77:in `log_to_stdout'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/commands/server/server_command.rb:37:in `start'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/commands/server/server_command.rb:144:in `block in perform'
        from <internal:kernel>:90:in `tap'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/commands/server/server_command.rb:135:in `perform'
        from /usr/local/bundle/gems/thor-1.1.0/lib/thor/command.rb:27:in `run'
        from /usr/local/bundle/gems/thor-1.1.0/lib/thor/invocation.rb:127:in `invoke_command'
        from /usr/local/bundle/gems/thor-1.1.0/lib/thor.rb:392:in `dispatch'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/command/base.rb:69:in `perform'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/command.rb:48:in `invoke'
        from /usr/local/bundle/gems/railties-6.1.4.1/lib/rails/commands.rb:18:in `<main>'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `require'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `block in require_with_bootsnap_lfi'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/loaded_features_index.rb:100:in `register'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require_with_bootsnap_lfi'
        from /usr/local/bundle/gems/bootsnap-1.9.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:31:in `require'
        from /app/sample/bin/rails:5:in `<top (required)>'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/client/rails.rb:30:in `load'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/client/rails.rb:30:in `call'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/client/command.rb:7:in `call'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/client.rb:30:in `run'
        from /usr/local/bundle/gems/spring-3.1.1/bin/spring:49:in `<top (required)>'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/binstub.rb:11:in `load'
        from /usr/local/bundle/gems/spring-3.1.1/lib/spring/binstub.rb:11:in `<top (required)>'
        from /app/sample/bin/spring:10:in `require'
        from /app/sample/bin/spring:10:in `block in <top (required)>'
        from <internal:kernel>:90:in `tap'
        from /app/sample/bin/spring:7:in `<top (required)>'
        from bin/rails:2:in `load'
        from bin/rails:2:in `<main>'

Code example

described above

Full backtrace

described above

Start in google-cloud-logging/lib/google/cloud/logging/rails.rb, especially the Railtie initializer, init_middleware, and set_default_logger. Reproduce both set_default_logger_on_rails_init settings with the Rails 6.1.4.1 example and inspect the initializer ordering described in the issue. Done means Rails starts without the nil logger error and the relevant Rails framework loggers are replaced as intended.