Railsのロギングをマスターする:デバッグからプロアクティブなアラートまで

ログの必要性は、いちばん必要とする瞬間になって初めて気づくものです。しかし、アプリケーションが壊れ、ユーザーからの苦情が殺到し、どう対処すればいいのか見当もつかない——そんなときにログメッセージを追加しても、すでに手遅れです。

良いログは、その投資額の十倍の価値を返してくれます。厄介なバグの診断が格段に楽になるだけでなく、正しくログを実装していれば、ユーザーが気づく前に問題を検知してアラートを出すことさえ可能です。では、「正しくログを書く」とはどういうことなのでしょうか?

ロギングは始めるのは簡単ですが、習得するのは難しいものです。この記事では、Railsアプリケーションのログを最大限に活用する方法を詳しく見ていきます。

Railsにおけるロギング

まずは基本からおさらいしましょう。新しいRailsアプリケーションを作成すると、ロギングは最初から設定済みです。RailsはActiveSupport::Loggerの新しいインスタンスを初期化し、アプリケーション内のどこからでも利用できるようにしてくれます。

Railsのロガーは標準出力またはlog/<environment>.logに書き込みを行い、明示的に記述したログメッセージに加えて、受信したリクエストや実行されたクエリも自動的に記録します。

Railsのログには多数の設定方法があり、公式ドキュメントに優れた解説があります。

ログを最大限に活用するために、特に重要なのが「ログレベルの設定」と「ログフォーマット」です。

ただし、その前に、そもそもなぜログを書くべきなのかについて話しましょう。

良いログと悪いログ

ログの目的は、システムで発生したイベントを通知し、それに対して対応できるようにすることです。たとえば、エラーが発生したとき、ログメッセージは理解できる形でその事実を伝えるべきです。

ログメッセージをどれだけ理解できるかは、その説明的性質と文脈性にかかっています。説明的なログメッセージは、何が起きたかに関する関連情報を提供します。文脈的なログメッセージには、メッセージが書き込まれた時点のシステムの状態に関する情報が含まれています。

両方が必要な理由を、簡単な例で考えてみましょう。以下は、ユーザーがリクエストを行った際に外部APIを呼び出し、そのレスポンスを返すコードです。

ここで、顧客から問題の報告を受け、ログを調査する場面を想像してください。目にするのは、おそらく次のようなものです。

これらのログメッセージには多少の情報はありますが、十分とは言えません。顧客が報告したエラーの原因を突き止める手がかりは、ほとんど得られません。これらのメッセージには説明的性質も文脈も欠けており、単なるノイズです。どう改善すればよいのでしょうか?

Railsのログレベル

Railsのデフォルトロガーは、DEBUG、INFO、WARN、ERRORというログレベルを提供しています。これらを使うことで、ログメッセージを重要度ごとに分類できます。これはログのフィルタリングに役立つだけでなく、ある程度の文脈も与えてくれます。

どの場面でどのログレベルを使うべきか判断するのは難しいものです。ここでいくつかの経験則を紹介します。

• DEBUG: システム内部で行われている動作に関する詳細情報に使用します。メソッドの開始・終了時や、デバッグ時に価値をもたらしそうな箇所でdebugステートメントを使うとよいでしょう。
• INFO: システムが状態を変えたときや、何らかの関連イベントが発生したときに使用します。RailsアプリケーションでよくあるINFOメッセージの例としては、受信したリクエスト、外部APIへの送信リクエスト、ジョブの開始・終了などが挙げられます。
• WARN: 予期しないことが起こったことを示すために使用します。まだ問題にはなっていません(アプリケーションが処理できているため)が、繰り返し発生するようなら注意が必要かもしれません。
• ERROR: エラーが発生したときに使用します。エラーは無効なアプリケーションの状態であり、できるだけ早く解決しなければなりません。

アプリケーションが出力するログメッセージの種類は、各環境ファイルを編集することで変更できます。通常、Railsは本番環境ではDEBUGメッセージを破棄しますが、それも変更可能です。

それでは、上記のログレベルの指針をサンプルコードに適用してみましょう。

これでデバッグ時には、WARNやERRORメッセージを調べることで問題の根本原因を特定しやすくなりました。残念ながら、ログメッセージ自体の説明的性質はまだ向上していません。

説明的なログメッセージ

説明的なログメッセージは、解釈の余地を残しません。読み手が何が起きたのか即座に把握できるのに必要な詳細を提供します。

'An error occurred'(エラーが発生しました)のようなメッセージを読むと、どんなエラーなのか分からず戸惑ってしまいます。ログメッセージを書くときは、こうした混乱を避けたいものです。説明的なログメッセージを書くうえで最も重要なのは、ログの読み手の立場に立つことです。読み手はあなたのログから必要な情報をすべて得られるでしょうか?

そこで、'An error occurred'というメッセージを、エラーメッセージ本体を含む形に変更してみましょう。

かなり改善されました。続いて、サンプル内の他のログメッセージも確認しましょう。'Method entered'はどのメソッドが呼ばれたのか分からず、'Response success'は実際のレスポンスが省略され、'Response failure'は失敗の内容について何も教えてくれません。これらも変更しましょう。

