この記事は、FIXER Advent Calendar 2020　22日目の記事です。

アプリケーション作るとき障害調査を想定してログを残します。
なにも意識せずにログを残したとき、後で追いにくくてしょうがない。
そんなことはありませんか？私はいつもです。

ログの出力する手法なんかはいったんスルーで、今回はどういう観点でログを残すかというところでまとめていきたいと思います。

ログを残すとき、いつ起きたか 何が起きたか を忘れる人はさすがにいないかと思います。
いつ のほうはミドルウェアが付与してくれたりするのでアプリで出力しない方が多いでしょうか。

2020-12-22 10:55:00.000 Error HogeHogeの保存に失敗しました。

どこで起きたか なぜ起きたか これたまに忘れる人います。
最低限、例外情報をそのまま出すくらいはしないと直接原因探るのもなかなか大変になります。

2020-12-22 10:55:00.000 Error HogeHogeの保存に失敗しました。 ex: HogeException: message. at Hoge.Main(String[] args) in Hoge.cs:line 12

割と忘れがちなのが 誰が起こしたか 。
ユーザーIDを出力するだけなのですが、処理によっては引数に含まれない情報なので、画一的に出す内容としては割と忘れがち。

2020-12-22 10:55:00.000 Error ユーザー[FugaFuga] HogeHogeの保存に失敗しました。 ex: HogeException: message. at Hoge.Main(String[] args) in Hoge.cs:line 12

そして今回の主題とでもいうべき内容、これがないからこそ追いにくいログになっているであろう
どのようにして起きたか
これに注目したいと思います。

他の5Wはログ出力する瞬間の情報なのに対して、
どのようにして起きたか については発生するまでの処理が必要な情報になります。

少し昔の仕組みだと、スレッドIDを出力したりして、どのスレッドがどういう処理をしていたかを追うことで
どのようにして起きたか を追う実現していたりしていました。

2020-12-22 10:55:00.000 Error スレッド[1234] ユーザー[FugaFuga] HogeHogeの保存に失敗しました。 ex: HogeException: message. at Hoge.Main(String[] args) in Hoge.cs:line 12

昨今の処理だと async await な非同期処理が各所に実装され、あまり意味のない情報になってしまっています。

そこで、リクエストごとに一意なIDを定めて出力することで、このログは同一のリクエストをということを表すことで、どのようにして起きたか を追うことを考えました。
ASP.NET Core では HttpContext.TraceIdentifier という値で用意されています。

2020-12-22 10:55:00.000 Error TraceId[0HM51L4EUTF91:0000000] ユーザーId[FugaFuga] HogeHogeの保存に失敗しました。 ex: HogeException: message. at Hoge.Main(String[] args) in Hoge.cs:line 12

これを出力しておくことで、エラーで出力されているログのTraceIdをGrep検索で取得することで、そのエラーが起こるまでのログを確認し、どのようにして起きたか を追えるようにしました。

他にもログレベルやログIDを管理したり、出力内容をコントロールできるようなこと考えたり、出力されたログをどう管理・表示していくかなど、考え始めると奥が深い世界です。
ただ出力するだけではなく、どう使うかまで想像してログを出力しましょう。