googleapis / googleapis/google-cloud-ruby

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

Ouverte
#16,111 1 commentaire 0 réactions 0 personnes assignées Voir sur GitHub
:rotating_light: api: logging priority: p2 type: bug
Langage dominant
Ruby
Étoiles
1.4k
Forks
578
Merge moyen
1 j 11 h
PR mergées (30 j)
166

Description

## Overview

When`Logging.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](https://github.com/googleapis/google-cloud-ruby/blob/5da8dc88a4c0b6f101043c8b35ec4ae8627f0b31/google-cloud-logging/lib/google/cloud/logging/rails.rb), 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](https://hub.docker.com/layers/ruby/library/ruby/3.0.2-slim-buster/images/sha256-64d8b5be06054b8b4c79b8c01dec6776401552eebaf91f36ee70be3b3d3d0515?context=explore)
- 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`
```rb
require "google/cloud/logging/rails"
```
6. configure in `config/environments/development.rb`
```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 '
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 `'
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 '
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 :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 `'
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 `'
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 `'
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 `'
from /app/sample/bin/spring:10:in `require'
from /app/sample/bin/spring:10:in `block in '
from :90:in `tap'
from /app/sample/bin/spring:7:in `'
from bin/rails:2:in `load'
from bin/rails:2:in `'
```

#### Code example

described above

#### Full backtrace

described above

Guide de contribution

Ouvrir le guide de contribution

Piste de recherche

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.

Rédigé par le modèle d'indexation à partir du texte de l'issue.

Évaluation

Stack technique
rails, ruby
Domaine
observability
Type d'issue
Bug
Difficulté
4/5
Temps estimé
3-5 jours
Activité
À l'abandon
Clarté
Plutôt claire
Accessibilité débutants
35/100

Recevez les nouvelles issues par e-mail

Un résumé court des issues GitHub adaptées aux débutants.