Railsをproductionモードで動かしている時、ログに
I, [*** #237177] INFO -- : [95c95a65-608b-45d3-aa02-bcf61950e7c2] Completed 204 No Content in 1ms
と、 [95c95a65-608b-45d3-aa02-bcf61950e7c2]
のようなHTTPリクエストを識別できるようなタグがついていることに気づきました。
一方、developmentモードで動かしている時はそのようなタグが見当たりません。
この違いがどこにあるのか気になったので、調べてみた時のメモを残します。
目次
環境
なお、今回は
$ bundle exec rails new rails_request_id --minimal --skip-bundle
$ cd rails_request_id/
$ bundle install
にて作成したRailsアプリを元に調査・実装していきます。
development環境でも、Request-IDをログへ出力する
調査
developmentとproductionの設定をファイルを見比べたところ、 config/environments/production.rb
に以下の設定がありました。
config.logger = ActiveSupport::Logger.new(STDOUT)
.tap { |logger| logger.formatter = ::Logger::Formatter.new }
.then { |logger| ActiveSupport::TaggedLogging.new(logger) }
config.log_tags = [ :request_id ]
Railsガイドには、それぞれ以下の説明がありました。
config.log_tags
について
3.2.44 config.log_tags
「requestオブジェクトが応答するメソッド」「requestオブジェクトを受け取るProc」または「to_sに応答できるオブジェクト」のリストを引数に取ります。これは、ログの行にデバッグ情報をタグ付けする場合に便利です。たとえばサブドメインやリクエストidを指定可能で、これらはマルチユーザーのproductionアプリケーションのデバッグで非常に有用です。
3.2.44 config.log_tags
| Rails アプリケーションの設定項目 - Railsガイド
config.logger
について
3.2.45 config.logger
タグ付きログをサポートする場合は、そのログのインスタンスをActiveSupport::TaggedLoggingでラップしなければなりません。
3.2.45 config.logger | Rails アプリケーションの設定項目 - Railsガイド
これらより、productionモードでは
- config.log_tags
- config.logger
の2つが設定されているために、Request-IDが出力されたと考えました。
実装
それでは実際にためしてみます。
まずは、 config/environments/development.rb
の末尾に、productionの設定を移植します。
config.logger = ActiveSupport::Logger.new(STDOUT)
.tap { |logger| logger.formatter = ::Logger::Formatter.new }
.then { |logger| ActiveSupport::TaggedLogging.new(logger) }
config.log_tags = [ :request_id ]
続いて、コントローラーを作成します。
class PollsController < ApplicationController
def index
end
end
最後に config/routes.rb
にルーティングを定義します。
今回は単に動作確認したいだけなので、リソースベースルーティングにはしません。
(なお、以降で掲載する実装では、routes.rbの実装は省略しています)
Rails.application.routes.draw do
get "polls" => "polls#index"
end
以上で実装は完了です。
動作確認
今回は curl を使って動作確認します。
HTTPリクエストヘッダにX-Request-IDがない場合
Railsを起動し、
$ curl http://localhost:3000/polls
を実行すると、以下のログが出力されました。
RailsがRequest-IDを生成し、ログへ出力したようです。
I, [2024-01-04T14:55:00.279164 #237177] INFO -- : [657269a2-2de5-4cdb-a861-cde782e0b09d] Started GET "/polls" for 127.0.0.1 at 2024-01-04 14:55:00 +0900
...
I, [2024-01-04T14:55:00.346282 #237177] INFO -- : [657269a2-2de5-4cdb-a861-cde782e0b09d] Completed 200 OK in 63ms (Views: 61.4ms | ActiveRecord: 0.0ms | Allocations: 3977)
HTTPリクエストヘッダにX-Request-IDがある場合
続いて、curlでHTTPリクエストヘッダに X-Request-ID を追加してみます。
$ curl -H 'X-Request-ID:123abc' http://localhost:3000/polls
すると、curlで渡したHTTPヘッダ X-Request-ID
の値がログに出力されました。
I, [2024-01-04T14:57:16.479859 #237177] INFO -- : [123abc] Started GET "/polls" for 127.0.0.1 at 2024-01-04 14:57:16 +0900
...
I, [2024-01-04T14:57:16.485114 #237177] INFO -- : [123abc] Completed 200 OK in 3ms (Views: 3.1ms | ActiveRecord: 0.0ms | Allocations: 1096)
開発者向けのエラーメッセージでも、Request-IDとbacktraceをログへ出力する
ここまでで、Request-IDが付与されることでログをトレースできるようになりました。
ただ、「処理を止めるまでもない例外が出たので、開発者向けにはログを出力し、例外自体は握りつぶして正常終了させる」という場合、以下の記事の通り TaggedLogging
では backtrace を取得できません。
RailsのCurrentAttributesを使ってX-Request-IDでnginx(Webサーバ)とunicorn(アプリサーバ)のログを追えるようにする方法 - R-Hack(楽天グループ株式会社)
TaggedLogging で開発者向けのログを出力してみた時の様子
では、実際にログへ何が出力されるかをためしてみます。
今回は動作確認が目的なので、コントローラで例外を握りつぶし、例外オブジェクトを logger に渡してみます。
class PollsController < ApplicationController
def logging_with_exception_object
raise 'error!'
rescue StandardError => e
logger.error(e)
end
curlで動作確認します。
$ curl http://localhost:3000/polls/logging_with_exception_object
すると、ログにはエラーメッセージ error!
のみ記録されました。ログにbacktraceが含まれないことから、例外を握りつぶした時の状況を追うのは大変そうです。
I, [2024-01-05T09:48:50.410898 #264090] INFO -- : [9f2b9d25-8d77-487c-b932-1741cd3b1b54] Started GET "/polls/logging_with_exception_object" for 127.0.0.1 at 2024-01-05 09:48:50 +0900
D, [2024-01-05T09:48:50.450455 #264090] DEBUG -- : [9f2b9d25-8d77-487c-b932-1741cd3b1b54] ActiveRecord::SchemaMigration Load (0.2ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
I, [2024-01-05T09:48:50.471630 #264090] INFO -- : [9f2b9d25-8d77-487c-b932-1741cd3b1b54] Processing by PollsController#logging_with_exception_object as */*
# 例外を握りつぶしたところで出力したログ
E, [2024-01-05T09:48:50.471945 #264090] ERROR -- : [9f2b9d25-8d77-487c-b932-1741cd3b1b54] error!
I, [2024-01-05T09:48:50.474279 #264090] INFO -- : [9f2b9d25-8d77-487c-b932-1741cd3b1b54] No template found for PollsController#logging_with_exception_object, rendering head :no_content
I, [2024-01-05T09:48:50.474505 #264090] INFO -- : [9f2b9d25-8d77-487c-b932-1741cd3b1b54] Completed 204 No Content in 3ms (ActiveRecord: 0.0ms | Allocations: 960)
例外オブジェクトそのものを渡す代わりに、loggerへ例外オブジェクトの各属性を渡してみる
例外オブジェクトを渡すとメッセージのみログに出力されます。
では、loggerへ例外オブジェクトの各属性を渡してみるとどうなるか確認します。
実装
今回は
を渡してみます。
なお、backtraceは文字列の配列になっているため、改行文字で結合しています。
class PollsController < ApplicationController
def logging_with_backtrace
raise 'error!!'
rescue StandardError => e
logger.error(e.class)
logger.error(e.message)
logger.error(e.backtrace.join("\n"))
end
動作確認
curlで動作確認します。
$ curl http://localhost:3000/polls/logging_with
_backtrace
ログを確認すると、各属性が出力されていました。backtraceも確認できました。
I, [2024-01-05T10:06:02.321388 #264090] INFO -- : [e2f5733f-aeb3-4a3f-9f73-1a51a6abadcb] Started GET "/polls/logging_with_backtrace" for 127.0.0.1 at 2024-01-05 10:06:02 +0900
I, [2024-01-05T10:06:02.322953 #264090] INFO -- : [e2f5733f-aeb3-4a3f-9f73-1a51a6abadcb] Processing by PollsController#logging_with_backtrace as */*
E, [2024-01-05T10:06:02.323211 #264090] ERROR -- : [e2f5733f-aeb3-4a3f-9f73-1a51a6abadcb] RuntimeError
E, [2024-01-05T10:06:02.323245 #264090] ERROR -- : [e2f5733f-aeb3-4a3f-9f73-1a51a6abadcb] error!!
E, [2024-01-05T10:06:02.323418 #264090] ERROR -- : [e2f5733f-aeb3-4a3f-9f73-1a51a6abadcb] path/to/app/controllers/polls_controller.rb:12:in `logging_with_backtrace'
path/to/vendor/bundle/ruby/3.2.0/gems/actionpack-7.1.2/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
...
path/to/vendor/bundle/ruby/3.2.0/gems/puma-6.4.1/lib/puma/thread_pool.rb:155:in `block in spawn_thread'
I, [2024-01-05T10:06:02.323782 #264090] INFO -- : [e2f5733f-aeb3-4a3f-9f73-1a51a6abadcb] No template found for PollsController#logging_with_backtrace, rendering head :no_content
上記の方法で backtrace を取得できましたが、毎回同じようなコードを書くのは手間です。
backtraceを取得する対応として、前述の記事では CurrentAttributes + formatter を使っていました。
ただ、他に方法がないかを調べたところ、Kaigi on Rails 2023 の発表「Exceptional Rails」で紹介されていた ActiveSupport::ErrorReporter
が使えそうでした。
そこで、今回は ActiveSupport::ErrorReporter による実装をためしてみます。
実装
コントローラでは、例外が発生したらエラーレポートサービスへ通知し、例外自体は握りつぶすよう実装します。
class PollsController < ApplicationController
def logging_with_error_subscriber
Rails.error.handle(StandardError) do
raise 'error!!!!'
end
end
end
続いて、サブスクライバを作成・登録します。
今回はRailsガイドに従い、 config/initializers/error_subscriber.rb
に実装していきます。
また、サブスクライバのreportメソッドの引数 context
には
context: リクエストやユーザーの詳細など、エラーに関する詳細なコンテキストを提供するHash。
1.3 エラー通知のオプション | Rails アプリケーションのエラー通知 - Railsガイド
とあるように、requestオブジェクトも含まれています。
そこで、headerから Request-ID を取得し、ログにも出力してみます。
ファイルの全体は以下の通りです。
class ErrorSubscriber
def report(error, handled:, severity:, context:, source: nil)
Rails.logger.error(error.class)
request_id = context[:controller].request.headers.env['action_dispatch.request_id']
Rails.logger.error(request_id)
Rails.logger.error(error.message)
Rails.logger.error(error.backtrace.join("\n"))
end
end
Rails.error.subscribe(ErrorSubscriber.new)
動作確認
curlで動作確認します。今回はHTTPリクエストヘッダごとの挙動を確認してみます。
HTTPリクエストヘッダにX-Request-IDがない場合
curlを実行します。
$ curl http://localhost:3000/polls/logging_with_error_subscriber
ログを確認すると、backtraceやRailsの生成したRequest-IDが出力されていました。
I, [2024-01-05T10:37:14.731778 #264090] INFO -- : [db74caa8-8bf3-4278-8463-4b8102eee967] Started GET "/polls/logging_with_error_subscriber" for 127.0.0.1 at 2024-01-05 10:37:14 +0900
I, [2024-01-05T10:37:14.733008 #264090] INFO -- : [db74caa8-8bf3-4278-8463-4b8102eee967] Processing by PollsController#logging_with_error_subscriber as */*
E, [2024-01-05T10:37:14.733391 #264090] ERROR -- : [db74caa8-8bf3-4278-8463-4b8102eee967] RuntimeError
E, [2024-01-05T10:37:14.733435 #264090] ERROR -- : [db74caa8-8bf3-4278-8463-4b8102eee967] db74caa8-8bf3-4278-8463-4b8102eee967
E, [2024-01-05T10:37:14.733466 #264090] ERROR -- : [db74caa8-8bf3-4278-8463-4b8102eee967] error!!!!
E, [2024-01-05T10:37:14.733661 #264090] ERROR -- : [db74caa8-8bf3-4278-8463-4b8102eee967] path/to/app/controllers/polls_controller.rb:21:in `block in logging_with_error_subscriber'
path/to/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.2/lib/active_support/error_reporter.rb:76:in `handle'
...
path/to/vendor/bundle/ruby/3.2.0/gems/puma-6.4.1/lib/puma/thread_pool.rb:155:in `block in spawn_thread'
I, [2024-01-05T10:37:14.734010 #264090] INFO -- : [db74caa8-8bf3-4278-8463-4b8102eee967] No template found for PollsController#logging_with_error_subscriber, rendering head :no_content
I, [2024-01-05T10:37:14.734128 #264090] INFO -- : [db74caa8-8bf3-4278-8463-4b8102eee967] Completed 204 No Content in 1ms (ActiveRecord: 0.0ms | Allocations: 189)
HTTPリクエストヘッダにX-Request-IDがある場合
curlを実行します。
$ curl -H 'X-Request-ID:123abc' http://localhost:3000/polls/logging_with_error_subscriber
ログを確認すると、backtraceやcurlで渡したRequest-IDが出力されていました。
I, [2024-01-05T10:34:00.030751 #264090] INFO -- : [123abc] Started GET "/polls/logging_with_error_subscriber" for 127.0.0.1 at 2024-01-05 10:34:00 +0900
I, [2024-01-05T10:34:00.031771 #264090] INFO -- : [123abc] Processing by PollsController#logging_with_error_subscriber as */*
E, [2024-01-05T10:34:00.032011 #264090] ERROR -- : [123abc] RuntimeError
E, [2024-01-05T10:34:00.032066 #264090] ERROR -- : [123abc] 123abc
E, [2024-01-05T10:34:00.032100 #264090] ERROR -- : [123abc] error!!!!
E, [2024-01-05T10:34:00.032221 #264090] ERROR -- : [123abc] path/to/app/controllers/polls_controller.rb:21:in `block in logging_with_error_subscriber'
path/to/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.2/lib/active_support/error_reporter.rb:76:in `handle'
...
path/to/vendor/bundle/ruby/3.2.0/gems/puma-6.4.1/lib/puma/thread_pool.rb:155:in `block in spawn_thread'
I, [2024-01-05T10:34:00.032553 #264090] INFO -- : [123abc] No template found for PollsController#logging_with_error_subscriber, rendering head :no_content
I, [2024-01-05T10:34:00.032670 #264090] INFO -- : [123abc] Completed 204 No Content in 1ms (ActiveRecord: 0.0ms | Allocations: 248)
以上より、ActiveSupport::ErrorReporterを使っても、Request-IDをログへ出力することができました。
その他、RailsとRequest-ID・ロギングに関する参考資料
Githubにあげました。
https://github.com/thinkAmi-sandbox/rails_logging_request_id_with_error_reporter-example
今回のプルリクはこちら。
https://github.com/thinkAmi-sandbox/rails_logging_request_id_with_error_reporter-example/pull/1