外部API呼び出し時のログ設計：他のメンバーのログから学んだ実践的アプローチ

はじめに

こんにちは。バックエンドエンジニアの齋藤です。

ログを追加する時に、「調査しやすいように」「運用で役に立つように」ということは理解していますが、今回外部APIの呼び出し時に他の方がログを追加してくださり、実際にどういうことかとても勉強になりました。

もしかすると当たり前のことかもしれませんが、自分にとってはとても有益だったので、こういうことを出力すればよいのかとわかったことをメモしておきたいと思います。

ログレベルごとにみていきたいと思います。

ERRORログ

エラーの発生内容がわかり、ログ内容から調査を進められるようにする。

どこで起きたエラーか
内容（外部API呼び出しの場合は、レスポンスのステータスコードやエラーメッセージなど。内部でのエラーの場合もエラーメッセージなど）
外部API呼び出し時はエラー時に渡したリクエスト

上2つは今までもやっていましたが、3つ目もあると調査時に便利でした。

WARNログ

致命的ではないが注意すべきこと、今後問題になるかもしれないこと。

通常時でも発生しうるエラー（リトライなどで回復可能）が発生したという記録

Exceptionが起きたらエラーログにしてしまいがちですが、エラーだからといって全部ERRORログにする必要はないです。（むしろ問題がないのにERRORログが出てしまうと本当に問題の時に埋もれてしまう。）でもリトライで復帰可能なエラーでも発生したことは追えるようにしておいた方が傾向の把握などに役立ちました。

INFOログ

担当システムでは、通常INFOレベルまでログを出しているので、常に出力される。問題ではないが、調査に役立てられるものなど。

リクエスト内容
- 調査の時にあると助かる。
リトライの記録・リトライ回数・リトライ待ち時間
- API全体としては正常終了しているが、リトライが発生している時に、どれくらいリトライが発生しているか調べられる。API正常終了なのに内部的にはリトライが頻発している状況に気がついたりしやすくなる。
特に時間がかかりがちな外部API呼び出しのレスポンスタイム

どれくらい細かく出すかはログの保存容量や価格、注意して監視したい内容や外部APIのエラー率とも相談になりそうです。

DEBUGログ

本番環境では通常は出力されないログだが、エラー発生時やテスト時などにログレベルを変更して調査に使えるようにする。

外部APIのリクエスト・レスポンス内容
- 普段から全て出すと膨大な量になってしまうが、当該APIのエラー時の調査に役立つ。実際レスポンス内容はとても役に立った。エラーになる前から仕込んであるとログレベルを変更するだけで調査できて便利。
エラーに関して怪しい部分
- 今回は他のログの出力状況から序盤に落ちている可能性が高かったため、序盤の処理１行１行にログを仕込み、ログがどこまで出ているかで落ちている箇所を特定していた。
- 今回どこかの処理に時間がかかりタイムアウトエラーが発生していたため、外部APIのメソッドそれぞれにかかった時間を出力していた。

たまにしか発生しないエラーに関して、１行１行ログを出して、エラーが出たタイミングでリクエストID（一緒にログに出力）で絞って状況を特定する方法が効果的でした。ただ、膨大に出力されてしまうので、調査がひと段落ついたらログレベルを戻すのを忘れないように。