ロギングベストプラクティス

CC BY 4.0 @Brice Figureau

1.自分でログの書き出しをしない

printfをつかったり、ログエントリを自分でファイルに書き出したり、ログローテションを自分でやったりしてはいけない。運用担当者にお願いして、標準ライブラリやシステムAPIコールを使うようにしよう。そうすれば、実行中のアプリケーションが他のシステムコンポーネントと適切に連携して、特別なシステム設定なしに適切な場所またはネットワークサービスにログを記録できるようになる。

ロギングライブラリを使いたければ、特にJavaの世界にはLog4j, JCL, slf4j, logbackなど多くのものが存在する。私はslf4jとlogbackを組み合わせて使うのが好きだ。とてもパワフルで、設定も比較的簡単だ。(JMXで設定できたり、設定ファイルのリロードもできる)。

slf4jの最高なところは、状況にあわせてロギングのバックエンドを変えれるところにある。特にあなたがライブラリ書くときには、ライブラリの修正なしに、ライブラリを使ってくれる人がロギングのバックエンドを自由に選べるようになる。

また他の言語でもいくつかのロギングライブラリが存在する。例えばrubyには、Log4rやstdlib loggerやJordan Sisselのruby-cabinがある。

ロギングライブラリを使わない理由がCPU消費であれば、この記事は読み飛ばしてOKだ。確かにループの内部にログステートメントを入れてはいけないが、そうでもしない限り、その差なんて分からないだろう。

2.正しいレベルでログを出力する

最初のプラクティスにしたがえば、アプリケーションでログステートメント毎に異なるログレベルを使えることだろう。どのログレベルを使うべきかは、難しい仕事の1つだ。

いくらかのアドバイスを示そう。

TRACE: 本番環境でこれが使われていたら、コードスメル(不味い兆候)だ。これは開発時にバグを追跡するために使われるべきもので、バージョン管理システムにはコミットしてはならない。

DEBUG: プログラムで起こることは何でもこのレベルで出力してもよい。ほとんどはデバッグ時に使われるが、本番運用に入る前に必要そうなものだけ残しておいて、障害対応時にアクティブにできるようにしておくのがオススメだ。

INFO: ユーザ主導またはシステム固有のすべてのアクション(すなわち、定期的にスケジュールされた操作)をこのレベルで記録する。

NOTICE: 本番運用時にプログラムが実行されるときにこのレベルを使う。エラーと見なされないすべての把握しておきたいイベントを、このレベルで記録する。

WARN: エラーになる可能性のあるすべてのイベントをこのレベルで記録する。例えば、あるデータベース呼び出しがいつもより長くかかった場合や、メモリー内キャッシュの容量が限界に近づいた場合が該当する。そうすることで、アラートの自動化が可能になり、障害対応中に、障害発生前のシステムの動作を、より理解できるようになる。

ERROR: このレベルにはすべてのエラー状態を記録する。エラーを返すAPI呼び出しや、内部のエラーがこれに該当するだろう。

FATAL: 最悪、破滅の日を表す。これは実際のプログラムではあまり使わないようにしよう。ふつうこのレベルでログが書かれることは、プログラムの終了を意味する。例えばネットワークデーモンが、ネットワークソケットをバインド出来ないときに、このレベルでログを記録して終了する、なんてのがこのレベルの唯一の使い途だろう。

プログラムまたはサービスのデフォルトのログレベルは、まったく異なることがある。例えば、サーバアプリケーションは、通常INFOレベルで実行するが、デスクトップアプリケーションはDEBUGレベルで実行するのがふつうだ。アクセス権限のないコンピュータでは問題のトラブルシューティングが非常に困難なため、サポートやカスタマサービスを行う際に、ユーザにログレベルの変更を指示してから送信してもらうよりも、ユーザにそのままログを送ってもらうように要求する方がはるかに簡単だからだ。

もちろん、これは人それぞれかもしれないけれどもね。

3.正しいログカテゴリを採用しよう

最初のTipsで挙げたロギングライブラリでは、ログカテゴリを指定することができる。このカテゴリによって、ログメッセージを分類することができ、最終的にはロギングフレームワークの構成に応じて、ログをある方法で記録するか、全く記録しないかを決めることができる。

たいていの場合、Java開発者はカテゴリに完全修飾クラス名を使う。これはプログラムが単一責任原則(SRP)を守っていれば、比較的上手く機能するスキームだ。

Javaロギングライブラリのカテゴリは階層構造になっているので、例えばカテゴリcom.daysofwonder.ranking.ELORankingComputationは、上位レベルのcom.daysofwonder.rankingにもマッチする。これによって運用エンジニアが、このカテゴリの構成を指定するだけで、すべてのランキングサブシステムで動作するログ設定ができるようになる。同時に、必要に応じて子カテゴリのロギング設定を生成することもできる。

