「Webアプリケーションのログレベルについて考える」の編集履歴(バックアップ)一覧に戻る

Webアプリケーションのログレベルについて考える - (2010/01/15 (金) 11:33:53) の編集履歴(バックアップ)


Java開発の次のデファクトになると思われるSLF4Jのログレベルの説明を見てみます。

   * FATAL - アプリケーションを異常終了させるような非常に深刻なイベントを指定します。
   * ERROR - アプリケーションの稼働が継続できる程度のエラーを指定します。
   * WARN - 潜在的に害を及ぼすような状況を指定します。
   * INFO - アプリケーションの進捗の概要が分かるメッセージを指定します。
   * DEBUG - アプリケーションをデバッグすのに役立つ詳細なイベント情報を指定します。
   * TRACE - DEBUGより詳細なイベント情報を指定します。

エラーに関するログレベルとそれ以外で分けてみます。

   * エラーに関するログレベル - FATAL、ERROR、WARN
   * それ以外 - INFO、DEBUG、TRACE

次に、トランザクションごと、WEBアプリケーションでいうとアクセスごとに出力させるログレベルとそれ以外に分けてみます。

   * アクセスごと - DEBUG、TRACE
   * それ以外 - FATAL、ERROR、WARN、INFO

何故アクセスごとに出力させるログレベルとそうでないログレベルを分けるのか

ログ出力にはそれなりにコストがかかるのでアプリケーションを本番環境へでデプロイした際はアクセスごとのログ出力をさせないためです。またアクセスごとにDEBUGレベル以上のログを出力していると、アプリケーションに問題が起こった際に本当に見たいFATAL〜WARNレベルのログが発見しづらいというのも理由のひとつです。

DEBUGとTRACE

上記に書いたように、アクセスごとのログを出力するのはDEBUGとTRACEですが、この2つの使い分けはどのようにすればいいのでしょうか。

この2つのログレベルを分ける基準は単純に出力するログの粒度でいいと思います。StrutsやLiftなどのフレームワークを使っているならば、ユーザからのリクエストをフレームワークが提供する構造のどの経路を通っているか分かる程度の粒度のログをDEBUGに、単なる変数のダンプログを TRACEにという具合です。質の良いフレームワークならばデフォルトでその経路をDEBUBレベルで出力してくれるので、フレームワーク使用者が自分で出力しなくてはいけない情報はあまりないと思います。Liftはまだ発展途上ということもあり、フレームワークが出力してくれるログが少ないので、 RewriteRequestした際や、Snippetのメソッドがコールされたときなどに適宜ログを出力するようにすれば良いでしょう。

TRACEレベルのログについては、SLF4JのFAQに興味深い記述があります。

ここでは、何故SLF4Jのバージョン1.4.0にしかTRACEレベルのログが紹介されていないのか?という質問に対して、様々な議論があるもののいくつかの理由でTRACEレベルを推奨しないと解答しています。詳細は記事を読んでもらうとして、内容を意訳するならば、TRACEログに出力するあまりに詳細なログはその利点よりも欠点が上回るということです。私もその意見に同意しますし、FAQの解答にTRACEログを推奨しない理由を付け加えるならば、あまりにも多いログ出力の記述はコードの可読性を著しく下げることになるからです。またFAQの解答ではTRACEレベルのログ出力と同等のことはDEBUGレベルの設定を適宜することで代替できるとも書いてあります。

INFO

INFOレベルのログは本番環境下で唯一エラー以外のログを出力します。ここにはアクセスごとのログを記述するのではなく、アプリケーションの状態を表すようなログを出力します。具体的には、

   * アプリケーションのモード。アプリケーションによってはモードを切り替える事で、本番環境と開発環境など環境ごとの設定をしているものも少なくないと思うので、どのモードで起動されているかどうかを出力します。
   * 現在のログレベル。ログレベルが実行時に変更されたときにも変更後のログレベルを出力します。
   * 接続しているDBの情報。どのDBに接続しているかどうかをURLとして出力します。コネクションプーリングをしている場合などは、プールしているコネクション数なども適宜出力します。コネクションの生成、破棄のサイクルが速いのアプリケーションの場合は出力しない方がいいでしょう。
   * 生存期間の長いキャッシュの生成情報。半日以上キャッシュされるようなデータが生成された際に出力します。ユーザごとにキャッシュされるようなデータは含みません。

