Ruby on Railsのログを良い感じに構造化する

はじめに

Hubble Advent Calendar 2025の 2 日目の記事を少し書き直しています。

これまでの Rails で構造化ログを自動で吐き出させるには少し苦労していましたが、Rails 8 系ではログの構造化がしやすくなるようです（詳しくはおググりあれ！）が、今まではログを構造化するのに少し労力がかかりました。2 年前くらいまでは Hubble 社のログは特に構造化などはされていませんでしたが、Rails.logger.levelを Hash の引数と一緒に呼ぶだけで構造化ログが出力されると嬉しいなと思っていました。

# こんな感じでログが吐き出されると嬉しい
Rails.logger.info({ user_id: 1, org_id: 100 })
# => "{\"user_id\":1,\"org_id\":100}"

実際に試行錯誤しながら（ほぼ）理想の構造化ログを導入してみたので、今回はその実装の内部を紹介してみようと思います。

なぜログを「構造化」すると嬉しいのか？

今回は Ruby on Rails アプリから吐き出すログに焦点を当てますが、どんなログであっても構造化することには大きな意義があると考えています。なぜなら、Datadog といった監視ツールとの親和性が高いからです。親和性が高いということはどういうことなのでしょうか？

Datadog を使って、実際の画面を見ながら説明して行きます。

ポイントは赤枠で囲ってある「Fields & Attributes」部分です。この画像のように構造化ログを Datadog へ送信すると、良い感じに attributes として表示してくれます。

また、DataDog の場合（他の監視ツールでも概ね同様かと思います）は、この Attributes をキーにしてログを「フィルタリング」することができます。

赤枠で囲ってある箇所がログを探すためのプロンプトですが、@action:pdfと入力することにより、Rails の action でログを上手く「フィルタリング」できています。

つまり、この Attributes で user_id、controller、action や操作対象オブジェクトの id などを用いて「いつ、誰が、何に対して、どんな操作をした」といったログの捜索をより正確な表現で絞り込むことが可能であることを意味します。

他の監視ツールなどでも同様の操作ができるはずです。私の前職では GCP の Cloud Logging で同様に構造化ログ使用していました。（だったはず、、、、、）

え？それだけですか？

はい、それだけです。 ですが、このありがたみを知るために、同様の条件を構造化されていないログから検索してみると仮定してみてください。もしくは今、自身が所属されている開発チームのログが構造化されていない場合は日々の開発を思い起こしてください。

この場合、プロンプトにどのように入力しますか？ 仮にuser_id = 100であると仮定しましょう。100 という数字を素直に打ち込めば、use_id = 100に関するログだけが素早く正確に出力されるでしょうか？恐らくそうではないはずです。user_id 100とちょっと工夫して検索したところで、user_id = 1001に関する情報などが出力されたりします。

本番に障害が起きた際にuser_id = 100のユーザーの操作を追いかけたい場合に、ほとんどがノイズだらけのログの中から関連するログのみを早く正確に取得することが本当にできますか？一刻も早く問題を収束させたい焦りと不正確でノイズだらけのログの中で？

確かにログを出力する際の規約を決めるというのは一つの手っ取り早い解決策です。 ただ、果たして開発者は必ずuser_id = 100と記述してくれますか？user_id=100と記述するのは NG ですか？

「検索」ではなく「フィルタリング」を

個人的な思想ですが 「検索」 を信用してはなりません。「検索」をするためには、要素を index したりなどの労力がかかる割にはやや信憑性を欠きます。 Google 検索はあなたの思い通りの検索結果を美しく正確に全て出力してくれますか？（もちろん、Google は偉大なプロダクトですよ）顧客から「どんな操作が何回実行された結果でこうなりました？」という質問に対して、検索しただけのログで果たして自信を持って答えられますか？

賢い我々は 「フィルタリング」 をしましょう。あらかじめ決まったフォーマットで監視ツールに送ることをコミットする代わりに、フィルタリングによって、より正確に全ての目当てのログを探し出すのです。

それに、ゴチャゴチャと雑多なログが出てくるよりも、json フォーマットで出力される方が美しい、要は美意識です。

じゃあ、Lograge 使うか

github.com

