RailsのCurrentAttributesを使ってX-Request-IDでnginx(Webサーバ)とunicorn(アプリサーバ)のログを追えるようにする方法

https://cdn-ak.f.st-hatena.com/images/fotolife/R/Rakuma/20200908/20200908095133.png

動作確認したRailsのバージョン

6.0.3.4

よくある話として

こんにちは、ラクマのshoです。 NginxなどのWebサーバのログとunicornやpumaなどのアプリサーバのログを同じIDで検索するため、X-Request-IDをアプリサーバのログに仕込んだりします。Railsに予め用意されているconfigの設定で行うのが手軽ですが、下記のような問題があります。

TaggedLoggingの問題

TaggedLoggingを利用していれば、configファイルの以下の設定のコメントアウトを外せばX-Request-IDがログに付与されるようになっています。 config.log_tags = [ :request_id ]

X-Request-IDが123456789だとした時、↓のようなログになります。

[2020-11-XXT09:37:34+09:00] [123456789] some message 

しかし、TaggedLoggingは例えば下記のような処理がある時、backtraceをログに出力してくれません。

def XXX
rescue StandardError => e
  ~~~
  logger.error e
end

そんな時はRails 5.2から実装されたCurrentAttributesを使うことで同じことを実現できます。 CurrentAttributesの ドキュメントにはrequest_idという単語があって、こういうユースケースを想定していることが想像できますね。

ドキュメントにあったコード例

# app/models/current.rb
class Current < ActiveSupport::CurrentAttributes
  attribute :account, :user
  attribute :request_id, :user_agent, :ip_address

  resets { Time.zone = nil }

  def user=(user)
    super
    self.account = user.account
    Time.zone    = user.time_zone
  end
end

実装方法

流れとしてはmiddlewareでX-Request-IDをCurrentAttributesに設定して、formatterでそれを出力するだけです。

ActiveSupport::CurrentAttributesを継承したクラスを作成

app/models/current.rb

# frozen_string_literal: true

class Current < ActiveSupport::CurrentAttributes
  attribute :x_request_id
end

middlewareを使って作成したクラスに値をセットします、

config/initializers/x_request_id.rb

require 'current_x_request_id'

Rails.application.config.middleware.insert_after ActionDispatch::RequestId, CurrentXRequestId

ActionDispatch::RequestIdでX-Request-IDがenv['action_dispatch.request_id']にセットされます

lib/current_x_request_id.rb

# frozen_string_literal: true

class CurrentXRequestId
  def initialize(app)
    @app = app
  end

  def call(env)
    Current.x_request_id = env['action_dispatch.request_id']
    @app.call(env)
  end
end

あとはformatterでそれを出力する

lib/formatter.rb

    def call(severity, time, progname, msg)
        msg = msg2str(msg) # backtraceを出力するのに親クラス(Logger::Formatter)のメソッド(msg2str)を利用
        ~~~
        "request_id: #{Current.x_request_id} #{msg}"
        ~~~
    end

注意点として

CurrentAttributesはとても強力な仕組みですが、使う際はよく検討する必要がありそうです。注意書きの一例を載せておきます。

A word of caution: It's easy to overdo a global singleton like Current and tangle your model as a result.
Current should only be used for a few, top-level globals, like account, user, and request details.
The attributes stuck in Current should be used by more or less all actions on all requests. If you start
sticking controller-specific attributes in there, you're going to create a mess.

deepl翻訳

Currentのようなグローバルなシングルトンをやりすぎて、結果的にモデルが絡まってしまうことがあります。
Currentは、アカウント、ユーザー、リクエストの詳細などの少数のトップレベルのグローバルにのみ使用されるべきです。
Current に固定された属性は、多かれ少なかれすべてのリクエストのすべてのアクションで使用されるべきです。もし
コントローラー固有の属性を貼り付けてしまうと、混乱を招くことになります。