フツーって言うなぁ!

フツーなサラリーマンのフツーな嘆き.

Web APIのログ設計についての私見

かなり放置してしまいましたが,久しぶりに気分が乗ったのでブログを書いてみています.

最近は仕事でSpring Frameworkを使って何度かWeb APIを開発しているのですが,その度に毎回同じようなことを悩んでいる気がするので,次に開発する自分に向けて,ちょこちょここちらにまとめておこうと思います.

結構私見が混ざりそうなのでこちらのブログで.

今回はログについてです.

注意事項

  • 対象は,DBや他のAPIと通信して結果を返すタイプの一般的なRESTful APIを想定しています.
  • 業務領域はちょっとカッチリ目のWeb系です.
  • 特定のWebフレームワークには依存しないように書いたつもりですが,見返してみると若干Spring Frameworkに寄ってるような気もします...

ログ設計の観点

そもそもですが,Web APIのログってどんなものがあればいいのでしょうか?

仕様面の観点としては,

  1. 障害発生時にできるだけ早く運用者に通知されるようになっているか?また,ログから障害の原因を追跡しやすいか?
  2. APIクライアントからの問い合わせなど,日常運用に際して使いやすいか?もう少し具体的に言うと,そもそもログの中から問い合わせの対象となるリクエストを見つけやすいか?また,ログの内容から問い合わせを解決するための手がかりをつかみやすいか?
  3. 業務量(QPS)やリクエストの実行時間を把握しやすいか?
  4. 開発時に起こった問題の原因を追いやすいか?(要するにデバッグログ)
  5. その他,開発者/運用者/ログ分析者が知っているとよい情報を適切なタイミングで表示しているか?

があるかなぁと思っています.

要するに,使いやすいログを設計しましょう,ということです.

また,性能面の観点としては,

  1. ログの出力がAPIの性能に大きく影響しないか?
  2. ログによってシステムの他の構成要素に影響がないか?

といったところも重要です.

何も考えずたくさん出してしまうとログ追跡も難しくなりますし,ログ出力そのものがAPIの負荷の原因になったり,ログを吐き出しすぎてディスク溢れを起こしてしまったりするケースもあります.

これらの観点を鑑みて,私は以下のようにログを設計しています.

ログ設計

ログ分割と各ログの役割

以下の4つのログをファイルの形でAPIサーバに配置しています. その後,fluentd等のログ集約ツールで適宜集約サーバに送信するようにしています.

(以下,ログレベルはSLF4Jのものを基準としています)

SLF4J

request.log

APIが受けたリクエストを記録するログ.

HTTPのリクエストパス,クエリ文字列,リクエストボディ,リクエストヘッダ(,クッキー),リクエスト元のIPアドレスを記録します.

特に,何らかのバグによって途中でレスポンスが返らないまま処理が終了してしまう場合も考えて,できるだけ早いタイミングでログを記録することが重要です.

ログレベルはINFO.

response.log

APIが返したレスポンスの内容と,リクエストの処理にかかった時間(経過時間)を記録するログ.

HTTPのステータスコード,レスポンスボディ,レスポンスヘッダ,経過時間を記録します. アクセス量の調査については,基本的にこのログを利用します.

加えて,

  • APIのID(呼ばれたAPIを一意に識別するID)
  • ユーザのID(あれば)
  • ユーザが認証済みかどうか(認証済みユーザにのみコンテンツを開示する場合など)
  • APIクライアントのID(あれば)

あたりを別に記録しておくと,ログ検索の際の利便性が上がると思います.

ログレベルはINFO.

application.log

APIの内部ロジックにて,開発/運用に必要な情報を記録するログ.

いわゆるアプリログ.

ログレベル 観点
TRACE 基本的に使用しない.開発時に本当に必要になったときのみ.
DEBUG デバッグの際に必要な情報を記録する.DEBUGレベルのログは本番環境で出力することを想定しない.「開発/デバッグ時にはいつも必要になるが本番には出したくないログ」のみを残し,開発中にだけ必要だったものなどは本番投入前に消しておくようにするとよい.例えば,DBに接続する際の接続情報や,APIロジック内での処理件数,経過時間など.
INFO 本番運用に際して有用な情報を記録する.INFOレベル以上のログはすべて,本番環境で出力することを想定する.不要な情報はできるだけ削ぎ落とし,本当に必要な情報のみを出力するようにする.特に,毎リクエストごとに出力されるログについては吟味し,request.log/response.logに入れられないかを検討する.例えば,バックグラウンド処理が起動/停止したことを示す情報や,APIの設定項目が更新された際の通知など.
WARN 「即時の対応が必要ではないが,運用者にすぐに通知されるべき警告」を記録する.自動電話の対象とはしないが,メールやSlackなどのメッセージングツールなどで運用者がすぐに把握できるようにはしておく.例えば,APIが想定しない入力が受け付けた場合や,(マッシュアップAPI等で)一部の外部APIの呼び出しがエラーを返した(がAPI全体には大きな影響がない)場合など.
ERROR 「運用の継続を阻害しており,即時の対応が必要なエラー」を記録する*1.エラーの詳細(例外のスタックトレースなど)がわかるようにしておく.アラートの対象であり,自動電話等で夜間帯でも即時対応できるようにしておく.例えば,APIの業務ロジックが想定しない例外を送出した場合や,メモリやディスクの枯渇によってAPI自体の状態が不安定になった場合など.

