googleapis / googleapis/google-cloud-ruby

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

Abierto
#16,111 1 comentario 0 reacciones 0 asignados Ver en GitHub
:rotating_light: api: logging priority: p2 type: bug
Lenguaje dominante
Ruby
Estrellas
1.4k
Forks
578
Merge medio
1 d 11 h
PR fusionados (30 d)
166

Descripción

## 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

Guía de contribución

Abrir la guía de contribución

Línea de trabajo

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.

Escrito por el modelo de indexación a partir del texto del issue.

Evaluación

Stack tecnológico
rails, ruby
Área
observability
Tipo de issue
Error
Dificultad
4/5
Tiempo estimado
3-5 días
Estado de actividad
Estancado
Claridad
Bastante claro
Aptitud para principiantes
35/100

Recibe los nuevos issues en tu correo

Un resumen breve de issues de GitHub para principiantes.