Request id について

herokuで動いているRailsアプリケーションのログを眺めていたときに出てくる、uuidって何?となったのでメモる。わからないところがわかったら、あとで加筆する。

つまり

RailsアプリケーションにはX-Request-Id というHTTPヘッダーを見てログに出す仕組みがある。
herokuのWebサーバーが X-Request-Id を付与してRailsアプリケーションにリクエストを流している
X-Request-Id の仕組みはherokuに限らず、Webサーバー全体で使われてそう。

sequenceDiagram
    participant ブラウザ
    participant heroku/router
    participant app/web(Rails)
    
    ブラウザ->>heroku/router: APIリクエスト
    heroku/router->>heroku/router: X-Request-IDヘッダーをログ出力
    heroku/router->>app/web(Rails): X-Request-IDヘッダーを付加してリクエスト
    activate app/web(Rails)
    app/web(Rails)->>app/web(Rails): 処理
    app/web(Rails)->>app/web(Rails): X-Request-IDの内容を含めてアプリケーショのログ出力
    deactivate app/web(Rails)
    app/web(Rails)->>heroku/router: レスポンスを返す
    heroku/router->>ブラウザ: レスポンスを返す

Railsのロギング

先にRailsアプリケーションがどうやってログ出しているの?というところから。

Railsアプリケーションでログ出力の設定としてRails::Application::Configuration クラスの log_tags プロパティが存在する。 Rails アプリケーションを設定する - Railsガイドには以下の記述がある。

config.log_tags: 次のリストを引数に取ります（requestオブジェクトが応答するメソッド、requestオブジェクトを受け取るProc、またはto_sに応答できるオブジェクト）。これは、ログの行にデバッグ情報をタグ付けする場合に便利です。たとえばサブドメインやリクエストidを指定することができ、これらはマルチユーザーのproductionアプリケーションをデバッグするのに便利です。

色々付加してログに出せるっぽいですね。

Rails 6.0.3.2でrails new した時点で、config/environments/production.rb にはconfig.log_tags = [ :request_id ]が設定されている。この :request_id は requestオブジェクトが応答するメソッド に合致する。この先はRackかと思ったのだけども迷子になってしまったのでまた別の機会の追う。

production.rb にある設定を config/environments/development.rb で同じように設定したうえでリクエストをすると、以下のような結果になる。

X-Request-Id ヘッダーなし

$ curl -I http://localhost:3000
HTTP/1.1 200 OK
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block
X-Content-Type-Options: nosniff
X-Download-Options: noopen
X-Permitted-Cross-Domain-Policies: none
Referrer-Policy: strict-origin-when-cross-origin
Content-Type: text/html; charset=utf-8
ETag: W/"6e6be3ab17e553298ac68f8a42a50540"
Cache-Control: max-age=0, private, must-revalidate
Content-Security-Policy: script-src 'unsafe-inline'; style-src 'unsafe-inline'
X-Request-Id: d662620f-f16e-4b0f-b0df-34a45247f195
X-Runtime: 0.005475

# $ curl -I http://localhost:3000 の結果
[d6e516d6-8a13-4bb4-be3a-c0a0636b4b0e] Started GET "/" for ::1 at 2020-07-24 19:41:13 +0900
[d6e516d6-8a13-4bb4-be3a-c0a0636b4b0e]    (1.6ms)  SELECT sqlite_version(*)
[d6e516d6-8a13-4bb4-be3a-c0a0636b4b0e] Processing by Rails::WelcomeController#index as HTML
[d6e516d6-8a13-4bb4-be3a-c0a0636b4b0e]   Rendering /Users/ikaruga/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.2/lib/rails/templates/rails/welcome/index.html.erb
[d6e516d6-8a13-4bb4-be3a-c0a0636b4b0e]   Rendered /Users/ikaruga/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.2/lib/rails/templates/rails/welcome/index.html.erb (Duration: 10.1ms | Allocations: 295)
[d6e516d6-8a13-4bb4-be3a-c0a0636b4b0e] Completed 200 OK in 22ms (Views: 15.4ms | ActiveRecord: 0.0ms | Allocations: 1643)

