「ロギングにおける十戒」を読んで
たまたま検索に引っかかった記事が面白そうだったので読んでみた感想文。
1. 自分でログを書くべからず
printfを使ったり、自分でファイルにログエントリを書き込んだり、あるいはログローテートを手動でやってはいけない。オペレータにお願いして、一般的なライブラリを使うか、システムAPIコールを使ってやろう。
自分でログ機構を実装しないでエコシステムに乗りましょうという話。 最近はJVMアプリのロギング周りを追っているけど、確かにslf4jのインターフェイスと実装を分ける設計は合理的に感じる。
いま関わっているプロジェクトでも自作ロガーが使われており、エコシステムに乗れなくて辛い思いをしている…
2. 適切なレベルでログを出力すべし
当たり前のようで意外と守れていないことが多い気がしている。
最近自分が見たのは、バッチ処理の開始・終了をWARNレベルで出力しているところ。
これはログレベルが間違っているのは明白であるが…
NOTICE レベル : 本番環境でプログラムを動かす時のレベルだ。エラーには分類されないが記録すべき全てをログに残す。
ここでの説明に従うなら、NOTICEレベルを使うのだろうけど、slf4jにはNOTICEレベルはないので、どう表現するのが正しいのだろうか?
Markerをうまく使って表現するのがいい?
3. 汝のログカテゴリを尊重せよ
多くの場合、Java開発者はログの文がカテゴリ分けされたように見えるようFQDNを使う。これは、プログラムがシンプルな責任原則を大切にしている場合に特に有効なやり方だ。
なんとなくクラスのFQDNを渡していたけど、あれはカテゴリ分けの意図があるのかと気づきを得られた。
そういえばLogbackもパッケージ階層ごとに振る舞いを変えられるような設計になっていたなと。
(前述の自作ロガー、ロガー名をひとつに潰すような実装になってたので、そこは直さなきゃいけないなと感じた…)
4. 意味のあるログを書くべし
これは本当に大事だと自分も思う。
このログを読んだ人はどう思うのか…という気遣いが大切なのかも。
また、前のメッセージの内容に依存したメッセージを表示してもいけない。前のメッセージが、違うカテゴリやレベル、あるいはマルチスレッドのためや非同期処理のために最悪違う場所(前)に記録されることもありうるからだ。
このあたりはMDCあたりが助けてくれそうな気がする。
5. ログは英語で書くべし
「読み手は日本人だし、ログは日本語でいいでしょう」と思っていた自分からすると、これには少し驚きがあった。
英語は、メッセージをASCII文字でロギングすできる。ログメッセージがどう扱われるか本当の所は分からないし、どこかにメッセージがアーカイブされる前にどんなソフトウェアレイヤやメディアを経由するかも分からないので、これは特に重要だ。
言いたいことはわかるものの、emojiの流行でマルチバイト文字に強くなってきた(?)昨今ではあまり気にならない気がしているけどどうなんだろう…。
ログの文(例えばWARNとERRORレベル全部など)をローカライズするなら、以下のような特定の意味のあるエラーコードを接頭辞としてつけることを忘れないようにしよう。これにより、ユーザは言語に関係なくインターネットで検索して、情報を見つけることができる。
何かしらのサービスでREST APIを使う時によく見る方法だけど、確かにこれは良さそうだ。社内アプリケーションなどでも役立ちそう。
6. ログは背景を持つべし
正しい背景なしには、これらのメッセージは雑音でしかない。これらは、何の価値も持たず、トラブルシューティングに有用なスペースを消費してしまう。
4と似通った話? ごもっともである。
背景を保持する簡単な方法は、Javaのロギングライブラリ実装であるMDCを使うことだ。
最近、Sentryを利用するところでMDCを知ったけど、引用通りに便利だなと感じている。
その一方で非同期処理が多くなるScalaだと取り回しが難しい…
kamon-logbackがそのひとつの解決策だと思っているけど、Kamon自体ちゃんと触れてないので追々やっていきたい…
7. ログはコンピュータがパースできるフォーマットで出力すべし
ログエントリは人間が読むには非常によいが、機械に処理するのはとても不得意なものだ。手動でログファイルを読むには不十分な時もあるだろうし、自動処理(たとえばアラート通知や監査など)が必要なこともあるだろう。
ログにJSONを組み込むあたりはログ解析をちゃんとやろうとしたときに必須になりそうな気がする。
ちゃんとしたログ解析をやったことないので何とも言えないけど…
8. ログは長すぎず短すぎないものにすべし
多すぎるログは、そこから十分な価値を得るのが本当に難しくなってしまう。そういったログを手動で追う時、午前3時に本番環境での出来事をトラブルシュートするような場合に無駄な情報が多すぎるのはよいことではない。
このあたり、最近は自分もよく悩んでいる気がする…。
ついつい色んなデータを取りにいきたいと思ってしまう。
また、ログ出力したいデータを取得するのにビジネスロジックが圧迫されてしまうのもいま個人的に感じている課題だ。
これはたぶん、Sentryにログを出力するときに一度にまとめて情報を送りつけようとしているせいかもしれない。
Sentryだけで原因がわかるのが一番ではあるがそれも難しい。
ログの持つデータは適切な場所で吐いてやるのが正しいのかなと感じた。
9. ログの読み手のことを考えるべし
・自分自身のためにトラブルシュートするエンドユーザ(クライアントあるいはデスクトップ用プログラムを想像しよう) ・本番環境での問題をトラブルシュートする、システム管理者あるいはオペレーションエンジニア ・開発中のデバッグ、あるいは本番環境での問題解決をする開発者
「誰が」ログを読むのか、という点はつい忘れがちなので気をつけたい…
10. トラブルシューティングのためだけのログにするべからず
監査 : ビジネス上の要求から必要なことがある。マネジメント上、あるいは法律家が扱うような重要なイベントを補足しておく意味がある。そのシステムのユーザが何をしているかを記述する文が必要だ(例えば、誰がログインしたか、誰が編集したか、等々)。
プロファイリング : ログにはタイムスタンプ(時にそれはミリ秒単位のレベルで)が付けられており、プログラムの位置をプロファイリングする便利なツールになり得る。例えば、オペレーションの始まりと終わりにログを仕掛ければ、プログラム自身に仕組みを備えなくても、(ログをパースすることで)パフォーマンスを推測することもできる。
統計 : 特定のイベント(ある種のエラーなど)が発生するたびにログを記録するようにしておけば、実行中のプログラム(あるいはユーザの行動)の興味深い統計情報が取れるだろう。これは、連続した大量のエラーを検知してアラートを発報するような使い方も可能だ。
ここまで辿り着くには上記の戒めを守るのが必須であり、長い道のりになるんだろうなと感じる…。
(今関わっているプロジェクトではトラブルシューティングに使えるログを吐けてるかも怪しい…)
ロギングの世界はとても奥が深いなぁと思わせてくれる読み応えのある記事だった。
つい影に隠れがちな技術だけど、プロファイリングやAPMなどより、一番手軽な「可視化」の手段なんだなと思い直した。
自分達の行いを省みさせてくれるツールとして、もっともっとロギングのいろはを学んでいきたい。