優れたロギング

2021/06/21 09:15

Henrik Warne
ストックホルムを拠点におくシニアソフトウェア開発者
この記事は、著者の許可を得て配信しています。
Good Logging

プログラムがすべきことをきちんとこなしているかどうかを確認するには、与えられた入力からの出力を調べることができます。しかし、システムが大きくなると、何が起こっているかを理解するためのログも必要になります。優れたログメッセージは、問題のトラブルシューティングには欠かせません。しかし開発者の多くは適切な場所に十分な情報を記録していないのです。

問題のトラブルシューティングをするときには、ログを見ます。時にはバグが原因で間違った動作をしていることもあります。また、何も問題がない場合もあります。システムは正しく動作していますが、私たちはシステムが何をすべきかについて間違った予想をしていた場合です。どちらの場合も、ログはシステムで何が起こっているかを理解するのに役立ちます。また、新しい機能を完成させた後、探索的テストを行う際にもログをチェックします。その機能をいじってみて、期待通りの結果が得られるかどうかをチェックします。私はログを見て、期待した結果と一致しているかどうかを確認します。

目安としては、タスクの開始時、移行時、終了時にログを取るのがいいでしょう。短いタスクであれば、最後に記録するだけで十分な場合もあります。また、タスクが失敗する可能性のあるすべての場所でログを取るのが好きです。ログメッセージを最大限に利用するためのさらなるヒントをご紹介します。

やりすぎということはない

最近のログシステムは大量のログメッセージを処理できるようになっていますが、ログに記録される内容を制限することは良いことです。過剰なロギングの中には、ほとんど価値のないものもあります。例えば、スキップの条件がシンプルな場合、「Skipped message of type margin_data_available」は不要な情報に過ぎず、削除すべきものです。また、コードのA点の後に必ずB点が続くような場合は、2つのログステートメントではなく、B点(A点の情報を含む可能性あり)でのログで十分な場合もあります。

少なすぎてもいけない

ログが多すぎることも問題ですが、ログが足りないことの方がはるかに多いのです。これは特に、あらゆる種類の障害(予期されるものと予期されないものの両方)に当てはまります。多くの場合、問題をデバッグする際には、タスクがどのように、そしてなぜ失敗したのかを知りたいですよね。もし、すべての失敗モードのログがなければ、推測するしかない場合もあります。

ダイナミックな情報の追加

よくあるのが、ログメッセージがあまり役に立たない場合があるということです。例えば、「請求書発行サーバーに接続しました」というのは、サーバーのIPアドレスとポートを追加することで改善できます。別の例として、ファイルからカレンダーデータを読み込んでインメモリデータベースを初期化する場合が挙げられます。データベース作成時のログメッセージには、ファイル名と、ファイルに含まれるデータの行数が含まれています。このログメッセージは、データファイルが切り捨てられたことによる問題のトラブルシューティングに重要な役割を果たしました。一般的には、できるだけ多くのダイナミックな情報を追加するようにします。

grep可能なメッセージ

ログメッセージにファイル名と行番号が自動的に含まれている場合でも、ログメッセージ内のテキストをユニークにして、grepしやすくするのもいいでしょう。これにより、コード中のログ文を簡単かつ迅速に見つけることができます。ログメッセージが文字列から作られている場合は、やはりgrepしやすいようにしてください。多くの場所で 「Failed: %s %s」 と書かれていると、それが難しくなります。異なるケースをテキストで記述するのが難しい場合は、「Failed (1): %s %s 」などを使ってケースを区別することもできます。

ロギングが多くの場所から呼び出される関数で行われている場合、どのケースであるかを記述する文字列のために、関数に追加の引数を追加してみてもいいと思います。そうすれば、ログメッセージの中で、どのケースからのものかが明確になります。

メッセージリストを返す

「何をすべきか」というロジックがある場合、私はそのロジックを単体でユニットテストが可能な関数の中に入れたいと思っています。ロジックが複雑な場合は、決定事項を説明するログメッセージを生成すべきだと思います。これにはいろいろな方法がありますが、私が好きなのはタプルを返す方法です。タプルの最初の要素は結果で、2番目の要素は出力する(空でも大丈夫です)ログメッセージのリストです。この関数が呼び出された後、メッセージリストが空でなければ、エントリが連結され、ログメッセージとして出力されます。

こうすることで、結果が正しいことと、ログメッセージが予想通りのものであることの両方を簡単にテストすることができます。文字列ではなくリストになっているのは、決定がどのように行われたかについて、重要な点が複数ある場合があるからです。例えば、コンフィグレーションでは強制的にマージンタイプになっており、契約の開始日は「近い将来」であるとします。これらはいずれも、今期はこの契約を請求すべきではないという判断に関連している可能性があります。また、リストに複数の項目があっても、複数のログステートメントではなく1つのログステートメントで済むので、ログを取る手間が省けます。

叫ばないで「####--」を付けることで目立つようになるということであれば、「目立とうとしないで」としてもいいかと・・・「####--」の意味合いがよくわかないので)

時折、コードに残された以下のようなログメッセージを目にすることがあります。"#### Could not fetch agreement data for ABC-DEF-CSA"(ABC-DEF-CSAの契約データを取得できませんでした)。必然的に、例えば「####--」などで始まる同じようなメッセージが出てきます。最終的には、誰のログメッセージが最も大きく声を上げて注目されるかという競争に発展します。ログメッセージには、目を引くような特別な文字を使ってはいけません。ログを見ている人に何を見たいかを決めさせてください。唯一認められる差別化要因は、WARNINGやINFOのようにログレベルを使い分けることです。

繰り返し

最初の試みでログメッセージを正しく理解するのは難しいです。私の場合は、満足のいく結果が得られるまで何度も試してみます。出力結果を見て、必要に応じてメッセージを修正します。例えば、私は請求書が発行されない場合に契約書のUUIDを記録していました。しかし、UUIDではなく、契約名や当事者名を記録した方がはるかに意味があることが分かったので、そのように変更しました。

さらに、トラブルシューティングの際に、ログに必要な情報がすべて含まれていない場合は、忘れずに追加するようにしています。

その他

ロギングは一見冗長に見えますが、それでも有用な場合があります。例えば、会社では1分ごとにハートビートのAPIコールを行っています。これにはメトリクスがあり、受信されない場合はアラートが送信されます。しかし、受信したときのロギングも追加しました。1分ごとなので、あまり多くの出力は発生しません。システムで何が起こっているかを把握するのに役立ちます。また、メトリクスの収集に問題があったときに、ログをチェックしてハートビートがまだ来ていることを確認できたのも良かったです。

トラブルシューティングは私にとって身近なものであり、以前にもトラブルシューティングとログとの関係について記事を書いたことがあります。「優れたプログラマーはデバッグ可能なコードを書く」、「バグを見つけるということ:デバッガ対ロギング」「セッションベースのロギング」などで紹介しました。

まとめ

優れたロギングはトラブルシューティングの際に本当に役立ちます。トラブルシューティングをすればするほど、適切な場所に適切な情報を記録することのありがたみがわかってきます。新しい機能を開発する際には、その機能が機能していない場合にどのような情報が必要になるかを自問し、適切なログメッセージを追加してください。ロギングに関するご意見がありましたらコメントをください!みなさんからのご意見をお待ちしております。

appstore
googleplay
会員登録

会員登録して、もっと便利に利用しよう

  • 1.

    記事をストックできる
    気になる記事をピックして、いつでも読み返すことができます。
  • 2.

    新着ニュースをカスタマイズできます
    好きなニュースフィードをフォローすると、新着ニュースが受け取れます。