Railsのログ出力をフィルタする config.filter_parameters の仕組み

Ruby / Rails

ログはとても重要ですが、機微情報を出力してしまうとすると大きなリスクにつながります。Railsではconfig.filter_parametersとActiveSupport::ParameterFilterを用いてリクエストパラメータやカラムの値をフィルタリングしています。この記事では、具体的にどのようにフィルタをしているか紹介します。 Ruby on Railsのバージョンは、7.0.5で確認しています。

Railsのconfig.filter_parametersとは

Railsのconfig.filter_parametersとは、パスワード、アクセストークン、クレジットカード番号など、ログに出力したくないパラメータやActiveRecordの値をフィルタで除外するために利用します。

デフォルトの設定値はconfig/initializers/filter_parameter_logging.rbファイル内で次のように設定されています。フィルタは正規表現の大文字小文字を区別しない部分一致によって行われ、マッチした値を[FILTERED]という文字列に変換してログ出力します。 以下の設定ですと、例えばpassword、access_token、PRIVATE_KEYなどのパラメータやカラムはフィルターされます。

# config/initializers/filter_parameter_logging.rb
# Be sure to restart your server when you modify this file.

# Configure parameters to be filtered from the log file. Use this to limit dissemination of
# sensitive information. See the ActiveSupport::ParameterFilter documentation for supported
# notations and behaviors.
Rails.application.config.filter_parameters += [
  :passw, :secret, :token, :_key, :crypt, :salt, :certificate, :otp, :ssn
]

Railsのconfig.filter_parametersの挙動を確認する

フィルターの処理自体は、ActiveSupport::ParameterFilterで実装されています。
以下のサンプルコードのように、文字列、シンボル、正規表現、Procを渡すことができます。また、完全一致やネストした値に対してもフィルターをすることができます。

# /password/i にマッチする値を "[FILTERED]" に置き換える
# ※iは正規表現で大文字小文字を区別しないオプション
parameter_filter = ActiveSupport::ParameterFilter.new([:password])
parameter_filter.filter({ email: 'john@example.com', password: 'password '})
#=> {:email=>"john@example.com", :password=>"[FILTERED]"}

# /foo|bar/i にマッチする値を "[FILTERED]" に置き換える
parameter_filter = ActiveSupport::ParameterFilter.new([:foo, "bar"])
parameter_filter.filter({ foo: 'foo', bar: 'bar', baz: 'baz', foooo: 'foooo' })
#=> {:foo=>"[FILTERED]", :bar=>"[FILTERED]", :baz=>"baz", :foooo=>"[FILTERED]"}

# "pin"に完全一致と"pin_"で始まる文字列を"[FILTERED]"に置き換える
# \Aと\zは文字列の先頭と末尾を表す（=完全一致）
parameter_filter = ActiveSupport::ParameterFilter.new([/\Apin\z/, /\Apin_/])
parameter_filter.filter({ pin: '1234', pin_number: '1234', shipping_id: '1234' })
#=> {:pin=>"[FILTERED]", :pin_number=>"[FILTERED]", :shipping_id=>"1234"}

# "credit_card"にネストされた"code"を"[FILTERED]"に置き換える。他の"code"は置き換えない。
parameter_filter = ActiveSupport::ParameterFilter.new(["credit_card.code"])
parameter_filter.filter({ credit_card: { code: "xxxx" }, file: { code: "xxxx" }, code: "xxxx" })
# => {:credit_card=>{:code=>"[FILTERED]"}, :file=>{:code=>"xxxx"}, :code=>"xxxx"}

# /secret/i にマッチする値を逆順に置き換える
parameter_filter = ActiveSupport::ParameterFilter.new([-> (k, v) do
  v.reverse! if /secret/i.match?(k)
end])
parameter_filter.filter({ secret: 'secret' })
#=> {:secret=>"terces"}

より詳細はActiveSupport::ParameterFilterのドキュメントを確認ください。

特定のgemをいれるとRailsのconfig.filter_parametersがうまく反映されない

特定のGemをいれると、ActiveRecordの#inspect時にconfig.filter_parametersがうまく反映されないケースがあります。この原因の1つとして、Gem側でActiveRecordのhookを利用せずに直接呼び出してしまうことで、Rails初期化時のconfig.filter_parametersに値を設定するより前に、ActiveRecordの#filter_parameters=に空の値が設定されてしまうためです。

Rails起動時の本来の流れ

  1. Rails.application.config.filter_parametersの値をActiveRecordに設定するhookが登録される。該当コード
  2. config/initalizers/filter_parameter_logging.rbが読み込まれ、Rails.application.config.filter_parametersが設定される。
  3. ActiveRecord::Baseが読み込まれ、ActiveSupport.run_load_hooks(:active_record, Base)が実行される。該当コード
  4. 1で登録していたhookの処理が走り、Rails.application.config.filter_parametersがfilter_parameters=に設定される。
  5. ActiveRecordのfilter_parametersの値が入っているので、うまくフィルターされる。

