Java EE アドベントカレンダー 13日目 ログ出力について

これはJava EE Advent Calendar 2014の13日目の記事です。

昨日はtatsu983さんの「JSFのコンセプト（考え方）って？」でした。

先日、Twitter上でログなんて出したいものを出しておけばいいんだよというお話をしていたら、そもそも出したいものってなんだよというツッコミを受けたのでそれをネタに書きます。
//10日も遅れて公開しましたよ！
基本的にJavaで作られたWebシステムを想定し、他のインフラでは必ずしも当てはまらないと思います。

ログとは

まずログとはなんでしょうか。
Wikipediaによるとデータログというもので、"コンピュータにおけるデータログでは、障害などが発生したとき、何が起きたのかを説明できるようにするためにプログラムが自動的にある範囲のイベントを記録する。"だそうです。
"ログは「航海日誌」 (logbook) を語源とする用語"という説明もあります。
結局は、日記、履歴もしくはそれらに類するものですね。

そもそも何があったというのはどうやって判断するのでしょうか？
ログを監視することで何かがあったということを発見するということもよく行われています。
問題(何かがあったこと)を見つけることが出来なければ解決(何があったかを説明して、それに対して対応を行う)ことは出来ませんからね。

また、今日では、ログを使用してシステムの今後の戦略を詰めていくことも行われています。
例えば、ユーザーの行動履歴を記録し、よく使用される機能を特定して、機能を充実させるとか、もしくは購買情報を記録して今後の販売計画に使用するとかですね。

ログを取得する観点

私は次の観点で取得するログを決めています。

システムが正常に処理できていること

システムが急に重くなったとかそういう話があるのですが、大抵の場合は予兆があります。*1
正常にリソースが使用されていることをログとして収集します。
例えば、以下のものを取得します。

  • スレッド数/スレッド情報
  • CPU、メモリ、ディスク使用率
  • GCがいつ行われたのか
  • 発行されたSQL/バインドされたパラメーター/SQLの実行時間
  • アクセス履歴/実行時間
  • S.M.A.R.T.等
セキュリティ上問題がないことを確認すること

多くのシステムでは他人から見られたら問題のあるデータを扱います。個人情報保護法などもあり、適切にセキュリティが守られていることを確認する必要があります。
有名な基準としては、PCI-DSSがあります。何をログとして記録するべきか不安になるのならばそちらを確認し、記録するものを決めるのが良いでしょう。
例えば、次のものを取得します。

  • ユーザーがログイン/ログオフした
  • ユーザーが自分の情報にアクセスした/変更した
  • ユーザーが何かしらのリソースにアクセスした
障害時に解析できるようにすること

システムがダウンしてしまった場合に、なぜダウンしたのかを解析できるようにログを取得します。
システムが正常に処理できていることの確認ログや、障害発生時のメモリダンプを取得します。

業務的に必要な情報

その他、業務上必要な情報についてログを取得します。購買情報を解析して次に欲しい物を見極めたり等を行います。
システムにより千差万別なので省略します。
個々のシステムで考えて下さい。

ログとしては取ってはいけないもの

ログは他の情報よりもセキュリティ面で脆弱な管理がされる場合が多いので、個人情報については原則としてログには書き出さないようにします。
例えば、以下のものはログとして出力しないようにマスクします。

  • パスワード
  • カード番号
  • 性別、生年月日等いわゆる機微情報

実際にどうログを取っていくのか

以下の様な感じで、ログを取得していけば良いと思います。

全般的なインフラ情報

色々な監視ミドルウェアがありますので、そちらで監視できる項目を調べるのが良いと思います。
最近私の周りではZabbixを使っているというのをよく聞きます。
CPUや、メモリ、HDD等を適切に。
また、APサーバーで取得できる、アクセスログ等があります。APサーバーで取得できるログについては各種マニュアルを参照して下さい。

JVMに対する情報

JMXで色々取得できます。「全般的なインフラ情報」で紹介したZabbixがあればスレッド数等の情報も取得できます。
リアルタイムで取得した情報を見て、何が取得できるのかについて想像がつかない人はJVisualVMを使用してどのような情報が取れるのかについて一度見てみるのが良いと思います。
Tomatで使ってみる場合は以下を参照してみてください。
http://ameblo.jp/wataru420/entry-11250099243.html

また、非常時のため、GCのログと、OOM発生時のメモリダンプを取得するようにしておきます。
"-Xloggc:<ファイル名>" と "+HeapDumpOnOutOfMemoryError"オプションを起動時につけてあげます。詳細はググれ。

アプリケーションで正常動作をしていることを確認するために作りこむログ

多分ここを書きたかった。
アプリケーションではどのようなログを出力すればよいのでしょうか。
まず、以下の様なものはログとしては出力しません。

デバッグログでロジックのどこを通ったのかを詳細に出力するログを見かけることがありますが、そのようなものは書かないほうが良いでしょう。
今日では、JUnit等を使用して、In/Outが固定された状態での詳細なロジックについての確認は本番環境でなくても出来ます。
また、ほんとうに必要な場合はデバッガを利用して直接メモリの状態を確認すれば良いと考えます。*2


では、何を出力するように作るべきか。
それは、In/Outです。

何を受け取って、何を返したのかが判れば他の環境で再現を試みることが出来ます。
以下のような形で検討しています。

  • In/OutはUnix的なソケットを介する場所と定義する。例えば、ユーザーからの入力や、ディスクIO、データベースアクセス等。
  • 原則として、アクセスする側、される側両方でログを取得する。例えば、Hibernateを利用したOracle DBへのアクセスであれば、HibernateでSQLとバインド変数のログを取得するだけでなく、Oracle Audit等を利用してDB側でもログを取得する。

アクセスログだけではなく、ユーザーがUI上で操作した情報をJavaScriptを使用して、他のサーバーに送ったりとか・・・・・・

  • 原則として通信に使用された生データと、それをプログラム上どう解釈したのかについて両方共ログに出力する。

JAX-XXを使用して通信した場合、勝手にJavaBeansに変換されますが、不要な情報はいつの間にか除去されてしまったりします。
両方とっておいたほうが無難です。

アプリケーションで異常動作をしていることを確認するために作りこむログ

昨今のフレームワークであれば、ExceptionResolverや、ExceptionHandlerとかそれっぽい名前でエラーハンドリングをするための部品が用意されています。
中でエラーが発生した場合は極力キャッチをせず、そちらにエラーをハンドリングさせて、異常を検知させます。その際に、In/Outとの紐付けが出来る情報(日時、スレッドID等)と、どうして異常と判断されたのか(具体的にはスタックトレース)を出力します。

まとめ

ということで、私がログ設計をする場合に検討している項目をざっくりと並べました。
こういうのもログに残したほうが良いよというのがあればご教示いただけると幸いです。

*1:ECサイトで商品がテレビに急に紹介された場合等、まったくもって突然の場合もあります

*2:ただし、常時デバッガの接続を有効にしていると動作が遅くなるそうですので必要な場合のみデバッガの接続を有効にする必要があります。