- Google Testing Blog より Optimal Logging の和訳
あなたのシステムで、失敗の根本的な原因を探すのにどのくらい時間がかかりますか?5分?5日? もし、5分近くで答えられたなら、あなたのプロダクションシステムやテストは素晴らしいロギングを持っていることでしょう。 多くの場合、ロギングや例外ハンドリングや(あえて言いますが)テストなどの一見、本質的ではない機能は実装の後に行われます。 例外ハンドリングやテストと同様に、あなたのシステムやテストの両方にロギングの戦略が本当に必要です。 ロギングの力を過小評価しないでください。最適なロギングは、デバッガの必要性を排除することさえできます。 以下は長年に渡って便利だった、いくつかのガイドラインです。
訳者メモ 3匹のくま、から転じて、Goldilocksはちょうどよい状態を表している?
大量にログを吐かないでください。大量のディスクを使い尽くすログはログに対してほとんど考慮していないことに対する明確な指標です。 大量にログを吐いている場合、あなたは、ディスクアクセスの最小化やログの履歴を管理し、大量のデータをアーカイブし、 それらの大量のデータを検索するための複雑なアプローチを考える必要があります。 そして重要なのは、すべてのおしゃべりの中で価値のある情報を見つけることはとても難しい、ということです。
ロギングが多すぎるより悪いことは、ロギングが少なすぎることだけです。通常、ロギングには2つの主なゴールがあります。 それはバグの調査やイベントの確認を助けることです。 あなたのログによって、バグの原因やあるトランザクションが起きたかどうかを説明できないならば あなたのログは少なすぎるでしょう。
ログを吐くと良いこと
- Important startup configuration (重要な起動時の設定)
- Errors
- Warnings
- Changes to persistent data(永続データへの変更)
- Requests and responses between major system components(主要なシステム間のリクエスト、レスポンス)
- Significant state changes(重要な状態の変更)
- User interactions(ユーザとの相互作用)
- Calls with a known risk of failure(失敗のリスクが分かっている呼び出し)
- Waits on conditions that could take measurable time to satisfy (条件を満たすのにかなりの時間がかかる可能性のある条件の待機時間)
- Periodic progress during long-running tasks(長い実行時間のタスクの周期的な進捗)
- Significant branch points of logic and conditions that led to the branch(重要なロジックの分岐点やその分岐に至った条件)
- Summaries of processing steps or events from high level functions - Avoid logging every step of a complex process in low-level functions. 高次の関数で処理されたステップやイベントのサマリ。低レベルの関数で、複雑なプロセスの各ステップでログを吐くのは避けてください
ログを吐くと良くないこと
-
Function entry - Don’t log a function entry unless it is significant or logged at the debug level. 関数への突入。- 重要でない関数への突入はログ出力しないでください。もしくはデバッグレベルでログ出力してください。
-
Data within a loop - Avoid logging from many iterations of a loop. It is OK to log from iterations of small loops or to log periodically from large loops. ループ内のデータ。- ループの繰り返しからログを吐かないでください。小さいループの繰り返しや大きなループから定期的にログを記録するなら大丈夫です。
-
Content of large messages or files - Truncate or summarize the data in some way that will be useful to debugging. 大きなメッセージやファイルの中身。- 切り捨てるか、デバッグに有用な形でデータを纏めてください。
-
Benign errors - Errors that are not really errors can confuse the log reader. This sometimes happens when exception handling is part of successful execution flow. 良性のエラー - 本当のエラーではないエラーはログを読む人を混乱させます。これは例外ハンドリングが正常な実行フローの一部にある時におきます。
-
Repetitive errors - Do not repetitively log the same or similar error. This can quickly fill a log and hide the actual cause. Frequency of error types is best handled by monitoring. Logs only need to capture detail for some of those errors. 繰り返しのエラー。 - 同じや似たようなエラーのログを繰り返さないでください。これはログを急速に埋め尽くし、本当の原因を隠すことがあります。エラータイプの頻度は監視によって最も良く処理されます。ログはそれらのエラーの一部について詳細を記録するだけで済みます。
全て同じログレベルでログ出力しないでください。ほとんどのロギングライブラリでは、いくつかのログレベルを採用しており システムの起動時にレベルを決めて有効にすることができます。 これは、ログの詳細性を便利に制御できます。
一般的なレベルは以下のようなものです。
- Debug - verbose and only useful while developing and/or debugging. debug - 冗長で開発中やデバッグ時にのみ有効
- Info - the most popular level. info - 最も一般的なレベル
- Warning - strange or unexpected states that are acceptable. warning - 許容可能な奇妙な状態や期待していない状態
- Error - something went wrong, but the process can recover. error - 何かがおかしくなったが、プロセスはリカバリが出来るもの
- Critical - the process cannot recover, and it will shutdown or restart. critical - プロセスがリカバリ不可能で、シャットダウンや再起動します。
実際には、2つのログ設定だけが必要になります。
-
Production - Every level is enabled except debug. If something goes wrong in production, the logs should reveal the cause. 本番 - デバッグを除く全てのレベルが有効になっている。もし本番で何かがおかしくなったら、ログによって原因を明らかになっているはずです。
-
Development & Debug - While developing new code or trying to reproduce a production issue, enable all levels. 開発 & デバッグ - 新しいコードの開発中やプロダクションでのイシューの再現しようとしながら、全てのレベルが有効になっている
ログの品質はテストやプロダクションコードと同じように重要だ。 テストが失敗したとき、ログは、テストに問題があったのか、本番システムに問題があったのか 明確に示すべきだ。もしそうでないなら、テストのログは壊れている。
テストのログでいつも含んでいるべきもの
- Test execution environment テストの実行環境
- Initial state 初期状態
- Setup steps セットアップステップ
- Test case steps テストケースステップ
- Interactions with the system システムとのインタラクション
- Expected results 期待する状態
- Actual results 実際の結果
- Teardown steps teardownステップ
エラーが起きたとき、ログには詳細についてたくさん含んでいるべきです。残念ながら、エラーを導いた詳細はしばしば エラーが発生すると利用できなくなります。また、ログを記録しすぎないというアドバイスに従った場合、エラーの記録より前のログでは 詳細が分からない場合があります。 この問題を解決する良い方法は、一時的な、インメモリのログのキューを作ることです。 トランザクションの処理中、各ステップでキューの詳細な情報を追加します。 もしトランザクションが成功したなら、キューを捨て、サマリをログ出力してください。もしエラーが起きたら、キューの中身とエラーをロギングしてください。 このテクニックは、システムのインタラクションに関するテストのロギングで特に有効です。
プロダクションシステムでエラーが起きたとき、問題を探し、酒精するのにフォーカスするべきですが、ログについても考えるべきです。 もし、エラーの原因を突き止めるのが難しいなら、それはあなたのログをより良くする貴重な機会です。問題を修正する前に、ログが原因を明確に示すように ログを直しましょう。また問題が起きてしまっても、特定するのにより簡単になるでしょう。
もし、問題を再現することが出来ない場合や、脆いテストがあるなら、また起きたときに問題を追いかけやすくするためにログを強化しましょう。
失敗を使って、ロギングを改善することは、開発中を通して行われるべきです。新しいコードを書いたなら、デバッガを使うことを控えるようにして ログのみを使いましょう。ログはどうなったかを示していますか?そうでないならログは不十分でしょう。
ログ出力した時間はパフォーマンスイシューをデバッグすることを助けます。例えば、大きなシステムの中で タイムアウトの原因を特定するのは非常に難しいでしょう、もし、あなたが重要なステップごとに使った時間をトレース出来ないなら。 これは、測定可能な時間が掛かる可能性のある呼び出しの開始時間と終了時間 ロギングによって簡単に成し遂げられます。
- Significant system calls - 重要なシステムコール
- Network requests - ネットワーク呼び出し
- CPU intensive operations - CPUに負荷のかかる処理
- Connected device interactions - 接続デバイスとのインタラクション
- Transactions - トランザクション
あなたはスレッドやプロセスを超えて処理を紐付ける、トランザクションのユニークIDを作るべきだ。 トランザクションのイニシエータはそのIDを作るべきで、それは、そのトランザクションの作業をする全てのコンポーネントに 渡されるべきである。 このIDはトランザクションに関するログ情報を記録する時に、それぞれのコンポーネントによってロギングされるべきです。 これは、多くのトランザクションが並列で処理されているときに、特定のトランザクションを追いかけやすくします。
プロダクションサービスでは、ロギングとモニタリングは持っているべきです。 モニタリングではシステムの状態のリアルタイムな統計的サマリを提供します。 あるリクエストの種類が失敗している場合、異常なトラフィックパターンが発生している場合、パフォーマンスが低下している場合、もしくはその他の異常が発生した場合に アラートが可能です。 時に、これらの情報だけで問題の原因を突き止められるでしょう。しかしながら、多くのケースにおいて モニタリングアラートは調査を始めるべきだとあなたに伝えるためのトリガーです。 モニタリングは問題の症状を示します。ログによって個別のトランザクションの詳細と状態を提供し、問題の原因を完全に理解することができます。