gemが悪さをしているときの流れ

  1. Rails.application.config.filter_parametersの値をActiveRecordに設定するhookが登録される。該当コード
  2. gemが読み込まれ、gem内からActiveRecord::Baseがロードされることで、ActiveSupport.run_load_hooks(:active_record, Base)が実行される。
  3. 1で登録していたhookの処理が走り、空のRails.application.config.filter_parametersがfilter_parameters=に設定される。
  4. config/initalizers/filter_parameter_logging.rbが読み込まれ、Rails.application.config.filter_parametersが設定される。
  5. ActiveRecordのfilter_parametersの値は空になってしまうので、うまくフィルターされない。

理想的な対応としては、gem側で直接ActiveRecord::Baseを呼ぶのではなく、以下のようにフックを登録するとよいです。それが難しい場合は、暫定対応でActiveRecord::Base#filter_attributes=を任意のタイミングで呼び出すとよいかもしれません。

# Before: gemロード時にActiveRecordのhookの処理が走ってしまう
ActiveRecord::Base.include(SomeModule)

# After: Railsの初期化後にActiveRecordのhookの処理が走るようになる
ActiveSupport.on_load(:active_record) do
  ActiveRecord::Base.include(SomeModule)
end

補足：Railsの初期化順序の参考記事: https://blog.freedom-man.com/rails-initializers

Railsのconfig.filter_parametersの実装をコードリーディングする

Railsのconfig.filter_parametersのより理解を深めるために実装コードを見てみます。
config.filter_parametersの値が使われている箇所は主に3箇所で、「ActionDispatchのリクエストパラメータのフィルタ」と「ActiveRecordのカラムの値をフィルタ」と「ActionCableのリクエストのフィルタ（今回は説明を割愛）」です。

まず、フィルター設定はconfig/initializers/filter_parameter_logging.rbで Rails.application.config.filter_parametersという変数にRailsの初期化時に設定されます。

# config/initializers/filter_parameter_logging.rb
# Be sure to restart your server when you modify this file.

# Configure parameters to be filtered from the log file. Use this to limit dissemination of
# sensitive information. See the ActiveSupport::ParameterFilter documentation for supported
# notations and behaviors.
Rails.application.config.filter_parameters += [
  :passw, :secret, :token, :_key, :crypt, :salt, :certificate, :otp, :ssn
]

ActionDispatchのリクエストパラメータをフィルタする実装のコードリーディング

ActionDispatch::Http::FilterParameters内でActiveSupport::ParameterFilterを利用してリクエストパラメータ（parameters）をフィルターしています。
ActionDispatch::Http::FilterParametersモジュールはActionDispatch::Requestクラスに利用しているのでrequestはrequest.parameters（フィルターされていないリクエストパラメータ）とrequest.filtered_parameters（フィルターされたリクエストパラメータ）の両方を使い分けることができます。

# rails/actionpack/lib/action_dispatch/http/filter_parameters.rb
# https://github.com/rails/rails/blob/v7.0.5/actionpack/lib/action_dispatch/http/filter_parameters.rb
module ActionDispatch
  module Http
    module FilterParameters
      ENV_MATCH = [/RAW_POST_DATA/, "rack.request.form_vars"] # :nodoc:
      NULL_PARAM_FILTER = ActiveSupport::ParameterFilter.new # :nodoc:
      NULL_ENV_FILTER   = ActiveSupport::ParameterFilter.new ENV_MATCH # :nodoc:

       ...

      # Returns a hash of parameters with all sensitive data replaced.
      def filtered_parameters
        # 注釈: parametersにはリクエストパラメータが入っている
        @filtered_parameters ||= parameter_filter.filter(parameters)
      rescue ActionDispatch::Http::Parameters::ParseError
        @filtered_parameters = {}
      end

    private
      def parameter_filter # :doc:
        # 注釈: env["action_dispatch.parameter_filter"] は [:foo, "bar"] のような値が入っている
        parameter_filter_for fetch_header("action_dispatch.parameter_filter") {
          return NULL_PARAM_FILTER
        }
      end

      def parameter_filter_for(filters) # :doc:
        ActiveSupport::ParameterFilter.new(filters)
      end

      ...
enddd

