ログ設計指針

概要

このドキュメントは、効率的かつ安定した、システム開発/運用をするためのログ設計指針です。
的確かつ無駄のない、ログ出力を目指します。

ログレベル

ログの緊急度や用途により、以下のようにログレベルを設定する。 Log4j のログレベルを踏襲しているため、運用の状況によっては Critical などのレベルを適宜追加すると良い。
PHP における PSR-3 では、さらに細分化され emergency, alert, critical, error, warning, notice, info, debug となっている。
「出力先」「運用時の対応」は、各プロジェクトのポリシーに準じてください。

レベル	概要	説明	出力先	運用時の対応
FATAL	致命的なエラー	プログラムの異常終了を伴うようなもの。コンソール等に即時出力することを想定	コンソール, ファイル	即時対応が必要
ERROR	エラー	予期しないその他の実行時エラー。コンソール等に即時出力することを想定	コンソール, ファイル	営業時間内のみ対応
WARN	警告	廃要素となったAPIの使用、APIの不適切な使用、エラーに近い事象など。実行時に生じた異常とは言い切れないが正常とも異なる何らかの予期しない問題	コンソール, ファイル	次回リリースまでに対応
INFO	情報	実行時の何らかの注目すべき事象（開始や終了など）。メッセージ内容は簡潔に止めるべき	コンソール, ファイル	対応不要
DEBUG	デバッグ情報	システムの動作状況に関する詳細な情報	ファイル	出力しない
TRACE	トレース情報	デバッグ情報よりも、更に詳細な情報	ファイル	出力しない

参考

出力場所

ログは、運用担当者が、できるだけすぐに見つけられる場所に出力する。
ファイルに出力する場合は、 /var/log など、わかりやすいディレクトリに出力し、適切なパーミッションを設定すること。

ログにはシステム内部の重要な情報が出力される場合もあるため、 Webの公開ディレクトリや、パーミッション 777 のディレクトリ等、不特定ユーザーのアクセス可能な場所には出力してはならない。

標準出力: 主にバッチアプリケーションなど、コンソールから起動する場合で、途中経過を出力する場合などに使用する。
標準エラー出力: 主にバッチアプリケーションなど、コンソールから起動する場合で、エラーが発生した場合などに使用する。標準出力に実行結果を出力する場合は、途中経過などに使用される場合もある。
ファイル: 主にコンソール以外で起動されるアプリケーションに使用する

また、開発者や運用担当者の作業やコミュニケーションを円滑化するため、 Slack などのチャットツールやメールに出力しても良い。
この場合、出力しすぎないよう流量に注意する。ログの出力しすぎは放置の要因となる。

Slack などの外部システムへ出力している場合、外部システムの稼働率に注意すること。
システム障害発生時など、多くのログが出力された場合、外部システムがダウンしてしまうと元も子もないため、必ず代替の出力先を用意しておくこと。

ログメッセージ

メッセージファイルにまとめ、プログラムに直接ハードコーディングしないのが望ましい。
機種依存文字は使用しない。ASCII文字のみが望ましい。マルチバイト文字を使用する場合は、ログを閲覧する環境で文字化けしないよう注意すること。
できるだけ簡潔に、わかりやすく出力すること。
コンソールから確認することを考慮し、1行を80文字以内に収めるのが望ましい。

フォーマット

見やすく、運用を考慮したフォーマットを心掛けること。以下は一例。

ヘッダ

開始時間
処理名称
処理対象
対象件数

フッタ

終了時間、所要時間、処理結果
- OK/NG など

BODY

処理途中経過
- ○件/○件中
イベント内容
種類
- ログレベル
- 対象ファイル、行数
- 調査時など特に理由のある場合を除き、エラー時以外でスタックトレースは出力しない

出力例

Webアプリケーションでの出力例

INFO レベルでは処理内容、 DEBUG レベルでは、HTTP Request/Response の内容、 SQL のデバッグログ等を出力する
出力内容が多くなるとレスポンスに著しく影響を与えてしまうため、 Web サーバーのログなどで代替可能なものは活用すること(特にスクリプト言語)

org.apache.log4j.PatternLayout に従ったフォーマットでは以下のように指定することで、サンプルのような出力となる

%-5p %d [%t] %m%n

処理内容(正常終了)