注: ログで文字列補間を行う際にブロック構文を使用していることにお気づきでしょうか。ブロック構文を使うと、アプリケーションのログレベルがログメッセージのレベルより高い場合に、不要な計算を回避できます。たとえば、log.debug("Some #{concatenation}")は常に文字列連結を実行しますが、log.debug { "Some #{concatenation}" }はログレベルがdebugに設定されている場合にのみ実行されます。

ログは格段に読みやすくなりました。各ログメッセージが何を意味しているのか、ほぼ疑問の余地はありません。

ログメッセージへのさらなる文脈の追加

新しいログメッセージは、何が起きたのかを明確に示してくれます。これはシンプルな例なので、なぜそういうことが起きたのかもよく分かります。しかし現実には、そう単純ではないのが普通です。

メッセージが書き込まれた状況に関する追加情報を提供することは、デバッグに大きく役立ちます。

たとえば、リクエストやレスポンスをログに記録する際には、誰がリクエストを行ったのかが分かると便利でしょう。また、エラーにはスタックトレースを添えておくと、エラーがなぜ発生したのかについて追加の情報を収集できます。

注: お気づきかもしれませんが、Railsのデフォルトロガーで文脈情報付きのログメッセージを作成するのは、やや煩雑になりがちです。幸い、OugaiやMrLogaLogaといったカスタムロガーを使えば、この作業がぐっと楽になります。

構造化ロギング

ログを人間にとって読みやすいものにできたら、次のステップに進みましょう。今度は、モニタリングやデータ分析に活用できるよう、機械にとって読みやすいログにする必要があります。

筆者のお気に入りの形式はJSONですが、使用するツールによっては、Logstashなど別のログ形式の方が好ましい場合もあります。カスタムログフォーマッターを作成することで、ログメッセージの形式を変更できます。

カスタムフォーマッターを自作する代わりに、カスタムログフォーマッターを提供する多くのgemのいずれかを使うこともできます。おすすめはLogrageです。すぐに使えるフォーマットを提供するだけでなく、Railsのやや冗長なリクエストログを整理して、はるかに読みやすくしてくれます。

AppSignalによるRailsのロギング

ログを見やすく整えられたら、アクセスしやすくするのも良いアイデアです。わざわざマシンにSSH接続して、tailやgrepでログを調べたくはないですよね?

幸い、AppSignalは最近、ベータ版としてロギング機能をリリースしました!これにより、AppSignalのWebインターフェース上でRailsのログを直接確認・分析できます。

左側のメニューにある「Logging」タブから、ロギングのベータ版にアクセスできます。

Rubyロギングのドキュメントの手順に従えば、以下のコードをconfig/environment.rbファイルのinitializationより前に記述することで、RailsロガーがAppSignal::Loggerクラスを使用するように設定できます。

JSON形式やLogrageによる構造化ログの取り込みにも対応しています。

すべての設定が完了すると、RailsのログがAppSignalに表示されるようになります!

ロギングとエラーレポーティング

この記事はAppSignalのブログで読んでいるわけですから、こんな疑問を持つかもしれません。「すでに優れたエラーレポーティングプラットフォームを使っているなら、ロギングなんて気にする必要があるの?」

良い質問です。エラートラッキングツールは、アプリケーションエラーに関する詳細な情報を提供します。あらゆるアプリケーションエラーの完全なスタックトレースをキャプチャし、豊富な文脈情報を最初から提供してくれます。

しかしながら、多くのツールはエラー以外のイベントもキャプチャできますが、任意の量のメッセージを送信するのは一般的に非現実的です。適切に書かれたログが提供する詳細で履歴的な情報を置き換えることはできません。

実際には、適切に書かれたログはエラートラッキングツールを補完し、支えるものです。両方を使うのがよいでしょう。

まとめ

この記事では、ログを最大限に活用する方法を見てきました。Railsでのロギングは簡単に始められますが、有用なログを書くのは難しいことが分かりました。

説明的性質や文脈に欠けるログは、ディスク容量を消費するだけで、ほとんど価値をもたらしません。一方、適切なログレベルを使い、読み手に必要な情報を提供するログは、大きな資産になります。

優れたログメッセージの書き方をマスターしたら、さらに一歩進んで、ログ分析やフィルタリングが容易になる形式でログを出力できるようにしましょう。

また、AppSignalの新しいロギング機能を使えば、ログに簡単にアクセスできることも紹介しました。最後に、ログはエラートラッキングツールを置き換えるのではなく、補完するものであるべき点にも触れました。

それでは、Happy Logging!

P.S. Ruby Magicの記事を公開と同時にお読みになりたい方は、Ruby Magicニュースレターを購読すれば、記事を見逃すことはありません!

Hans-Jörg Schnedlitz(ハンス=ヨルク・シュネトリッツ)

ゲスト執筆者のHansは、オーストリア・ウィーン在住のRailsエンジニアです。時間の大半をコーディングやコーディング関連の読書に費やし、自身のブログで執筆することもあります。画面の前に座っていないときは、山登りをしていることでしょう。

Hans-Jörg Schnedlitzの記事一覧