kakudooo docs

Rails.loggerのjson formatterを自作してみる | その③

ActionControllerのLogSubscriberの置き換え

ActionControllerのLogSubscriberを拡張して、出力されるログを構造化ログにしてみる。

Railsでは各内部フレームワーク向けにLogSubscriberが準備されている。ActionControllerについても初期化時に専用のSubscriberがattachされているため、それを参考にしながら拡張していくことにする。

LogSubscriberの拡張

config/my_log_subscriber.rb

class MyLogSubscriber < ActiveSupport::LogSubscriber
  def start_processing(event)
    payload = event.payload

    info(
      {
        message: "Processing by #{payload[:controller]}##{payload[:action]} as #{payload[:format]}",
        data: {
          controller: payload[:controller],
          action: payload[:action],
          format: payload[:format]
        }
      }
    )
  end
end

LogSubscriberの置き換え

同じログが重複して出力されてしまうのを防ぐため、拡張したLogSubscriberをattachしつつ、デフォルトでattachされているLogSubscriberはdetachする必要がある。

config/my_log_subscriber.rb

...

Rails.application.config.after_initialize do
  ActiveSupport.on_load(:action_controller) do
    ActionController::LogSubscriber.detach_from(:action_controller)
    MyLogSubscriber.attach_to :action_controller
  end
end

Rackのログイベントを構造化に対応させる

フレームワークで発生するログイベントを構造化ログとして網羅するにあたっては、LogSubscriberの置き換えに加えてミドルウェアやライブラリのloggerを置き換える必要がある。

例えば、Rackのログを構造化する場合は、ミドルウェアを置き換える必要がある。

Rails::Rack::Loggerの拡張

Rackでは、ミドルウェアにActiveSupport::LogSubscriberを継承したRails::Rack::Loggerクラスがデフォルトで指定されている。

例

{"severity":"INFO","timestamp":"2025-09-21T03:11:05.403981Z","progname":null,"message":"Started GET \"/\" for 127.0.0.1 at 2025-09-21 03:11:05 +0000"}

message属性は構造化されていない。Rails::Rack::Loggerを継承したカスタムクラスを作成して、構造化に対応させる。

config/my_rack_logger.rb

class MyRackLogger < Rails::Rack::Logger
  def call(env)
    request = ActionDispatch::Request.new(env)

    env["rails.rack_logger_tag_count"] = if logger.respond_to?(:push_tags)
      logger.push_tags(*compute_tags(request)).size
    else
      0
    end

    custom_call_app(request, env)
  end

  private

    def custom_call_app(request, env)
      logger_tag_pop_count = env["rails.rack_logger_tag_count"]

      instrumenter = ActiveSupport::Notifications.instrumenter
      handle = instrumenter.build_handle("request.action_dispatch", { request: request })
      handle.start

      # Hashを渡す形式に変更する
      logger.info({
        message: started_request_message(request),
        data: {
          request_method: request.raw_request_method,
          filtered_path: request.filtered_path,
          remote_ip: request.remote_ip,
          timestamp: Time.now.to_i
        }
      })

      status, headers, body = response = @app.call(env)
      body = ::Rack::BodyProxy.new(body) { finish_request_instrumentation(handle, logger_tag_pop_count) }

      if response.frozen?
        [ status, headers, body ]
      else
        response[2] = body
        response
      end
    rescue Exception
      finish_request_instrumentation(handle, logger_tag_pop_count)
      raise
    end
end

ミドルウェアスタックの置き換え

Rackミドルウェアの場合は、config.middleware.swapで置き換えることができる。

config/my_rack_logger.rb

...
Rails.configuration.middleware.swap Rails::Rack::Logger, MyRackLogger, Rails.configuration.log_tags

結果

{"severity":"INFO","timestamp":"2025-09-21T04:43:48.520450Z","progname":null,"message":"Started GET \"/\" for 127.0.0.1 at 2025-09-21 04:43:48 +0000","data":{"request_method":"GET","filtered_path":"/","remote_ip":"127.0.0.1","timestamp":1758429828}}

参考