INFO  2015-10-30 15:44:01,836 [http-8080-4] START - /path/to/example is Called from getApplication.
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT email=user@example.com
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT password=******
INFO  2015-10-30 15:44:01,836 [http-8080-4] ID: 5003 - Success
INFO  2015-10-30 15:44:01,836 [http-8080-4] END - /path/to/example is Called from getApplication.

処理内容(異常終了)

INFO  2015-10-30 15:44:01,836 [http-8080-4] START - /path/to/example is Called from getApplication.
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT email=user@example.com
INFO  2015-10-30 15:44:01,836 [http-8080-4] INPUT password=******
ERROR 2015-10-30 15:44:01,836 [http-8080-4] EXECUTE FAILURE! User registration
ERROR 2015-10-30 15:44:01,836 [http-8080-4] Cause by: WebServiceException - [ERR:1000] User exists
ERROR 2015-10-30 15:44:01,836 [http-8080-4] redirect to /path/to/error

デバッグログ

DEBUG 2015-10-30 15:44:01,822 [http-8080-4]

** before *****************************************: /path/to/example
  REQUEST_URI=/path/to/example
  CharacterEncoding=UTF-8, ContentLength=-1, ContentType=null, Locale=ja, Locales=ja, zh_TW, en, Scheme=http, isSecure=false
  SERVER_PROTOCOL=HTTP/1.1, REMOTE_ADDR=127.0.0.1, REMOTE_HOST=127.0.0.1, SERVER_NAME=localhost, SERVER_PORT=8080
  REQUEST_METHOD=POST, QUERY_STRING=null, PathInfo=null, RemoteUser=null
  Session SessionId=C5C2638BEDBD6553F000EF87E749CBAF
  Session :: CreationTime=1446186481217, LastAccessedTime=1446187436782, MaxInactiveInterval=1800
  [request]javax.servlet.forward.request_uri=/path/to/example
  [cookie]JSESSIONID=C5C2638BEDBD6553F000EF87E749CBAF
  [header]accept=text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
  [header]accept-encoding=gzip, deflate
  [header]accept-language=ja,zh-TW;q=0.7,en;q=0.3
  [header]connection=keep-alive
  [header]cookie=JSESSIONID=C5C2638BEDBD6553F000EF87E749CBAF
  [header]host=localhost:8080
  [header]referer=http://localhost:8080/path/to/example
  [header]user-agent=Mozilla/5.0 (Windows NT 6.1; WOW64; rv:41.0) Gecko/20100101 Firefox/41.0
  [header]x-clickoncesupport=( .NET CLR 3.5.30729; .NET4.0E)
  [session]user=user@example.com

DEBUG 2015-10-30 15:44:01,835 [http-8080-4] BEGIN path.to#example()
DEBUG 2015-10-30 15:44:01,836 [http-8080-4] BEGIN TRANSACTION tx=[FormatId=4360, GlobalId=1446186481238/32, BranchId=]
DEBUG 2015-10-30 15:44:01,836 [http-8080-4] SELECT email, password FROM users WHERE email = 'user@example.com';
DEBUG 2015-10-30 15:44:01,836 [http-8080-4] INSERT INTO users (email, password) VALUES ('user@example.com', '******');
DEBUG 2015-10-30 15:44:01,836 [http-8080-4] COMMIT TRANSACTION tx=[FormatId=4360, GlobalId=1446186481238/32, BranchId=]
DEBUG 2015-10-30 15:44:01,836 [http-8080-4] END path.to#example()
DEBUG 2015-10-30 15:44:01,840 [http-8080-4]

** after *****************************************: /path/to/example
  [request]email=user@example.com
  [request]password=******
  [request]request_uri=/path/to/example
  [cookie]JSESSIONID=C5C2638BEDBD6553F000EF87E749CBAF
  [session]user=user@example.com

バッチアプリケーションでの出力例

コンソールで閲覧することを前提にしているため、1行80文字以内に収まるようにし、「年」のフィールドは省略している
クリティカルなアプリケーションの場合は、ミリ秒単位で出力する場合もある

org.apache.log4j.PatternLayout に従ったフォーマットでは以下のように指定することで、サンプルのような出力となる

%-5p %d{MM/dd HH:mm:ss} %m%n

ジョブの開始

INFO  04/03 09:55:14 -----------------------------------------------------------
INFO  04/03 09:55:14 BEGIN JobAB000000001
INFO  04/03 09:55:14 -----------------------------------------------------------

