新年の私のブログにようこそ。監視とログのモニタリングについてのParisのdevopsメーリングリストでのスレッドに返信を書いた後、長らく心に留めていたブログ記事を思い出した。
このブログ記事は、私のOpsとしての顔をもって、主に開発者向けに書いた。
どのように何をロギングするかを知ることは、ソフトウェアエンジニアが解決すべき最高に難しいことの一つだ。多くの場合、これは予言をするのと同じようなことだからだ。トラブルシューティング中にどんな情報が必要かを知るのはとても難しい。それが、Opsエンジニアの大きな助けとなるよう、あなたのアプリケーションのログを拡張する手助けとなるこの「十戒」を望んだ理由だ。
1. 自分でログを書くべからず
printfを使ったり、自分でファイルにログエントリを書き込んだり、あるいはログローテートを手動でやってはいけない。オペレータにお願いして、一般的なライブラリを使うか、システムAPIコールを使ってやろう。
この方法なら、動いているアプリケーションは他のシステムコンポーネントとうまくやって、正しい場所あるいはネットワークのサービスに、特別な設定設定なしにログを書きこむことができるに違いない。
ここでシステムAPIを使うなら、それは syslog(3)
を意味することになる。使い方をおぼえるべし。
代わりにロギングライブラリを使いたいなら、Javaの世界には Log4j, JCL, slf4j, logback などがある。私のお気に入りは slf4j と logback の組み合わせで、これはとても強力で設定が比較的簡単だからだ(JMX の設定と設定ファイルのリロードもできる)。
slf4j の最高なところは、ロギングのバックエンドを自由に変更できることだ。ライブラリを書いている時はこれは特に重要だ。なぜなら、利用者はあなたの作ったライブラリに変更を一切加えずに、それぞれのロギングのバックエンドを使用することができるからだ。
他の言語にもいくつかのロギングライブラリが存在している。Rubyで言えば Log4r, stdlib logger そしてほとんど完璧な Jordan Sissel の Ruby-cabinだ。
あなたがロギングライブラリを使わない理由がCPU負荷なら、このブログ記事を読み飛ばしていい。確かに小さな内部ループ内にログ文を入れるべきではないが、その差に気付くこともないだろう。
2. 適切なレベルでログを出力すべし
あなたが最初の戒めを守るなら、アプリケーション内ではログ文ごとに異なるログレベルを使おう。難しいのは、そのエントリがどのレベルでログとして記録されるか決めることだ。
いくつかのアドバイスを提示しよう。
TRACE レベル : 本番環境で使うのはまずい(コードが臭い)。これはバグを見つけるために開発段階で使うべきで、VCS(バージョン管理システム)にはコミットしてはならない。
DEBUG レベル : プログラムで起こったこと何もかもをログに残す。多くの場合デバッグ中に使われるものだが、特に意味のあるエントリだけを残してトラブルシューティング中に有効にできるように、本番環境に投入する前にデバッグ分の数を減らしておくのもおすすめだ。
INFO レベル : ユーザによる動作あるいはシステム依存の全ての動き(例、定期実行される処理)をログに残す。
NOTICE レベル : 本番環境でプログラムを動かす時のレベルだ。エラーには分類されないが記録すべき全てをログに残す。
WARN レベル : エラーになる可能性のあるすべてのイベントをログに残す。例えば、データベースがある一定の時間を超えてコールされていたり、メモリ上のキャッシュ容量が上限に近くなった時である。自動化されたアラート通知を可能にし、トラブルシューティング時に、障害前にシステムがどのようにふるまっていたのかを理解する助けになる。
ERROR レベル : 全てのエラーをログに残す。エラーを返すAPIコールや内部エラーの状態などである。
FATAL レベル : 最悪な破滅の日。ほとんど使ってはならないし、本物のプログラム内でそんなにたくさん起きるべきではない。一般的には、プログラムの完了通知をログに残す。例として、ネットワークデーモンがソケットをバインドできない時、このレベルでログを残して終了するといったことが、唯一ありうる方法である。
留意すべきは、プログラムあるいはサービス内でのデフォルトのレベルは多種多様だろう。例えば、通常はINFOレベルでサーバコードを実行しているが、デスクトップのプログラムはDEBUGレベルで実行することもある。なぜなら、あなたがログインする権限を持たないコンピュータの上で起きたことをトラブルシュートするは非常に難しいが、サポートしたりカスタマーサービスがログを送るように依頼する方が、ログレベルを変更してからログを送るように依頼するよりは楽だからだ。もちろんこれは人に寄るが。
3. 汝のログカテゴリを尊重せよ
最初の戒めで紹介した多くのロギングライブラリは、ログのカテゴリを指定することができる。このカテゴリは、ログメッセージをクラス分けし、ロギングフレームワークの設定によって、最終的に明確な方法でログを残したり、何もログに残さなかったりする。
多くの場合、Java開発者はログの文がカテゴリ分けされたように見えるようFQDNを使う。これは、プログラムがシンプルな責任原則を大切にしている場合に特に有効なやり方だ。
Javaのロギングライブラリのカテゴリ分けは階層的で、例えばカテゴリ
com.daysofwonder.ranking.ELORankingComputation
のログは、最上位のカテゴリ com.daysofwonder.ranking
に属している。これにより、オペレーションエンジニアはこのカテゴリに対して設定をすることで、全てのランキングのサブシステムで動くログ設定をセットアップすることができるわけだ。
このパラダイムを、特定の状況でのトラブルシューティングをやりやすくするよう少し拡張してみよう。ユーザからのリクエストに応答するサーバソフトウェア(例えばREST
API)を扱っていることをイメージしてほしい。そのサーバがカテゴリ
my.service.api.<apitoken>
(apitokenはユーザから与えられる)でログを記録しているとすると、全てのAPIログを
my.service.api
カテゴリで記録することもできるし、とある不正をはたらいているAPIユーザを詳細なレベルでかつ
my.service.api.<bad-user-api-token>
カテゴリで記録することもできる。もちろんこれはその場その場でロギング設定を変更できるシステムでなければならない。
4. 意味のあるログを書くべし
これは戒めの中でも最も重要なものかもしれない。プログラム内部の深い理解を前提とした、暗号めいたログは何よりもひどいものだ。
ログメッセージを書く時は、何が起きているのかを理解せねばならず、唯一の手がかりはログファイルであるという緊急の事態が起きていることを念頭におくこと。これを正しくやっておくことは、クビになるか昇格するかの微妙な違いになりうる。
開発者は、ログ書き込み文が挿入されるコードを背景にログメッセージを書く。こういった状況下では、その時の文脈を含んだメッセージを書いてしまいやすい。しかし残念なことに、その背景がない時にログを読むと、これらのメッセージは理解不能なものになってしまう。
こういったことを克服する方法は(そしてこれはWARNやERRORレベルのログを書く時は特に重要だ)、改善のための情報をログメッセージに含めてやること、あるいはそこまでは不可能なら、オペレーションの目的とその結果を出力することだ。
また、前のメッセージの内容に依存したメッセージを表示してもいけない。前のメッセージが、違うカテゴリやレベル、あるいはマルチスレッドのためや非同期処理のために最悪違う場所(前)に記録されることもありうるからだ。
5. ログは英語で書くべし
これは、少しおかしな戒めに思えるかもしれない。特にフランス人が言うには。まず、私は英語はフランス語より簡潔で、技術的な言語としてふさわしいと思っている。半分以上英語の単語を含むのに、ログメッセージをフランス語で書かなければならないだろうか？
それは別にしても、この戒めの背景にある本質的な理由は以下の通りだ。
英語は、メッセージを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 2346432 failed: cc number checksum incorrect
や:
User 54543 successfully registered e-mail user@domain.com
あるいは:
IndexOutOfBoundsException: index 12 is greater than collection size 10
最後の例で例外について扱ったからには、もしあなたが例外を伝播することになったら、トラブルシューティングを簡単にするためにも、現在のレベルに適した背景を付加して拡張するのを忘れないように。Javaの例は以下の通り。
背景の伝播:
public void storeUserRank(int userId, int rank, String game) {
try {
... deal database ...
... データベース操作 ...
} catch(DatabaseException de) {
throw new RankingException("Can't store ranking for user "+userId+" in game "+ game + " because " + de.getMessage() );
throw new RankingException("ゲーム " + game + " 内でユーザ " + userId + " " の情報を保存できません。原因は " + de.getMessage() );
}
}
これで、ランクAPIの上位レイヤのクライアントは、十分な背景情報を含んだエラーをログに残すことができるだろう。メッセージの代わりに例外そのもののパラメータを使うとなおよいだろう。この場合、上位層では必要なら修正に使うこともできる。
背景を保持する簡単な方法は、Javaのロギングライブラリ実装であるMDCを使うことだ。MDCはスレッド単位の連想配列だ。ログの各行にMDCのコンテントを表示するために、ロガーの設定は変更可能である。あなたのプログラムがスレッド単位のパラダイムを採用しているなら、これは背景を保持するのに役立つだろう。以下のJavaの例は、リクエストごとにユーザの情報をMDCを使ってログに残すものだ。
MDCの例:
class UserRequest {
...
public void execute(int userid) {
MDC.put("user", userid);
// ... all logged message now will display the user=<userid> for this thread context ...
// ... このスレッドに関しては全ログメッセージに user=<userid> が表示される
log.info("Successful execution of request");
// user request processing is now finished, no need to log our current user anymore
// ユーザリクエスト処理完了、ユーザ情報を表示する必要はなくなる
MDC.remote("user");
}
}
MDCシステムは、Akkaロギングシステムのような非同期ログの仕組みではうまく動かないことに注意しよう。MDCはスレッドごとのストレージエリアに保持されており、非同期システムにおいては、MDCが保持されているスレッドがログ書き出しも行うという保証がないからだ。このような場合には、各ログ文に対して手動で背景を付け加えてやる必要がある。
7. ログはコンピュータがパースできるフォーマットで出力すべし
ログエントリは人間が読むには非常によいが、機械に処理するのはとても不得意なものだ。手動でログファイルを読むには不十分な時もあるだろうし、自動処理(たとえばアラート通知や監査など)が必要なこともあるだろう。あるいは、ログを集約して保存したり、検索リクエストに応えられるようにすることもあるだろう。
以下の仮のログ文にログの内容を埋め込んだときにはどうなるだろうか。
パースが難しい例:
log.info("User {} plays {} in game {}", userId, card, gameId);
これは以下のようなテキストを出力する。
パースが難しい例:
2013-01-12 17:49:37,656 [T1] INFO c.d.g.UserRequest User 1334563 plays 4 of spades in game 23425656
ここで、この文をパースしたいなら、以下のような正規表現が必要になるだろう(未テスト)。
パースが難しい例:
/User (\d+) plays (.+?) in game (\d+)$/
これは、あなたのコード内でネイティブに分かっているパラメータにアクセスするだけにしては、簡単ではないし、エラーが起きやすい。
というわけでこのアイディアについて、私は Jordan Sissel が彼の書いた ruby-cabin ライブラリで最初に採用された、ログエントリに機械がパース可能なフォーマットでログの内容を埋め込む方法を信じている。前述の例は以下のようにJSONを使って表現できる。
パースが難しい例:
2013-01-12 17:49:37,656 [T1] INFO c.d.g.UserRequest User plays {'user':1334563, 'card':'4 of spade', 'game':23425656}
これでログパーサはより簡単に書き込みができ、インデクシングは分かりやすくなって、logstashの力を十分に発揮できるようになる。
8. ログは長すぎず短すぎないものにすべし
これは間抜けに聞こえるかもしれないが、ログの量には適切なバランスというものがある。
多すぎるログは、そこから十分な価値を得るのが本当に難しくなってしまう。そういったログを手動で追う時、午前3時に本番環境での出来事をトラブルシュートするような場合に無駄な情報が多すぎるのはよいことではない。
少なすぎるログでは、問題をトラブルシュートできない危険性がある。トラブルシューティングは難しいパズルを解くようなもので、解くためには十分な情報が必要だ。
残念ながら、何をログに残すようにコーディングするかについての魔法のルールは存在しない。それゆえ、アプリケーションが動いている時にログの詳細レベルを上げたり下げたりできるように、1番目と2番目の戒めを厳格に守ることが非常に重要である。
この問題を克服する一つの道は、開発の際にログを出来るだけ多く出すことだ(プログラムをデバッグするためにログを出すことと混同しないように)。こうして、アプリケーションが運用に入った時、出力されたログを分析しよう。そして、発見された問題に応じて、ログの文を減らしたり増やしたりしよう。特にトラブルシューティングの間には、より多くの背景やログを得られるようにアプリケーションの部分を記録しておき、次のバージョンにそのログ文を追加するのを忘れないように(可能なら問題を記憶にとどめておくために同時に直してしまうこと)。もちろんその際にはOpsとDevsの間のたくさんのコミュニケーションが必要だ。
これは複雑なタスクだが、コードをリファクタリングするのと同じぐらい、ログ文もリファクタリングすることをおすすめする。この狙いは、本番環境のログとログ文の変更の間での密接なフィードバックのループだ。あなたの属する組織が継続的デリバリのプロセスを整えているなら、リファクタリングが持続的に行われるのと同じくより効果的になるだろう。
ログ文は、コードのコメントと同じレベルで、コードのメタデータの一種である。コードとログ文を同期させておくことは非常に重要なことである。トラブルシューティングの際に、実行中のコードと何の関係もない見当違いのメッセージが出てくるほどひどいことはない。
9. ログの読み手のことを考えるべし
なぜアプリケーションにはロギングが必要なのか？
その唯一の答えは、誰かがある日読まなければならなくなるからだ。重要なことに、誰がログを読むかを考えることは興味深い。あなたが書こうとしているログメッセージを読むと想定される人によって、ログメッセージの文、文脈、カテゴリやレベルは違ってくるだろう。
想定される人とは
- 自分自身のためにトラブルシュートするエンドユーザ(クライアントあるいはデスクトップ用プログラムを想像しよう)
- 本番環境での問題をトラブルシュートする、システム管理者あるいはオペレーションエンジニア
- 開発中のデバッグ、あるいは本番環境での問題解決をする開発者
もちろん、開発者はプログラムの内部を知っているのだから、彼らにとってのログメッセージは、エンドユーザに向けたものよりも複雑になるだろう。ログを読むと想定される人に対する言語を決めたら、そのカテゴリ分けについても注意を向けるべきではないだろうか。
10. トラブルシューティングのためだけのログにするべからず
ログメッセージが異なる対象に向けたものになるように、異なる理由に使われることもある。トラブルシューティングは確かに最も明白なログメッセージの目的ではあるが、他にも以下のような有用な使い方があるはずだ。
監査 : ビジネス上の要求から必要なことがある。マネジメント上、あるいは法律家が扱うような重要なイベントを補足しておく意味がある。そのシステムのユーザが何をしているかを記述する文が必要だ(例えば、誰がログインしたか、誰が編集したか、等々)。
プロファイリング : ログにはタイムスタンプ(時にそれはミリ秒単位のレベルで)が付けられており、プログラムの位置をプロファイリングする便利なツールになり得る。例えば、オペレーションの始まりと終わりにログを仕掛ければ、プログラム自身に仕組みを備えなくても、(ログをパースすることで)パフォーマンスを推測することもできる。
統計 : 特定のイベント(ある種のエラーなど)が発生するたびにログを記録するようにしておけば、実行中のプログラム(あるいはユーザの行動)の興味深い統計情報が取れるだろう。これは、連続した大量のエラーを検知してアラートを発報するような使い方も可能だ。
結論
このエントリが、より有用なログを出すことの一助となることを願っている。そして(あなたにとって)重要な戒律が抜けていたらどうか我慢してくれ。いや、このブログを読んだ後に、あなたのログがさらに良くならなくても責任を負わせるつもりはないけれど :)
この十戒が十分でないこともあるかもしれない。だから、より有用な情報を付け加えるため、コメント欄を活用してほしい(あるいはTwitterやあなた自身のブログでもいい)。
ありがとう。
