googleapis / googleapis/google-cloud-ruby

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

Đang mở
#16,111 1 bình luận 0 reaction 0 người được giao Xem trên GitHub
:rotating_light: api: logging priority: p2 type: bug
Ngôn ngữ chính
Ruby
Star
1.4k
Fork
578
Merge trung bình
1 ngày 11 giờ
Pull request đã merge (30 ngày)
166

Mô tả

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

Hướng dẫn đóng góp

Mở hướng dẫn đóng góp

Hướng nghiên cứu

Bắt đầu trong google-cloud-logging/lib/google/cloud/logging/rails.rb, đặc biệt là Railtie initializer, init_middleware và set_default_logger. Tái hiện cả hai thiết lập của set_default_logger_on_rails_init với ví dụ Rails 6.1.4.1 và kiểm tra thứ tự initializer được mô tả trong issue. Được xem là hoàn tất khi Rails khởi động mà không có lỗi nil logger và các logger framework Rails liên quan được thay thế như dự kiến.

Do mô hình lập chỉ mục viết ra từ nội dung của issue.

Đánh giá

Công nghệ
rails, ruby
Lĩnh vực
observability
Loại issue
Lỗi
Độ khó
4/5
Thời gian dự kiến
3-5 ngày
Mức độ hoạt động
Đình trệ
Độ rõ ràng
Khá rõ ràng
Mức phù hợp với người mới
35/100

Nhận issue mới trong hộp thư của bạn

Bản tóm tắt ngắn những issue GitHub phù hợp với người mới.