サービス運用をしていくうえで、ログはとても重要です。
どういった操作がされているのか、どういったことが起こっているのか。運用しているサービスを調べる方法として、「実際のデータを確認すること」と「ログを確認すること」しかできません。
「データを確認する」ことは、問題があった時に原因が分からず、どうにかして確認するための最終手段となります（個人情報を含むようなサービスであれば、そう簡単には見ることができないでしょう…）。
ということは、サービス運用の視点も踏まえたログ出力を心掛ける必要があります。
では、実際にログを取得しないといけない状態になったと仮定しましょう。どういったことができると 楽ができる(早く見つけられる) でしょうか。
追跡しやすいログ出力にする意味
ログを確認する時、多くの場合は下記の流れになると思います。
- 「何かが発生した時間」で絞り込み
- その出力内容と同じ処理であるログ出力がどれかを探す
- どういう流れでどういう処理が実行されたのかを確認
この中で一番大変なのが、「2」になります。
もしも「操作しているユーザーが一意」 且つ 「複数人で同じユーザーを同時に利用できない」場合は、そのログ上に「ユーザーの識別子」が出力されていれば、すぐに見つけることができるでしょう。
しかし、原因箇所と同じ処理か否かを再度確認する必要 と、上記の前提ではない場合、さらに絞り込む必要があり、大変な作業となります。
このようなことがないように、ログの出力内容として 「操作の始め～操作の完了」の中で同じ値を出力する という方法を取ります。
そうすれば、「1」で見つけた該当のログから、その値でさらに絞り込みをするだけで、すぐに確認をすることができるというわけです。
マイクロサービスアーキテクチャーを採用していた場合、 分散トレーシング という考え方にも関連しています。
（アーキテクチャーに関わらず、採用されることが多い考え方だと思います）
実現方法
「一連のログの中で同じ値」 且つ 「全てのログの中で固有な値」 を、ログに出力する必要があります。
「トレースID」や「リクエストID」と呼ばれるようです（どちらも同じ目的で利用されます）。
では、その値をどうやって渡していくと良いでしょうか。
- 「Request Parameter」, 「Request Body」 に項目として追加する
- 「Request Header」に「X-*」(カスタムヘッダー) として追加する
- 「Request Header」に「traceparent」「tracestate」に追加する
- gRPC通信の場合、「metadata」に追加する
モノシリック(一つだけで稼働している)サービスであっても、マイクロ(複数が連携している)サービスであっても、上記のいずれかの実現方法の方が良いと思います。
つまり、外部から渡してもらう形式です。
理由は、後に記載する「気を付けたいこと」に関連します。
traceparent と tracestate
「Request Parameter/Body」で渡すのは最終手段とした方が良いと思います(そもそも共通処理で出力しますし、リクエスト項目として渡すとノイズとなる可能性が高くなります)。
ですので、「Request Header」で渡す方法になりますが、(あまり気にする必要はないかもしれませんが)カスタムヘッダーは非推奨となっているため、
W3C が勧告している項目の「traceparent」「tracestate」を採用した方が良いかもしれません。
実現時の注意点
Access-Control-Allow-Headers の設定や、悪意のある値が送信されるリスクも考慮する必要があります。
目的を踏まえると、「最大文字列長」や「使用可能な文字種」のチェックのみで良いと思います（メタ情報に分類される内容のため、厳密なチェックをしてしまうことで逆に使い辛くなります）。
気を付けたいこと
「どこまでを始めとするのか」「どこまでを一連の操作として取得したいのか」を意識することです。
一般的で一番多いパターンは「1回のリクエスト（1回の実行）」かと思います。しかし、それだけではないことも考えないといけません。
具体例
「二段階認証/二要素認証」を例に考えてみます。
通常、「1. ログイン情報を入力 & 送信」→「2. 入力情報が妥当であればレスポンスし、追加の認証を求める」→「3. 追加認証情報を入力 & 送信」→「4. 認証結果をレスポンス」の流れかと思います。
この時、全てを一回の検索条件で取得できるようにしたい場合は、それらの処理ログの中で同じ値を出力してもらう必要があり、それが実現できるような基盤実装が必要になるでしょう。
Nginx のアクセスログも一緒に取得する
アクセスログを取得する場合、 nginx.conf の http > log_format の内容を、今回のheader の内容を出力するように書き換える必要があります。
Nginx 内の変数としての参照方法として「$http_*」「$sent_http_*」「$upstream_http_*」があるため、うまく利用して出力させます。
最後に
今回は、追跡がしやすいログ出力を実現する方法をまとめてみました。
「追跡しやすいログ出力」を実現するための実装は、基盤開発で行われることが多く、多くの人が何となくで使うことが多いものです。
また、カスタマイズがしやすい利点を取り入れることによって、問題になり得るリスクも同時に息をひそめます。
目的を知らないまま、適当に利用することによってやりたいことが実現されず、修正が必要となる場面にならないことをお祈り致します。
新規開発をする人、また、改善をするために頑張ろうとしている人の力になれれば幸いです。
参考
- https://openresty.org/download/agentzh-nginx-tutorials-en.html#02-nginxdirectiveexecorder01
- https://nginx.org/en/docs/http/ngx_http_core_module.html#variables
- https://stackoverflow.com/questions/12431496/nginx-read-custom-header-from-upstream-server