ログのタイミングと情報量: 処理の流れを完全に再現するために
何のためのログか
常時稼働しているソフトウェアシステム(Webサービスなど)を運用している開発現場なら、問い合わせ対応や障害調査は日常茶飯事のように起こるのではないでしょうか。すでに終わった処理をあとから振り返るためには、当時の情報が残ってなければならない。その手がかりが十分にあると、想像や推測を交えずに、事実だけで「その時、システムが、何をしていたか」が説明できるようになります。
筆者はログのことを、
完了した処理をあとから再現するために、残っていなければならない事実
と考えています。
処理を再現するための適正な情報量を求めて
極端な話、処理中のあらゆるところで現状を記録したログを出してしまえば、十分すぎるほどの事実が残るでしょう。そうしないのは、
- コード内がロギングの操作に埋め尽くされ、本来のロジックが埋もれて分かりにくくなってしまう
- いざログを読む場面になってみると、ノイズが多すぎてかえって精査するのに時間がかかってしまう
などのデメリットが大きいと考えられます。
一方で、ログをまったく出さなかったら何も追えないので、適正な情報量はそのあいだのどこかにあると容易に考えられます。
ここで一旦脱線して、コードの基本的な構成要素である「関数」の性質について考えてみようと思います。
実行するたびに結果が変わる関数、実行しなおしても結果が変わらない関数
いかなる関数も、
- 実行するたびに結果が変わる(可能性を秘めている)関数
- 実行しなおしても結果が変わらない関数
のうちのどちらかである。
func Fibonacci(i uint) uint {
if i == 0 || i == 1 {
return i
}
return Fibonacci(i-1) + Fibonacci(i-2)
}
なら何があっても Fibonacci(7) == 13
が成立するが、
func GetAccount(id string) (Account, error) {
// SQLを発行してレコードを取る
// select * from accounts where id = {入ってきたid}
//
// 見つからなかったらerrorを返す
// 見つかればレコードをAccountに変換して返す
}
なら、データベースの中身次第で GetAccount(42)
が成功する場合もあれば失敗する場合もあるし、初回の GetAccount(42)
が失敗したあとにレコードが挿入されれば二回目の GetAccount(42)
は成功する。
このように、実行するたびに結果が変わる関数は、
- 関数内のコードが一切変わらなくても
- 関数呼び出し時に渡される引数が同一でも
- 関数より外の要因から影響を受けて、実行するごとに結果が変わる可能性がある
という性質を持っています。
同じ類のものとして、
- 現在時刻を返す関数
- ランダム値を生成する関数
- ファイルの中身を読み取る関数
などがあげられます。
これが純粋関数(実行しなおしても結果が変わらない関数)と非純粋関数(実行するたびに結果が変わる関数)の違いで、その違いがログの出力方針に大きく関わってきます。
詳しくは「純粋関数」「非純粋関数」「副作用」などのキーワードで検索してみてください。
純粋関数のログ、非純粋関数のログ
純粋関数は引数が確定すれば戻り値が確定する。なので、純粋関数を通る処理を再現するためには、引数だけログに残っていれば十分(再実行により戻り値を計算することができるため)。
非純粋関数は実行時の状況によって出力が変わる。当時起こったことはあとから復元できる保証はないので、入出力ともにログに残す必要がある。
ユーザー・システム間の一回のやりとりから始まるロギング
システムはユーザーからの指示を受けて動き出す。システムには、ユーザーとやりとりをするための入り口がたくさんついていると考えることができます。
その入り口に立つ関数(例えば、REST APIの一つのオペレーション)を例に、ロギングがどう展開されていくのかを説明していきたいと思います。
入り口の関数は純粋関数、非純粋関数を交互に呼んでいるという考え方
プログラムは関数と関数が呼び合って成り立つ。入り口の関数は、中でより粒度が細かい関数を呼び出していると考えることができます。呼ばれる関数については、純粋関数・非純粋関数のどちらかになるので、ここでは便宜上交互に呼び出しているとします(どの枠にも空の関数が入る場合がる、と考えることができるため)。
この構成でどこにログを出すべきかを考えてみましょう。
処理開始のタイミング
ユーザーによって提供された入力値は復元できないので、ログに出す。
最初の純粋関数に入るタイミング
入力は処理開始のタイミングですでにログに出ているので、ここでは改めてログに出さない。
最初の純粋関数を出るタイミング
純粋関数という性質により、出力も確定しているので、ログに出さない。
最初の非純粋関数に入るタイミング
入力はここまでで出ている情報から復元できるので、ログに出さない。
最初の非純粋関数を出るタイミング
実行時の状況下でしか観測できない情報なので、ログに出す。
次の純粋関数に入るタイミング
入力は前の段階ですでにログに出ているので、ここでは改めてログに出さない。
これより先
ここからは同じパターンが繰り返し出てくるので割愛。
ログのタイミング: まとめ
ここまでのことをまとめると、
- ユーザーによって提供された入力値
- 非純粋関数の出力値
この二種類の情報をログに残しておけば、あとから処理を再現するための手がかりがそろう、ということができます。
より細かいレベルへ
ここまでは、システム・ユーザー間のやりとりを支える入り口の関数を取り上げて話してきました。同じような考え方を、もっと細かいレベルの非純粋関数に適用させることもできます。
純粋関数は純粋関数をしか呼び出せないので、純粋関数の塊に対してログを出す必要がない。
秘密な情報をログに出せないとき
ユーザーによって提供された入力値はログに出すべきと話していましたが、パスワードやトークンなどの秘密な情報はセキュリティの観点からして出さない方が望ましいでしょう。
センシティブな情報を省略したことで不完全な情報しかログに残せなかった場合、
- 純粋関数は入力が不確かになって再実行できなくなったので、非純粋関数と同様に扱う
- 非純粋関数はもともと再実行することを想定していないので、特に対処を変える必要はない
というような状況になります。
Further Reading
この記事の考え方は、筆者が Code That Fits in Your Head から感銘を受けて自分なりに解釈を加えたものになります。
Discussion