などです。

考えれば他にもありそうなのですが、重要なのは大量のログが生成されそうな情報は出力しないというこです。また、これらの情報はJMXを使用することで、JConsoleから確認できるようにしたりすることができるので、もしそのような方法をとっているならば、出力しなければいけない情報はかなり少なくなると思います。

WARN、ERROR、FATAL

これらのログの使い分けは一般にエラーの深刻度を基準とするというような説明が多いですが、深刻度というのはかなりあいまいです。WEBアプリケーションに限るならばもう少し詳細な説明ができると思います。また、ERROR、WARNはアプリケーションの稼働が継続できるが、FATALエラーはアプリケーションの稼働が継続できないといった分類がされることがあります、WEBアプリケーションでいうならば、特定のユーザやユーザのリクエストに対するエラーに関することはERROR、WARNレベルで、FATALレベルにはすべてのユーザがエラーとなってしまう事象について出力すればいいのではないでしょうか。またWARNレベルに出力するログは実際にはエラーが起こっていないもの、つまり「潜在的にエラーを引き起こす」ようなものを出力します。この基準でERRORレベルとWARNレベルを使い分けます。

FATAL

FATALレベルにはユーザ全体に影響を与えるようなログを出力します。たとえばDB接続エラーなどのネットーワークに関するエラーや、ファイルの書き込みエラーなどのIOに関するエラーです。

しかし、すべてのネットワークエラーやIOエラーをFATALレベルにすればいいというわけではありません。ネットワークエラーは一時的なものである場合も多いからです。エラーが一時的である場合にはERRORレベルで出力するのが適当でしょう。

ERROR

ERRORレベルには簡単に言ってしまうと、FATALレベル以外のエラーをすべて出力します。前述した通り使い分ける基準はユーザ全体に影響を与えるかそうでないか、エラーが一時的なのか継続的なのかです。

ここで、エラーの出力をERRORとFATALに分ける事に疑問を持つ人もいるかもしれません。本番環境ではINFOレベルでログを出力するので ERRORとFATALを分けただけではログにERRORと出力されるかFATALと出力されるかだけの違いしかありません。頻繁にエラーを発生させるようなアプリケーションを本番環境にデプロイするとは考えにくいので、ERRORかFATALかは内容を見ればすぐに分かりそうです。

何故ERRORとFATALにログ出力を分けるのかというと、エラーの深刻度を明確にするためです。エラーがユーザ全体に影響を与えるかどうかと、エラーが一時的か継続的かという基準は、「深刻度」をより分かりやすくしたに過ぎません。実際の場面ではエラーの深刻度によってその対応がかわってくる事が多いと思います。エラーがFATALレベルのものであれば即座に対応しなくてはいけませんし、ERRORレベルのものであれば次の日に対応しても良い場合があります。

したがって、エラーが一時的であっても問題が深刻であるならば、FATALレベルで出力するといった場面もあると思います。

WARN

WARNレベルには「潜在的に害を及ぼすような状況を指定します」とありますが、この潜在的に害を及ぼすような状況とはどういうものでしょうか?

たとえば、あるメソッドの入力値として想定しないデータが来た場合にも適当な処理がなされるようにコードを書くことは多いと思います。処理は適切になされるのでエラーは発生しませんが、想定していないデータが入力値としてある時点で、アプリケーション内で整合性が取れていない箇所があるのかもしれません。そういった場合にWARNレベルのログとして出力しておけば、後でその問題をつきとめる事ができます。しかし、想定していないデータがくる事があらかじめ分かっている場合、たとえばそのデータがユーザからのリクエストに乗せられてくるようなデータの場合は、出力しない方が良いでしょう。

他にも具体的な例があるのかもしれませんが、これに関しては個々のアプリケーションによって様々なので一般的な例を挙げるは難しいです。しかし忘れてはいけないのは、あまりに大量のログを出力させるようなものは出力しないということです。というよりもWARNレベルのログを大量に出力しなければいけない場合があったとしても、それはアプリケーションのロジックに大きな問題があると考えられるので、まずそちらを対処した方が良いでしょう。