ジョブの正常終了

INFO  04/03 09:55:14 -----------------------------------------------------------
INFO  04/03 09:55:14 FINISHED SUCCESSFUL JobAB000000001
INFO  04/03 09:55:14 -----------------------------------------------------------
INFO  04/03 09:55:14 Total time: < 1 second
INFO  04/03 09:55:14 Finished at: Fri Apr 03 09:55:14 JST 2014
INFO  04/03 09:55:14 Final Memory: 6M/119M
INFO  04/03 09:55:14 -----------------------------------------------------------

ジョブの異常終了

INFO  04/03 10:25:22 -----------------------------------------------------------
ERROR 04/03 10:25:22 EXECUTE FAILURE! JobAB000000001
ERROR 04/03 10:25:22 Cause by: IOException - I/O Error!
INFO  04/03 10:25:22 -----------------------------------------------------------
DEBUG  04/03 10:25:22 Trace
java.io.IOException: I/O Error!
	at jp.example.job.JobAB000000001.execute(JobAB000000001.java:70)
	at jp.example.command.Main.main(Main.java:115)
DEBUG  04/03 10:25:22 -----------------------------------------------------------

途中経過

INFO  04/03 10:12:21 -----------------------------------------------------------
INFO  04/03 10:12:21 START - exampleMethod is Called from getApplication.
INFO  04/03 10:12:21 ID: 5002 - Skip (1/105)
INFO  04/03 10:12:21 ID: 5003 - Success (2/105)
... snip
INFO  04/03 10:12:21 END - exampleMethod is Called from getApplication.
INFO  04/03 10:12:21 -----------------------------------------------------------

出力タイミング

以下のようなタイミングで出力する

バッチアプリケーションの場合

INFO 処理開始時
INFO 途中経過
INFO 処理終了時
WARN イベント発生時
ERROR 例外発生時
INFO その他、必要に応じて

Webアプリケーションの場合

HTTP Request/Response の内容は、 DEBUG レベルで出力し、 RequestDumpFilter などを使用して、アプリケーション内ではコーディングしないのが望ましい。
PHP で monolog を使用している場合は EasyCorp/easy-log-handler を使用すると視認性の良いログを出力できる。

以下、 INFO レベルのログは、コントローラークラスで、できるだけ簡潔に出力すること。

INFO リクエスト開始時 - 処理概要、実行クラス名、メソッド名
INFO 途中経過 - 実行条件、処理対象オブジェクトのキーとなる値等(customer_id, order_id 等)
INFO 処理終了時 - 実行結果(OK/NG 等)、リダイレクト先
WARN イベント発生時 - 画面に表示したエラーメッセージ等
ERROR 例外発生時 - 例外クラス、例外メッセージ
INFO その他、必要に応じて

パフォーマンスについて

ログ出力によりパフォーマンス劣化が見られる場合は, ログ設計を見直すこと

ログローテーション間隔について

ログの種類、容量、解析するタイミングを考慮し、ローテーション間隔を決めること。
また、必要に応じて圧縮処理を行なう。

ログのセキュリティについて

ログには「氏名」「住所」など特定の個人を識別する情報や「電話番号」や「メールアドレス」「SNSのアカウント情報」などインターネットにおいて個人と連絡をとったり個人の所在を突きとめたりできるような情報を、そのまま出力しないこと。
また、セッションIDや、アクセストークンなど、流出すると不正アクセスの要因となるような情報も、出力を避けるべき。
各プロジェクトの個人情報保護指針に準拠し、以下のような対策をすることが望ましい。

出力しない
マスク処理をする
識別性を維持する必要がある場合は一方向ハッシュ関数を使用し符号化する

ログと変更履歴

アプリケーションの操作や、データの変化をログに記録することは重要である。
しかし、ログには、何らかのアクションが発生したことを記録するのに留め、証跡確認のための操作履歴や、データの変更履歴などは、別途変更履歴機能などを作成する方が望ましい。

TODO

ログ設計の有用性を追記する
ローテーションや保存期間の指針を追加する
ログのメンテナンスについての指針を追加する
ログの監視についての指針を追加する
コンソール、ファイル以外の出力先について追記する
- Amazon CloudWatch Logs や Azure Monitor Logs の活用方法

参考