特定の状況のトラブルシューティングに役立つように、パラダイムをもう少し拡張できる。

(REST APIのように)ユーザからのリクエストに応答するサーバソフトウェアを扱っているとする。サーバがこのカテゴリ my.service.api.<apitoken> (apitokenはユーザ毎に与えられたもの)を使ってログに記録している場合は、my.service.apiカテゴリですべてのAPIのログを記録することもできれば、より詳細なログレベルとmy.service.api.<bad-user-api-token>カテゴリにして1人のAPI利用ユーザの振る舞いを記録することもできる。

もちろん、そのためにはログ設定をシステム実行中に変更できる仕組みが必要だ。

4.意味のあるログメッセージを出力する

これはおそらく最も重要なベストプラクティスであろう。プログラムの内部を深く理解していなければ解読できない暗号のようなログエントリほど厄介なものはない。

ログエントリのメッセージを決めるときは、非常時に何が起こったのかを理解しなきゃいけないんだけど手がかりはログファイルしかない、という状況を常に頭に思い浮かべておかなきゃいけない。

開発者がログメッセージを決めるときは、あるコンテキストを前提としていることが多いだろう。そのような状況だと、現在のコンテキストを推測しなきゃいけないようなメッセージを書きがちだ。残念ながら、そのログを読むときには、このコンテキストは存在せず、そんなメッセージは理解できないものになるかもしれないのだ。

この状況(WARNやERRORレベルの場合は特に重要)を解消するには、ログメッセージにリカバリの情報を追加するとよい。それが不可能ならば、その操作の目的と結果が何だったかだけでもメッセージに記録しよう。

また、前のメッセージの内容に依存するログメッセージもやめよう。前のメッセージが別のカテゴリまたはレベルでログに記録されていると、それらのメッセージが表示されない可能性があるからだ。さらに悪いことに、マルチスレッドや非同期環境では、別の場所(ずっと前の方)に現れることもある。

5.ログメッセージは英語にしよう

フランス人からの奇妙なアドバイスに思えるかもしれないが、私は英語はフランス語よりもずっと簡潔で、技術用語により適していると考えている。メッセージに50%以上英語のワードを含んでいるのに、フランス語でログを出力したいと思うだろうか?

私個人の感想はさておき、このプラクティスの背景にある本質的な理由は次のとおり。

英語はメッセージをASCII文字でログ出力することを意味する。ログメッセージに対してなにがなされるのか、どこかにアーカイブされる前にどのソフトウェアレイヤ、メディアで処理されるのかがわからないので、特に重要だ。メッセージが特殊なキャラクタセットやUTF-8を使っていると、最終的に正しく表示されないかもしれないし、最悪の場合、送信中に壊れて読めなくなる可能性がある。色んなキャラクタセットやエンコーディングの可能性があるユーザ入力をログに記録するのは、さらに問題だ。

アプリケーションを色んなユーザが使っていて、完璧にローカライズするためのリソースがないときは、英語が最適な選択肢だ。特定のものをローカライズする必要がある場合は、エンドユーザに近いインタフェースをローカライズするだろう(それはログエントリじゃないだろう)。

ログエントリをローカライズする場合は(例えばすべてのWARN、ERRORレベルのもの)、意味のあるエラーコードをプレフィクスとしてつけよう。これでユーザは言語に依存しないインターネット検索で、情報を探し出せるようになる。VMS OSでは、このような素晴らしいスキームがしばらく前から使われていたが、それは非常に効果的であることが今私にも理解できるようになった。このようなスキームを設計する場合には、APP-S-CODEまたはAPP-S-SUB-CODEのような形式が使える。

APP: アプリケーションの名前を3文字で表す

S: 重大度を1文字で表す(すなわち、D: Debug、I: Infoなど…)

SUB: アプリケーション補助的な分類

CODE: 問題のエラーに固有の数値コード

6.ログメッセージにコンテキストを付ける

役立たずのログメッセージはこんなものだ。

Transaction failed

や

User operation succeeds

や、API例外の場合だと

java.lang.IndexOutOfBoundsException

など。

正しいコンテキストがないと、これらのメッセージはノイズでしかない。障害対応時には、なんの価値も産まずただ空間所消費するだけだ。

コンテキストを加えれば、より価値のあるメッセージになる。

Transaction 236432 failed: cc number checksum incorrect

や

User 54543 successfully registered e-mail user@domain.com

や

IndexOutOfBoundsException: index 12 is greater than collection size 10

のように。

この最後のコンテキストの例では例外についての話だが、例外を伝播する場合は、障害対応しやすくするために、次のJavaの例のように現在のレベルに適したコンテキストで拡張するようにしよう。

