結論

端的に言えば5W1Hを徹底した文章を書くと良いのでしょうね。

エラーログの責務

日々漫然とエラーログを出力していませんか？私はしがちです。

エラーログの責務が何かを考えたとき、エラーの原因特定だという認識におそらく齟齬が生まれる方というのは少ないのではないでしょうか。

ただ、テストを書いたりクラスの責務を考えながらコードを書くのを面倒に感じる場面があるように、習慣づけていないとエラーメッセージを丁寧に推敲することなく書いてしまったり、そもそも書き漏れのケースがあると思うのです。

とはいえ、エラーメッセージをいい加減に書くとデバッグコストが上昇するし、コンテキスト依存のバグを特定したいのにリクエストに紐づいた値が全く出力されていないと、途方に暮れるだけで根本対応ができずじまいになってしまいます。

よくないエラーログ

「うちは一応エラーログを書いているよな」と思うチームでも、ログを見てすぐに原因を推察してアクションを起こせるくらいになっているかと言われると微妙なのではないでしょうか。完全にブーメランなのですが。

エラーログを書いている気になっていて、全くアクションに役立たないのは、

[ERROR] failed to fetch user data

みたいなログでしょう。

こういったログは、例えそのエラーが発生した行が一緒に出力されていても、原因特定の助けになりません。なぜなら「現象」を報告しているだけで「調査材料」を一切報告していないからです。

例えばpanicログとかもある種それに該当すると思います。経験上nilなのに関数呼ぼうとしてたり、存在しないindexを参照しようとしてたりするケースが多いんですが、「なんでこの値がnilになったのか」を推測できない時点でエラーログが不足している状態だと言えます。

あと、個人的にはスタックトレースが表示されているからOKみたいな考え方にはそこまで共感できないです。トレースを読んで実装の中身を脳内で展開できないと原因ができない時点で、調査タスクが強く属人化してるからですね。

よいエラーログ

じゃあ良いエラーログとはなんなのか。冒頭にも書きましたが5W1Hとそれに付随するわずかな情報が網羅的に盛り込まれているかだと思います。

• When: リクエストの発生時刻
• Where: エラー発生行、当該スコープの関数名、サーバーの識別子
• Who: ユーザーID、Trace ID、IPアドレス(から割り出される地域情報など)
• What: コード内におけるユースケース情報、HTTPのpath名など
• Why: 予測可能な範囲での原因候補を表した文章
• How: 処理の呼び出し方。引数や操作対象のオブジェクトの情報

大まかに上記のような情報が含まれていれば割と短時間で原因調査できるのではないでしょうか。

5W1Hですねと書いた手前、「Whyを推測したいのにWhy埋めなきゃいけないのしんどいな」と思いながら書きました。

[ERROR] reqtime=1600760016, line=xxx.go:L12, trace_id=yyy, path=/me, scope=repository.GetUserByID, options={"user_id":"test"}, msg="failed to fetch user, err: record was not found"

くらいまで書いてあれば、「あーDBに入ってないIDでユーザー参照しようとしたな」くらいはわかると思うんですよ。

When、Whatあたりの情報はLTSVの表記でアクセスログを出力していれば、ある程度紐付けできると思います。

一方で、実装者でないと考慮できないWhyやHowあたりの情報はコードにコメントを残すようなノリでエラーメッセージに書いておいてあげると、チームの助けになって良いんじゃないかなって思ったりします。

皆さんはこの辺どうやってますか？