Railsのログに含まれるrequest_idについてコードリーディングしたメモ

request_idとは、Railsのログに標準で出力されるuuidのことです。リクエスト毎に一意なidが振られるようになっており、ログをトレースして見るのに便利です。

[42acbf94-050b-4728-a828-d6fea488a6ce] Started GET "/" for 172.20.0.1 at 2022-09-27 18:17:54 +0900

また、Request Header からrequest_idの値を設定したり、Response Headerにもrequest_idの値が設定されるので、うまく活用することで他のサービスも含めて串刺しでログをトレースすることができます。

今回、Railsのログフォーマットを構造化されたログに変えようとしたのですが、request_idは引き続き出力されるようにしたいと思い、request_idがどのように設定されるのか、またログフォーマットを変えたときにrequest_idを出力する方法について調査しました。

bisque

request_idが設定される箇所

ActionDispatch::RequestId は rack の middlewareです。middlewareって何っていう話は一旦置いておいて、Request Header に X-Request-Id があればその値を、なければランダムな値を生成してreqオブジェクトのrequest_idに設定していることが分かります。

reqオブジェクトは引数のenvを拡張したものなので、内部的には env の Response Header に request_id を設定しているのと同じことです。

ActionDispatch::Request の request_id の定義

ActionDispatch::Request は Rack::Requestをincludeしている。Rack::Request の set_header の定義

bisque

ログにrequest_idが差し込まれる仕組み

Rack::Logger middlewareで設定します。

if logger.respond_to?(:tagged) は、Rails.loggerがtaggedメソッドを持っていたらという判定です。taggedメソッドは ActiveSupport::TaggedLogging が提供しています。

つまり、Rails.loggerがActiveSupport::TaggedLoggingであれば logger.tagged(compute_tags(request)) を実行して、後続のmiddlewareへと進みます。

compute_tagsでは @taggers の内容に応じて配列を作成しています。@taggers はデフォルトでは config.log_tags の値が設定されます。この値は、デフォルトで [:request_id] となっています。@taggers の値がsymbolの場合、request.send(tag) が実行されますから、ここでは request.send(:request_id) 、つまり先ほどActionDispatch::Request middlewareで設定されたrequest_idを参照しているわけです。

bisque

ActiveSupport::TaggedLogging はtagをどうやって引き回しているのか

Rack::Logger middleware で logger.tagged(['リクエストID']) が設定されました。これがアプリケーション内のどの場所でも適用される仕組みが気になります。

taggedメソッドの定義を見てみます。中でyieldしているので、controller以下の処理は全てこのyieldの中で行われていることになります。

push_tagsメソッドではcurrent_tagsにtagsを追加しています。

current_tagsは IsolatedExecutionState です。

中身は Thread.current.active_support_execution_state です。つまり、スレッドセーフなスレッド変数にtagsを格納しているのですね。これにより、アプリケーション内のどの場所でもtagsを参照することができるようになっています。

bisque

ActiveSupport::TaggedLogging を使わずにrequest_idをログに差し込むには？

ActiveSupport::TaggedLoggingと同様に、スレッド変数にrequest_idを格納するrack middlewareを作る
スレッド変数のrequest_idを参照するログFormatterを作る

この2点でできるはずです。（未実装）

bisque

request_idが設定される箇所

ログにrequest_idが差し込まれる仕組み

ActiveSupport::TaggedLogging はtagをどうやって引き回しているのか

ActiveSupport::TaggedLogging を使わずにrequest_idをログに差し込むには？

参考