code:java

public void storeUserRank(int userId, int rank, String game) {

try {

// ... deal database ...

} catch(DatabaseException de) {

throw new RankingException("Can't store ranking for uesr" + userId + " in game " + game + " because " + de.getMessage());

}

}

したがって、rank APIの上位レイヤのクライアントは、十分なコンテキスト情報でエラーをログに記録できる。コンテキストがメッセージでなく、例外自体のパラメータになっているとさらに良いだろう。

いくつかのJavaのロギングライブラリではMDCを使うと、コンテキストを維持する簡単だ。MDCはスレッド毎の連想配列だ。ログの各行にMDCの内容を常に出力するように、ロガーの設定を変更できる。アプリケーションがマルチスレッドで動作するときは、コンテキストを維持する問題の解決に役立つ。次のJavaの例では、MDCを使って特定のリクエストのユーザごとの情報を記録している。

code:java

class UserRequest {

//...

public void execute(int userid) {

MDC.put("user", userid);

// ... all logged message now will display the user=<userid> for this thread context ...

log.info("Successful execution of request");

// user request processing is now finished, no need to log our current user anymore

MDC.remove("user");

}

}

MDCシステムはAkkaのロギングシステムのような非同期ロギングスキームとは相性が悪いので注意しよう。MDCはスレッド毎の記憶領域に保持されるが、非同期システムでは、ログ書き込みを実行するスレッドがMDCを持つスレッドであるという保証はない。そのような状況では、すべてのログステートメントでコンテキストを手動でログ出力する必要がある。

7.機械でパースしやすいフォーマットでログを書く

ログのエントリは、人間にとっては非常に便利だが、機械にとっては不都合なことが多い。ログファイルを手動で読み取るだけでは不十分な場合があり、自動処理(警告や監査など)を実行する必要がある。ログを一元的に保存し、検索リクエストを実行できるようにしたいこともあるだろう。

では、このロギングステートメントのように、ログコンテキストを文字列に埋め込むとどうなるのだろうか?

log.info("User {} plays {} in game {}", userId, card, gameId);

これから、次のようなメッセージが作られる。

これをパースするには次のような正規表現が必要だ。(あ、これはテストしてないです)

/User (\d+) plays (.+?) in game (\d+)$/

コードがネイティブに知っている文字列パラメータにアクセスするだけでは、簡単ではなく、エラーが発生しやすくなってしまう。

機械で構文解析可能なフォーマットでコンテキストをログエントリに追加する仕組みを、Jordan Sisselがruby-cabinのライブラリで最初に導入した。前述の例では、JSONを次のように使用している。

ログパーサはずっと簡単に書けるようになるし、logstashのパワーもより活かせるようになる。

8.でも同時に人間にも読めるように

ログファイルは機械にパースしなすくあるべきだが、同時に人間にも読めるものであるべきだ。なぜだろうか。

簡単にいえば、人はログエントリを読む。それはおそらくストレスで疲れ切った開発者であり、欠陥のあるアプリケーションを障害対応しているときだろう。読みにくいログエントリを生み出して、彼らの生活を苦しめないようにしよう。

では、人間が読めるログにするにはどうすればよいのか。Scalyrブログにはそれをカバーする記事がたくさん載っているが、ここに主要なものを示す。

標準の日時形式を使う(ISO8601)

UTCまたはローカル時刻+オフセットのいずれかでタイムスタンプを追加する。

ログレベルを正しく使う。

異なるレベルのログを細かくコントールできるよう異なるターゲットに分割する。

例外のロギング時にスタックトレースを含める。

マルチスレッドアプリケーションのログは、スレッド名を含める。

9.多すぎず少なすぎず

ばかげているように聞こえるが、ログの量には適切なバランスがある。

ログが多すぎると、ログから値を取得するのが難しくなる。このようなログを見ると、ごちゃごちゃしていて、午前3時に運用上の問題を障害対応しようとしても上手くいかない。

ログが少なすぎると、障害対応できなくなる危険性がある。それは難しいパズルを解くようなもので、そのためには十分な材料が必要だ。

残念ながら、コーディング時に何を記録すべきかを知るための魔法のルールなんてものは存在しない。いたがって最初の2つのベストプラクティスを厳密に遵守することが非常に重要だ。そうすれば、アプリケーションが可動するときにログの饒舌さを容易に増減できるようになる。

この問題を解決するための1つの方法は、開発中に出来る限りログをとることだ。(プログラムをデバッグするために追加されたロギングとは違うので注意しよう)。次に、アプリケーションが本番運用に入ったときに、生成されたログを分析し、検出された問題に応じてログステートメントを減らしたり増やしたりしよう。特に障害対応時には、アプリケーションの中でより多くのコンテキストやログを取得したい部分に注意し、これらのログステートメントを次のバージョンで追加する。もちろんそれには運用担当者と開発担当者間のコミュニケーションが必要だ。

