Railsにて、ActiveSupport::TaggedLoggingやActiveSupport::ErrorReporterを使って、Request-IDをログへ出力してみた

Railsをproductionモードで動かしている時、ログに

I, [*** #237177]  INFO -- : [95c95a65-608b-45d3-aa02-bcf61950e7c2] Completed 204 No Content in 1ms

と、 [95c95a65-608b-45d3-aa02-bcf61950e7c2] のようなHTTPリクエストを識別できるようなタグがついていることに気づきました。

一方、developmentモードで動かしている時はそのようなタグが見当たりません。

この違いがどこにあるのか気になったので、調べてみた時のメモを残します。

　
目次

環境

• Rails 7.1.2

　
なお、今回は

$ 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 に以下の設定がありました。

# Log to STDOUT by default
config.logger = ActiveSupport::Logger.new(STDOUT)
  .tap  { |logger| logger.formatter = ::Logger::Formatter.new }
  .then { |logger| ActiveSupport::TaggedLogging.new(logger) }

# Prepend all log lines with the following tags.
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の設定を移植します。

# from production
# Log to STDOUT by default
config.logger = ActiveSupport::Logger.new(STDOUT)
  .tap  { |logger| logger.formatter = ::Logger::Formatter.new }
  .then { |logger| ActiveSupport::TaggedLogging.new(logger) }

# Prepend all log lines with the following tags.
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へ例外オブジェクトの各属性を渡してみるとどうなるか確認します。

実装

今回は

• class
• message
• backtrace

を渡してみます。

なお、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

ActiveSupport::ErrorReporterを使ってみる

上記の方法で backtrace を取得できましたが、毎回同じようなコードを書くのは手間です。

backtraceを取得する対応として、前述の記事では CurrentAttributes + formatter を使っていました。

ただ、他に方法がないかを調べたところ、Kaigi on Rails 2023 の発表「Exceptional Rails」で紹介されていた ActiveSupport::ErrorReporter が使えそうでした。

• Exceptional Rails - Speaker Deck
• Kaigi on Rails2023で例外について発表してきました - おもしろwebサービス開発日記
• Rails アプリケーションのエラー通知 - Railsガイド
• ActiveSupport::ErrorReporter
• Rails標準のエラーレポートインターフェイスを追加 | 週刊Railsウォッチ: フォームヘルパーの改修、Railsの監査ログgem比較、DHHとimport-mapほか（20211129前編）｜TechRacho by BPS株式会社

　
そこで、今回は 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 を取得してログへ出力する
    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・ロギングに関する参考資料

• Usage with Rails | HTTP Request IDs | Heroku Dev Center
• Railsのlogger周りのコードリーディング
• 検索・集計がしやすいロギング環境の構築 - mrk21::blog {}
• Railsのバッチログにだけ何故かタイムスタンプが出なくて困った話 #Ruby - Qiita
• Railsのログに含まれるrequest_idについてコードリーディングしたメモ
• Request Idについて調べた - Re: 醤油の一升瓶じゃあ戦えない
• ログファイルが複数あるんだけど、全部に RequestId 入れたい #Rails - Qiita
• 調査しやすくするためログにリクエスト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