はじめに
Hubbleでバックエンドエンジニアをしている @alstrocrack です。
Hubble Advent Calendar 2025の2日目の記事です。
株式会社Hubbleは、契約書管理クラウド HubbleというSaaSを開発しており、HubbleはRuby on Railsで開発しています。Hubbleは今年、Kaigi on Rails 2025でRuby Sponsorをしていました。そこで私、漆島とCTOの藤井（Sponsor LT）とTech Leadの中島（全問正解率約3%: RubyKaigiで出題したやりがちな危険コード5選）の3人が登壇していたので、Hubbleを知っている方もいらっしゃるのではないでしょうか。
それはさておき、HubbleはRuby on 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といった監視ツールとの親和性が高いからです。親和性が高いということはどういうことなのでしょうか？
Hubbleでは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使うか
構造化ログ = Logrageという図式をRuby on Rails界隈では感じますが（私だけですか？）、Logrageでは構造化対象になるのはリクエストログのみです。
ですが、我々はリクエストログ以外にも重要な処理の内部状態がどうなっていたのかをログで吐き出したいという欲求も持っています。しかも正確に絞り込みたい、それもできるだけラクして。
じゃあ、こんな感じにしてみるとどうでしょうか？
- リクエストログ
- 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の引数をただの文字列だけで渡す怠惰な瞬間も残しておいてほしい（人間が読むための従来のようなログも搭載したい）
色々と調査した結果ではこれらの要望を叶えるためには、自前で実装をするしかないという結論に至りました。 そんな技術記事がないかなとインターネット上をガサガサ探すと良い感じの記事が出てきました。
探し出した解決策
インターネットをガサガサした結果、探し出した答えがこちらです。
詳しくは上記の資料を確認してください。
やりたいことは 「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などに値を入れる処理を書くことがよくあるのですが、そういった値があれば勝手にログに含めるようにします。
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が、どのクラスのインスタンスかによって処理を変えています。
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の基本的な設定も同時にここで行います。
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レベルでログが出ていました。しかし、リクエストログのレベルをここで決めちゃって、今後はより正確なログレベルで出力されるようにしましょう。
# frozen_string_literal: true
class HubbleLogSubscriber < 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
HubbleLogSubscriber.attach_to :action_controller
次に独自loggerを定義します。これは「logrageの次を考える」の資料でも出てきたことを、そのまま記述しています。
class HubbleLogger
def initialize(app)
@app = app
end
def call(env)
@app.call(env)
ensure
ActiveSupport::LogSubscriber.flush_all!
end
end
controllerのloggerを先ほどの独自loggerに挿げ替えてあげましょう。
require "#{Dir.pwd}/lib/hubble_logger"
require "#{Dir.pwd}/lib/hubble_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, HubbleLogger)
これで実装は完了です！
ドキュメントの記載
最後にloggerの使い方をどこかに書き記しておきましょう。せっかく、良い感じにloggerを改造したのに、使われないのでは悲しいので。
私は以下のようにNotionに記載をしました。これはHubbleにjoinしていただいたBackendエンジニアの方々に展開する資料の一部になっています。
まとめ
現代のシステム開発においてはRailsアプリケーションに限らず、各所から出てくるログは構造化しておくとより良いと考えています。人間が読むためのログもその中に入れられますし、まさに機械と人間にとってwin-winと言えるかと思います。
ただ、Rails 8系ではデフォルトでログを構造化できると聞いたので、この記事はすぐに不要になるかもしれませんが、知見を共有すること自体は悪いことではないと思うので悪しからず。詳しくはこちらから。
明日は @krabbe16 さんです！