X-Request-Id ヘッダーあり

$ curl -I -H "X-Request-Id: 1" http://localhost:3000
HTTP/1.1 200 OK
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block
X-Content-Type-Options: nosniff
X-Download-Options: noopen
X-Permitted-Cross-Domain-Policies: none
Referrer-Policy: strict-origin-when-cross-origin
Content-Type: text/html; charset=utf-8
ETag: W/"6e6be3ab17e553298ac68f8a42a50540"
Cache-Control: max-age=0, private, must-revalidate
Content-Security-Policy: script-src 'unsafe-inline'; style-src 'unsafe-inline'
X-Request-Id: 1
X-Runtime: 0.018485

[1] Started HEAD "/" for ::1 at 2020-07-24 19:52:49 +0900
[1] Processing by Rails::WelcomeController#index as */*
[1]   Rendering /Users/ikaruga/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.2/lib/rails/templates/rails/welcome/index.html.erb
[1]   Rendered /Users/ikaruga/.rbenv/versions/2.7.1/lib/ruby/gems/2.7.0/gems/railties-6.0.3.2/lib/rails/templates/rails/welcome/index.html.erb (Duration: 3.3ms | Allocations: 8)
[1] Completed 200 OK in 12ms (Views: 5.6ms | ActiveRecord: 0.0ms | Allocations: 303)

レスポンスヘッダーに付加して返すのはActionDispatch::RequestIdのしごとかな。 rails/request_id.rb at v6.0.3.2 · rails/rails

herokuのRequest id

では、herokuではどうしているかというと、 HTTP Request IDs | Heroku Dev Center に大体の事が書いてあるのでそれを読む。

リクエストを受けると、herokuのrouterがリクエストID(UUID)を自動生成し、X-Request-Id ヘッダーに付加してアプリケーションに流すっぽい。外から X-Request-Id を受けるときは、20~200文字の/[a-zA-Z0-9+=/-]/ が使えるみたい。これを満たさないヘッダーが来たときは、herokuがRequest idを自動生成して、アプリケーションに流すと。

各Webサーバーの Request Id の対応

Nginxは1.11.0から $request_id 変数が実装されて、HTTPリクエストが来るごとに16進16桁の文字列を生成するみたい。これをnginx.conf X-Request-Id ヘッダーに付与してアプリケーションにリクエストを流すと良さそう。 Application Performance Management with NGINX Variables

Apacheにも mod_unique_id というモジュールがあって、 UNIQUE_ID 環境変数を取得することでリクエストごとのユニークなIDを取れそう。 mod_unique_id - Apache HTTP サーババージョン 2.4

UNIQUE_ID 環境変数は 112 ビット (32 ビット IP アドレス、32 ビット pid, 32 ビットタイムスタンプ、16 ビットカウンタの四つの組) をアルファベット [A-Za-z0-9@-] を用いて MIME の base64 符号化と同様の方法により符号化し、19 の文字を生成することにより作成されます。MIME の base64 のアルファベットは実際は [A-Za-z0-9+/] ですが、 + と / とは URL では特別な符号化が必要なので、あまり望ましくありません。全ての値はネットワークバイトオーダで符号化されますので、符号は違ったバイトオーダのアーキテクチャ間で比較可能です。実際の符号化の順番は: タイムスタンプ、IP アドレス、pid, カウンタです。この順には目的がありますが、アプリケーションは符号を解析するべきではないことを強調しておきます。アプリケーションは符号化された UNIQUE_ID 全体を透過的なトークンとして扱うべきです。 UNIQUE_ID は他の UNIQUE_ID との等価性を調べるためだけにのみ使用できます。

Reqeust Idがうまく渡せると、色々なアプリケーションを経由するリクエストで横断的にログを見ることができてよいですね。