ActionController::Instrumentationのprocess_action(*)内でrequest.filtered_parametersを利用して、ActiveSupport::Notifications.instrument("start_processing.action_controller", raw_payload)`を呼び出してイベントを作成しています。

# rails/actionpack/lib/action_controller/metal/instrumentation.rb
# https://github.com/rails/rails/blob/v7.0.5/actionpack/lib/action_controller/metal/instrumentation.rb
def process_action(*)
  ActiveSupport::ExecutionContext[:controller] = self

  raw_payload = {
    controller: self.class.name,
    action: action_name,
    request: request,
    # NOTE: raw_payloadにフィルターしたパラメータを格納
    params: request.filtered_parameters,
    headers: request.headers,
    format: request.format.ref,
    method: request.request_method,
    path: request.fullpath
  }

  # NOTE: raw_payloadを利用して"start_processing.action_controller"のイベントを作成
  ActiveSupport::Notifications.instrument("start_processing.action_controller", raw_payload)

  ActiveSupport::Notifications.instrument("process_action.action_controller", raw_payload) do |payload|
    result = super
    payload[:response] = response
    payload[:status]   = response.status
    result
  rescue => error
    payload[:status] = ActionDispatch::ExceptionWrapper.status_code_for_exception(error.class.name)
    raise
  ensure
    append_info_to_payload(payload)
  end
end

そして、Actioncontroller::LogSubscriber#start_processingでログを出力しています。

# rails/actionpack/lib/action_controller/log_subscriber.rb
# https://github.com/rails/rails/blob/v7.0.5/actionpack/lib/action_controller/log_subscriber.rb
def start_processing(event)
  return unless logger.info?

  payload = event.payload
  # NOTE: フィルターされたパラメータを利用
  # INTERNAL_PARAMS = %w(controller action format _method only_path)
  params  = payload[:params].except(*INTERNAL_PARAMS)
  format  = payload[:format]
  format  = format.to_s.upcase if format.is_a?(Symbol)
  format  = "*/*" if format.nil?

  info "Processing by #{payload[:controller]}##{payload[:action]} as #{format}"
  info "  Parameters: #{params.inspect}" unless params.empty?
end

ActiveRecordのカラムの値をフィルタする実装をコードリーディング

まず、ActiveRecord::Baseクラスが読み込まれたときに、Rails.application.config.filter_parametersをfilter_attributes=に設定してます。

# rails/activerecord/lib/active_record/railtie.rb
# https://github.com/rails/rails/blob/v7.0.5/activerecord/lib/active_record/railtie.rb#L318-L322

initializer "active_record.set_filter_attributes" do
  ActiveSupport.on_load(:active_record) do
    self.filter_attributes += Rails.application.config.filter_parameters
  end
end

filter_attributes=の実装をみると、inspect_filterを初期化しつつ、filter_attributesに値をコピーしています。
filter_attributesはinspection_filterで利用されており、中身はActiveSupport::ParameterFilterのインスタンスになっています。

# rails/activercord/lib/active_record/core.rb
# https://github.com/rails/rails/blob/v7.0.5/activerecord/lib/active_record/core.rb#L381-L396

# Specifies columns which shouldn't be exposed while calling +#inspect+.
def filter_attributes=(filter_attributes)
  @inspection_filter = nil
  @filter_attributes = filter_attributes
end

def inspection_filter # :nodoc:
  if defined?(@filter_attributes)
    @inspection_filter ||= begin
      mask = InspectionMask.new(ActiveSupport::ParameterFilter::FILTERED)
      # filter_attributesを利用して、ActiveSupport::ParameterFilterインスタンスを作成している
      ActiveSupport::ParameterFilter.new(@filter_attributes, mask: mask)
    end
  else
    superclass.inspection_filter
  end
end

その状態で、ActiveRecordで#inspectが呼ばれると、各フィールドごとにattribute_for_inspectメソッドを呼び出します。

# rails/activercord/lib/active_record/core.rb
# https://github.com/rails/rails/blob/v7.0.5/activerecord/lib/active_record/core.rb#L687-L701

# inspectの補足
# ActiveRecord#inspectでフィルタされたときの出力イメージ。tokenの値がフィルタされている。
# Customer.new(name: 'name', token: 'some-token')
#=> #<Customer:0x000000010bf999d8 id: nil, name: "name", token: "[FILTERED]", created_at: nil, updated_at: nil>
#
# Returns the contents of the record as a nicely formatted string.
def inspect
  # We check defined?(@attributes) not to issue warnings if the object is
  # allocated but not initialized.
  inspection = if defined?(@attributes) && @attributes
    self.class.attribute_names.filter_map do |name|
      if _has_attribute?(name)
        # 各カラムの値を出力するときにattribute_for_inspectが呼ばれる
        "#{name}: #{attribute_for_inspect(name)}"
      end
    end.join(", ")
  else
    "not initialized"
  end

  "#<#{self.class} #{inspection}>"
end

attribute_for_inspectでは、実際の値を取得してformat_for_inspectが呼ばれます。

# rails/activercord/lib/active_record/attribute_methods.rb
# https://github.com/rails/rails/blob/v7.0.5/activerecord/lib/active_record/attribute_methods.rb#L283-L288

def attribute_for_inspect(attr_name)
  attr_name = attr_name.to_s
  attr_name = self.class.attribute_aliases[attr_name] || attr_name
  value = _read_attribute(attr_name)
  # NOTE: 値を取得した後にformat_for_inspectが呼ばれる
  format_for_inspect(attr_name, value)
end

format_for_inspect内でinspect_filterを使ってフィルターをしています。これにより、ActiveRecordの出力内容がマスクされるようになっています。

# rails/activercord/lib/active_record/attribute_methods.rb
# https://github.com/rails/rails/blob/v7.0.5/activerecord/lib/active_record/attribute_methods.rb#L407-L421

def format_for_inspect(name, value)
  if value.nil?
    value.inspect
  else
    inspected_value = if value.is_a?(String) && value.length > 50
      "#{value[0, 50]}...".inspect
    elsif value.is_a?(Date) || value.is_a?(Time)
      %("#{value.to_fs(:inspect)}")
    else
      value.inspect
    end

    inspection_filter.filter_param(name, inspected_value)
  end
end