これは複雑な仕事だが、コードをリファクタリングするのと同じくらい、ログステートメントをリファクタリングするようにしよう。本番ログとそのようなログステートメントの変更とに密接なフィードバックループを設けるのが良い考えだろう。継続的デリバリのプロセスが確立されていれば、リファクタリングも継続的に行うことができるので、さらに効率的だ。

ログステートメントは、コードのコメントと同じレベルの、ある種のメタデータだ。したがって、ログステートメントとコードを同期させることが非常に重要だ。コードと関係のないメッセージを表示しても、トラブルシューティングには何の役にも立たないから。

10.誰がログを読むかを考えよう

なぜアプリケーションにログを書くようにするのだろう?

ある日、後日それを読まなきゃいけない人がいるから、というのが唯一の答えだ。さらに重要なのは、誰がそのログを読むのかを考えるということだ。これから書くログメッセージは、それを読む人によって、メッセージの内容、コンテキスト、カテゴリ、レベルは大きく異なる。

次のような人が該当する。

問題のトラブルシューティングするエンドユーザ(クライアントやデスクトッププログラムを想定)

システム管理者または運用エンジニアが運用上の問題のトラブルシューティングをする。

開発中にデバッグしたり、プロダクトの問題を解決したりする開発者。

もちろん開発者はプログラムの内部を知っているので、ログメッセージをエンドユーザに提示するときよりもはるかに複雑になる。だから、意図した対象者にあわせて言語レベルを調整し、ログカテゴリを分けたりする。

11.トラブルシューティング目的だけでログを出力しない

ログメッセージを様々な対象ユーザのために書かれるのと同様に、ログメッセージには様々な理由で使われることがある。トラブルシューティングがログメッセージの最も明らかなターゲットであるのは確かだが、以下の場合にもログメッセージを効率的に使うことができる。

監査: これは業務要件の場合がある。その目的は経営層や法務担当者にとって重要なイベントをキャプチャすることだ。これらは通常、システムのユーザが行っていること(誰がログインしたか、誰がそれを編集したかなど…)を記述する。

プロファイル: ログはその時刻が記録される(時にはミリ秒単位で)ので、プログラムのある部分をプロファイリングする良いツールとなる。例えば処理の開始と終了をログに記録することで、自動的に(ログを解析して)、または障害対応中に、プログラム自体にそれらのメトリックを追加せずに、いくつかの性能メトリックを推測することができる。

統計: 特定のイベントが発生するたびに(ある種のエラーまたはイベントのような)ログを記録すると、実行中のプログラム(やユーザの行動)に関する統計を計算できる。また連続して多数のエラーが発生していることを検出してアラートシステムが作動させることも可能になる。

12.ベンダーロックインを避ける

このTipsは、すでに最初のTipsで部分的にカバーされているが、もっと明確な形で言及する価値がある。

したがって、ここでのアドバイスは単純だ。特定のベンダーに縛られないようにしよう。必要に応じて、ロギングライブラリ、フレームワークを別のものと簡単にチェンジできるようにロギング戦略を考えるのだ。

どうやって、それをやるのか?

1つの方法はラッパーを使って、アプリケーションコードがサードパーティ製のツールを明示的に呼ぶのを避けることだ。そうせずに、適切なメソッドとそれを実装するクラスを持つロガーインタフェースを作ろう。次にこのクラスに、実際にサードパーティツールを呼び出すコードを追加しよう。そうすることで、サードパーティツールからアプリケーションを分離できる。別のものに置き換える必要がある場合は、アプリケーション全体で1箇所修正するだけで済むようになる。

このアプローチを簡単にするために、slf4jのようなログファサードを採用することができる。このプロジェクトではいくつかのロギングフレームワークに対して、標準化れた抽象化を提供しているため、相互に簡単に切り替えることができる。

13.機微な情報をログに出力しない

最後に、機微な情報はログに記録しないようにしよう。まず明らかな箇所、以下のものは絶対にログに出力してはならない。

パスワード

クレジットカード番号

社会保障番号

また以下は微妙かもしれないが、ログに記録すべきではないものだ。

オプトアウトしているユーザのセッション識別子

認可トークン

PII (個人識別情報)

また、うっかり法を犯してしまわないようにしなければならない。特定の情報を記録することを禁止する法律や規則がある。そのような規制の中で最も有名なのは多分GDPRだろうが、それだけではない。対象の国や地域の法規制を把握し、それに従うようにしよう。