構造化ログ = Logrageという図式を Ruby on Rails 界隈では感じますが（私だけですか？）、Lograge では構造化対象になるのはリクエストログのみです。

qiita.com

ですが、我々はリクエストログ以外にも重要な処理の内部状態がどうなっていたのかをログで吐き出したいという欲求も持っています。しかも正確に絞り込みたい、それもできるだけラクして。

じゃあ、こんな感じにしてみるとどうでしょうか？

• リクエストログ
  • Lograge
• それ以外のログ
  • 別の仕組みで何とかする？

ただこれは少し冗長な感じがします。「それ以外のログ」が何とかできるのであれば、リクエストログも同じ仕組みを使えばいいだけです。できるだけ、色んなログが一括で構造化されるようになると嬉しいです。我々は KISS の原則を忘れてはならず、DRY にできるところは DRY にしましょう。

logger に求める要件

ここで一度、ログに対する要望を整理してみます。

• リクエストログには何も意識しなくても必要なメタデータを搭載しておきたい
• trace も意識したくない（trace についての参考: https://newrelic.com/jp/blog/how-to-relic/metrics-events-logs-and-traces）
• Rails.logger.level({ user_id: 100 }.to_json)は冗長なので、Rails.logger.level({ user_id: 100 })とかでいい感じに構造化ログが出てきて欲しい
• 例外を rescue した際にRails.logger.error(e)とアッサリ記述されただけの箇所が多いのでだけで、そういう箇所では backtrace もいい感じにログ出力しておきたい
• ただ別に無理に構造化しなくていい時もあるので、logger の引数をただの文字列だけで渡す怠惰な瞬間も残しておいてほしい（人間が読むための従来のようなログも搭載したい）

色々と調査した結果ではこれらの要望を叶えるためには、自前で実装をするしかないという結論に至りました。 そんな技術記事がないかなとインターネット上をガサガサ探すと良い感じの記事が出てきました。

探し出した解決策

インターネットをガサガサした結果、探し出した答えがこちらです。詳しくは上記の資料を確認してください。

kaigionrails.org

やりたいことは 「Ruby on Rails のオリジナルの logger を少し改造して、思った通りの構造化ログが何も意識しなくても出力されるようにしたい」 です。

そのヒントとして、上記の資料中では 「Lograge の基本戦略」 として以下のような記載があります。

• Rails が出力する Request 関連のログを無効にする
• 自前の LogSubscriber を attach してログ出力

この「Lograge の基本戦略」と同様のことをすれば、Lograge と同じように「ログを中継して思った通りのフォーマッターで出力」することができそうです。

このスライドには有り難いことに、実装の例も示していただいています。これらの情報を元に実装してみましょう。

実際の logger 実装の中身

では、具体的に logger 改造のコードを見ていきましょう。

基底コントローラーとして定義したApplicationControllerのappend_info_to_payloadメソッドを用いることによって、リクエストログの出力時に良い感じに payload を上乗せしましょう。

append_info_to_payloadは、リクエストに情報を載せるために使用されるメソッドですね。

ちなみに、before_actionで@cur_itemや@cur_userなどに値を入れる処理を書くことがよくあるのですが、そういった値があれば勝手にログに含めるようにします。

# app/controllers/application_controller.rb

class ApplicationController < ActionController::Base
    # ...
    def append_info_to_payload(payload)
        super

        # リクエストログに含めたいメタデータ系をセット
        payload[:referer] = request.referer
        payload[:params] = request.params

        # 誰が何に対してといった情報が取得できれば自動でログに載せる
        cur_user = @cur_user || @current_user || nil
        if cur_user.present? && cur_user.is_a?(User)
            payload[:cur_user_id] = cur_user.id
        end

        return unless @cur_item.present? && @cur_item.is_a?(Item)
        payload[:cur_item_id] = @cur_item.id
        # ...
    end
    # ...
end

また、ログをどのように出力するのかを定義するフォーマッターを実装します。Rails.logger.level(msg)のmsgが、どのクラスのインスタンスかによって処理を変えています。

# lib/json_log_formatter.rb

require "ddtrace"

