「トレースに出てこない」と報告されたとき

一言でいうと

スパンがない理由は4つなのに症状は1つなので、推測で直さず、リクエストの記録とダンプを突き合わせて、原因ごとに異なる痕跡で切り分ける必要があります。

なぜ必要なのか

報告は、いつも同じ文で来ます。「この注文番号でトレースを探したのですが、出てきません」。その1文から始めて、2日を費やしたことがあります。最初の2日は、サンプリングの設定を疑いました。比率を上げて1日待ちましたが、報告はそのまま入ってきました。次にエクスポーターを疑ってバッチサイズを大きくしましたが、それも違いました。3日目にログとダンプをリクエスト識別子で突き合わせて初めて、なくなっているのはすべて1つの経路のリクエストだとわかりました。

振り返ると、初日にできたことでした。自分たちがしなかったことは2つあります。1つ目、何件がないのかを数字にしませんでした。「見えない」という言葉だけを頼りに動いたため、直したあとも良くなったかどうかがわからず、同じ疑いを2回しました。2つ目、ないもの同士の共通点を見ませんでした。全部がないのと、1つの経路だけがないのとでは原因がまったく違うのに、その区別をしないまま、全体の設定をいじりました。

どう動くのか

診断は4歩です。突き合わせて一覧を作り、共通点で絞り込み、候補を除外し、残ったものを確認します。

第一歩はないもののリストです。アプリケーションのログにはリクエストが1行ずつ残っていて、スパンダンプのサーバースパンには、同じリクエスト識別子が属性として付いています。2つの集合の差を求めると、「ログにはあるのにダンプにはないリクエスト」が出てきます。この数字があって初めて、あとの話がすべて本物になります。

第二歩は絞り込みです。ないリクエストを経路別に数え、時間帯別に数えます。1つの経路に集中していればその経路の処理コードを見ればよく、時間帯に集中していればその時刻に何があったかを見ればよく、均等に散らばっていれば全体の設定を見る必要があります。この表1枚で、調査範囲が10分の1に減ります。

第三歩が除外です。候補は4つあり、4つがダンプに残す痕跡はそれぞれ異なります。

候補の原因	ルートスパン	子スパン	ないリクエストの分布
サンプリングで落ちた	ありません	ありません	散らばっています
スパンを終了しなかった	ありません	残っていて、親を指しているが、その親がダンプにありません	散らばっています(たいてい1つの経路)
プロセスが先に終了した	ありません	ありません	ログの末尾から連続しています
親コンテキストが途切れた	あります	残っているが、別のトレースのルートになっています	ないリクエストがありません

サンプリングと早期終了は、どちらも何の痕跡も残さないため、ダンプだけを見ても区別できません。切り分けるのは分布です。サンプリングは全区間に散らばってしまい、プロセスが落ちると、その時刻以降が丸ごとなくなります。終了しなかったスパンは、正反対にとてもはっきりした痕跡を残します。子は出力されたのに、その子が指す親がダンプのどこにもありません。親コンテキストが途切れた場合は、まったく別の症状です。ないリクエストは1件もないのに、リクエスト識別子が付いたスパンが1つもないトレースが別に浮いています。画面では「トレースにスパンが1つだけ」と見えます。

第四歩は、同じ判定をスクリプトに固める作業です。人が毎回表を描くと、次の報告のときにまた2日かかります。ルールを順序まで決めてコードに書いておけば、次の人はコマンド1行で同じ答えを得られます。ルールに順序を付ける理由は、痕跡が重なることがあるためです。終了しなかったスパンは「リクエスト識別子のないトレース」も一緒に作り出すので、親コンテキストの判定より先に見る必要があります。

サンプリングが正確に何を捨てるのか、子がなぜ親の決定に従うのかは、サンプリングの概念ドキュメントにまとまっています。プロセスが終わる前に出力する作業がなぜ明示的な呼び出しなのかは、Trace SDK仕様のForceFlushとShutdownの節にあります。親コンテキストが入ってきて出ていく規格は、W3C Trace Contextが原本です。

ここで扱わないことをはっきりさせておきます。欠陥のあるSDKの配線を見つけて直す作業は、SDKライフサイクルのモジュールの役割です。このモジュールが教えるのはその前です。複数の原因のうちどれなのかを、データで見分ける手順であり、成果物は直したコードではなく、分類表と診断スクリプトです。

この環境で判定できないことも書いておきます。ラボのPodにはOpenTelemetry Collectorもトレースバックエンドもありません。そのため、バックエンドの画面でそのトレースがどう描かれるか、コレクターが途中で何を捨てるかは、ここでは確認できません。見るのは、SDKが出力したスパンをそのまま書き出したJSONLダンプと、サービスが残したログの2つだけで、判定はすべてその2つの突き合わせで行います。

現場での姿

最もよく見るのは3つ目です。バッチ処理や短いコマンド型のプログラムで、最後のリクエスト数件がいつもなくなるのに、報告は「ときどき抜ける」と入ってきます。ログと突き合わせると、なくなっているのがいつも末尾側であることがすぐにわかります。散らばっていないという事実1つで、サンプリングの候補がすぐに消えます。

2番目によく見るのは4つ目です。キューのワーカーやコールバックの中でコンテキストを渡さないと、その中のスパンが新しいトレースのルートになってしまいます。なくなったものがないので、突き合わせ表には何も引っかからないのに、人々は「トレースが半分しかない」と報告します。このとき数えるべきなのは、ないリクエストではなく、リクエスト識別子のないトレースです。

次のラボですること

報告された事案1つの証拠2枚(リクエストログとスパンダンプ)を題材に始めます。まず突き合わせてないリクエストを数え、経路別・時間帯別に分けて、どこに集中しているかを見ます。次に、4つの原因を自分で再現して、それぞれがダンプに残す痕跡を確認し、その違いを分類表にまとめます。まとめたルールを診断スクリプトに移して事案に実行し、最後に、原因が異なる2つ目の事案に同じスクリプトを実行して、異なる答えが出ることを確認したあと、調査記録を残します。