RailsのTaggedLoggingでログを読みやすく整理する方法

奇妙で一見解決不能なバグに遭遇したとき、ロギングの改善こそが最善の一手となることがあります。優れたロギングは、さまざまな種類のバグを検出・修正するための最も手軽な手段です。十分な情報をログに出力すれば、リクエスト処理の中でデータがどのように変化していくかを目で追えますし、他サービスへの呼び出しとそのレスポンスも調査できます。実際、私自身もデバッガでは解決できなかった最難関のバグを、ロギングのおかげで修正できた経験があります。

しかし、ログを出しすぎると、ログファイルはたちまち読めない無意味なメッセージの山になってしまいます。膨大なデータの中から、本当に必要な情報だけをどう切り出せばよいのでしょうか?後からフィルタリングしやすい形でメッセージを出力するには、どうすればいいのでしょうか?

ログメッセージにタグを付ける

RailsにはTaggedLoggingが組み込まれており、関連するログメッセージを素早く分類できます。ロガーにタグを付けると、メッセージの先頭にマーカーが表示されるようになります。たとえば、次のようなログが出力されていたとします:

Finding people...
  Person Load (0.3ms)  SELECT "people".* FROM "people"
Found 0 people!

Railsのロガーにタグを付けると:

logger.tagged("People") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

出力はこのようになります:

[People] Finding people...
[People]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[People] Found 0 people!

これで、関心事項の異なるログメッセージが、見た目でもはっきり区別できるようになります。

タグ付きロガーの具体的な活用例

ロギングの頻度が増え、より複雑な内容を出力するようになると、タグによってメッセージが格段に明確になる場面に自然と気づくはずです。特にタグ付けが効果を発揮するケースがいくつかあります。私はそういった箇所には、すぐにタグを付けるようにしています。

外部APIへのリクエストを記録する

他のAPIに対して行うリクエストをログに残せます:

logger.tagged("GitHub API") do
  uri = URI("https://api.github.com/repos/rails/rails/tags")

  logger.info { "Fetching #{uri}" }
  tags = JSON.parse(Net::HTTP.get(uri))
  logger.info { "First tag: #{tags.first["name"]}" }
end

[GitHub API] Fetching https://api.github.com/repos/rails/rails/tags
[GitHub API] First tag: v4.2.4.rc1

こうすることで、アプリケーションがいつ・どのようにそのAPIと通信しているのかをひと目で把握できます。

(Faradayのミドルウェアと組み合わせたり、Gateway経由でのみサーバーと通信する構成にしたりすると、特に効果的です)。

バックグラウンドジョブを追跡する

バックグラウンドジョブもタグ付きロギングと相性抜群です:

require "active_support/tagged_logging"

Resque.logger = ActiveSupport::TaggedLogging.new(Resque.logger)

module LoggedJob
  def around_perform_log_job(*args)
    logger.tagged(name) do
      logger.info { "Performing #{name} with #{args.inspect}" }
      yield
    end
  end
end

class MyJob
  extend LoggedJob

  def self.perform(*args)
    ...
  end
end

これで、LoggedJobをextendしたすべてのジョブは、そのログメッセージにジョブのクラス名が自動的にタグとして付与されるようになります。複数のジョブが並行して動いている環境でも、どのジョブが出力したログなのか一目瞭然です。

ユーザーIDでタグ付けする

ログイン中のユーザーがいるなら、ユーザーIDをタグとして付けるのも有効です:

logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

[user-123] Finding people...
[user-123]   Person Load (0.3ms)  SELECT "people".* FROM "people"
[user-123] Found 0 people!

特定のユーザーから報告された問題を調査するとき、そのユーザーの操作に関連するログだけを簡単に抽出できるようになります。

config.log_tagsで自動タグ付け

さらに、config/environments/production.rb(またはdevelopment.rb)に1行追加するだけで、Railsが自動的にメッセージへタグを付けてくれます:

config.log_tags = [ :subdomain, :uuid ]

log_tagsには、Railsのすべてのログエントリの先頭に表示したいタグを列挙します。各シンボルはActionDispatch::Requestのメソッドに対応しており、:uuidならrequest.uuidを意味します。

requestオブジェクトを受け取るProcを渡すことも可能です:

config.log_tags = [ :subdomain, :uuid, lambda { |request| request.headers["User-Agent"] } ]

ただし、この書き方を実際のコードで見かけることはあまりありません。

まとめ:タグでログを「追跡可能」にする

こうしたデフォルトのタグは非常に便利です。uuidを使えば、1つのリクエスト内で発生したすべてのログエントリを時系列に紐づけられますし、サーバー側でセッションを管理しているならセッションIDも大きな手がかりになります。これらのタグと十分な量のログメッセージがあれば、アプリケーション内のかなり複雑な処理経路でも追跡できます。そして通常、厄介なバグの原因を突き止めるには、まさにそれが必要になるのです。

あなたのアプリケーションではRailsのロガーをどれくらい活用していますか?タグ付きロギングを試したことはありますか?まだなら、ぜひ使えそうな箇所を探してみてください。まずはユーザーの操作にタグを付けるところから始めるのがおすすめです。次に複雑な多段階バグのデバッグに迫られたとき、きっと役立つはずです。

ロギングやその他のデバッグ手法についてさらに学びたい方のために、書籍Practicing Railsでは章丸ごとを「アプリ開発で遭遇するエラーの発見と修正」に充てています。第1章はこちらから無料で入手できます。