class JsonLogFormatter < Logger::Formatter
  def call(severity, time, _prog_name, msg)
    correlation = Datadog::Tracing.correlation

    # Datadogでtraceさせるためにtrace_idを入れておく
    # 他の監視ツールでも同様のtraceの仕組みがあるはずなので組み込む
    log = {
      trace_id: correlation.trace_id,
      span_id: correlation.span_id,
      time: time.iso8601(6),
      level: severity
    }.compact

    # loggerの引数によって、msgの扱いを分岐させる
    #
    # String -> jsonログのmessageプロパティに引き渡す
    # Hash -> デフォルトで設定している項目に追加してjson化する
    # Exception -> messageとtraceをいい感じにセットする
    # それ以外 -> String化してmessageプロパティに引き渡す
    if msg.instance_of?(String)
      log[:message] = msg
    elsif msg.instance_of?(Hash)
      log.merge!(msg)
    elsif msg.instance_of?(Exception)
      log[:message] = msg.message
      log[:backtrace] = msg.backtrace
    else
      log[:message] = msg.to_s
    end

    # ログをjson化する
    "#{JSON.generate(log, ascii_only: false)}\n"
  end
end

そのフォーマッターを使うように設定してみましょう。同時に Ruby on Rails アプリ内の logger の基本的な設定も同時にここで行います。

# config/environments/application.rb

require "#{Dir.pwd}/lib/json_log_formatter"
# ...
# logの設定
config.logger = ActiveSupport::Logger.new(STDOUT)
config.logger.formatter = JsonLogFormatter.new
config.logger.level = 0
config.log_level = :info
# ...

次に LogSubscriber です。

ここではApplicationController#append_info_to_payloadで引き受けたプロパティを再度セットします。（もうちょっと上手いやり方がありそうな気がするので、知っていれば教えてください）

また、リクエストログに関しては、これまではどんなステータスであろうと、ずっとinfoレベルでログが出ていました。しかし、リクエストログのレベルをここで決めちゃって、今後はより正確なログレベルで出力されるようにしましょう。

# lib/custom_log_subscriber.rb

# frozen_string_literal: true

class CustomLogSubscriber < ActiveSupport::LogSubscriber
  def process_action(event)
    # ApplicationController#append_info_to_payloadの内容をここで拾う
    log_message = {
      method: event.payload[:method],
      db: event.payload.key?(:db_runtime) ? event.payload[:db_runtime].to_f.round(2) : nil,
      # ...
      user_id: event.payload[:cur_user_id],
      org_id: event.payload[:cur_org_id],
      item_id: event.payload[:cur_item_id],
    }.compact

    # リクエストログに関してはここでlevelを決めてしまう
    level = case event.payload[:status].to_i
            when 500..599
              Logger::ERROR
            when 400..499
              Logger::WARN
            when 100..399
              Logger::INFO
            else
              logger.level
            end

    logger.add(level, log_message)
  end
end

CustomLogSubscriber.attach_to :action_controller

次に独自 logger を定義します。これは「lograge の次を考える」の資料でも出てきたことを、そのまま記述しています。

# lib/custom_logger.rb

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

  def call(env)
    @app.call(env)
  ensure
    ActiveSupport::LogSubscriber.flush_all!
  end
end

controller の logger を先ほどの独自 logger に挿げ替えてあげましょう。

# config/initializers/log_settings.rb

require "#{Dir.pwd}/lib/custom_logger"
require "#{Dir.pwd}/lib/custom_log_subscriber"
require "#{Dir.pwd}/lib/json_log_formatter"
require "action_controller/log_subscriber"

ActionController::LogSubscriber.detach_from :action_controller
Rails.application.middleware.swap(Rails::Rack::Logger, CustomLogger)

これで実装は完了です！

ドキュメントの記載

最後に logger の使い方をどこかに書き記しておきましょう。せっかく、良い感じに logger を改造したのに、使われないのでは悲しいので。

私は以下のように Notion に記載をしました。

まとめ

現代のシステム開発においては Rails アプリケーションに限らず、各所から出てくるログは構造化しておくとより良いと考えています。人間が読むためのログもその中に入れられますし、まさに機械と人間にとって win-win と言えるかと思います。

ただ、Rails 8 系ではデフォルトでログを構造化できると聞いたので、この記事はすぐに不要になるかもしれませんが、知見を共有すること自体は悪いことではないと思うので悪しからず。詳しくはこちらから。

railsguides.jp