stdout.log

フレームワークが吐き出すログの内容をリダイレクトして記録するログ.

多くのWebフレームワークでは,フレームワーク側で実行した内容のログを標準出力に出力する設定になっていると思うので,それを記録しておきます.

ログレベルは出力したログに依存します.

気をつけるべきところ

ファイルフォーマット

プレーンテキストで記録してもいいのですが,一度集約サーバに送ってしまうと目視で確認する機会がほぼなくなってしまうので,プログラムで処理しやすい形式が良いかと思います. 個人的にはJSON形式がおすすめです.

ちなみに,ロギングにLogbackを利用しているのであれば,logstash-logback-encoderを利用することで,いい感じ(Logstash形式)にフォーマットしてくれるので,ELKで扱いやすいです.

GitHub - logstash/logstash-logback-encoder: Logback encoder which creates JSON for use with Logstash

JSONを使う場合でも,例えば開発時には目視しやすい方が楽かと思うので,必要に応じてフォーマットを変更しやすいようにしておくとよいかと.

リクエストID

ログごとにファイルを分割すると問題になるのが,どのログがどのリクエストに紐付いているのかわからなくなる点です. 例えば,request.logから同じリクエストに紐づくresponse.logを探すことができなくなります. このため,各ログには,リクエストごとに(ほぼ)*2一意になるIDを付与するようにしています.

ちなみに,ZipkinやJaegerなど,OpenTracing APIに対応するトレーサーを利用しているのであれば,IDとしてTrace IDの値を使うとよいかと思います.

時刻

ログの中でいちばん大事なのは,そのログを取った時刻の情報だと思います. もちろん要件次第だと思いますが,普通のAPIであれば,精度はmsecぐらいあれば十分かと思います.

時刻のフォーマットについては,ISO 8601の基本形式か拡張形式のどちらかを使っておけばいいと思います.

ISO 8601 - Wikipedia

私はよくuuuu-MM-dd'T'HH:mm:ssSSSXXX (E.g., 2018-10-27T22:17:35.213+09:00)のフォーマットを使っています.

ログローテーション

サーバのディスク容量には限りがあるので,ログがディスクを圧迫しないようにすることは重要です. 多くのロギングライブラリには,日別や日時別でログファイルを分割して古いファイルを圧縮,削除するログローテーション機能があるので,それを使うとよいと思います.

忘れがちですが,ログが溢れないかどうか,開発時に負荷試験で調べておくことも重要です.

ある程度信頼性を犠牲にしていいなら,ファイルを介さず直接TCP等で集約サーバに送ってしまう,という手もあるかと思います*3

リクエスト元のIPアドレス

リクエスト元のIPアドレスについては,(他にAPIクライアントを識別するための情報があれば必須ではないものの,)どのAPIクライアントのどのサーバがAPIを呼び出しているかを把握していると障害対応が楽になるため,できれば取得しておきたい情報です.

様々な取得の方法がありますが,APIクライアントと取り決められるなら取り決めた方法で,特にそういうものがないなら,

  1. X-Forwarded-Forヘッダが存在する際は,その値を,(カンマとスペース1つ)で分割した際の最初の要素(ロードバランサやリバースプロキシを経由するなどしてIPアドレスの付け替えがあっても対応できるので*4) 2.X-Forwarded-Forヘッダが存在しない場合は,REMOTE_ADDR(前段の呼び出し元IPアドレス

を取得するとよいかと思います.

X-Forwarded-For - Wikipedia

参考記事

qiita.com

7.1. ロギング — TERASOLUNA Server Framework for Java (5.x) Development Guideline 5.4.1.RELEASE documentation

www31.atwiki.jp

*1:RESTful APIであれば,APIクライアントにはステータスコード5XXを返すことになる.その際,レスポンスにエラーの詳細を記載するとセキュリティ面で問題があるため,問題が発生している旨のみ記述して残りはマスクしておくとよい.

*2:もし衝突してもちょっと探すのが面倒になるぐらいなので,あまり一意であることにこだわりすぎなくてもよいかと.

*3:最近はこちらの方が主流なんでしょうか...

*4:厳密に言うと,ヘッダの値は改ざん可能なので信頼できる値ではないけれど.