Railsのログに含まれるrequest_idについてコードリーディングしたメモ
bisquerequest_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を出力する方法について調査しました。
bisquerequest_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を参照しているわけです。
bisqueActiveSupport::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を参照することができるようになっています。
bisqueActiveSupport::TaggedLogging を使わずにrequest_idをログに差し込むには？
- ActiveSupport::TaggedLoggingと同様に、スレッド変数にrequest_idを格納するrack middlewareを作る
- スレッド変数のrequest_idを参照するログFormatterを作る
この2点でできるはずです。（未実装）
bisque参考