trace IDはあるのにスパンがない理由

一言でいうと

スパンの識別子があること、内容を記録すること、エクスポーターへ渡したことは、それぞれ別の事実です。3つの事実を分けて確認すれば、「計装コードを入れたのに見えない」という問題を、推測ではなく観測で絞り込めます。

なぜ必要なのか

注文APIにトレーシングを入れました。開発者はログでtrace IDを見つけ、コードにもstart_spanがあります。ところが、観測画面には何もありません。このときコレクターを再起動するのは、複数ある原因のうちの1つを、証拠なしに選ぶ行為です。実際には、providerにprocessorを接続していなかった、サンプラーがスパンを捨てた、スパンを終了していなかった、といったことが考えられます。エクスポーターまで渡されたあとで、受信サーバーが拒否した場合もあります。

このモジュールは、その境界のうちSDKの内側を扱います。前のラボのようにOTLP JSONを手で作るのではなく、公式Python SDKが生成したスパンを、実際のプロセッサーとエクスポーターに送ります。エクスポーターの手前で見える情報と、実際のHTTP受信の結果を一緒に見ます。プログラムがエラーなしで終了したという事実だけで、データが届いたと判定することはしません。

どう動くのか

API、SDK、provider、processor、exporter

アプリケーションの計装コードは、APIを通じてスパンを作ります。SDKのTracerProviderは、サンプラー・リソース・プロセッサーのような実行設定を所有します。tracerを取得しただけで、送信経路が自動的に完成するわけではありません。どのプロセッサーが終了したスパンを、どのエクスポーターへ渡すかも決める必要があります。最初のラボでは、この接続の1か所を、わざと空けておきました。

from opentelemetry.sdk.trace.export import SimpleSpanProcessor

provider.add_span_processor(SimpleSpanProcessor(exporter))
tracer = provider.get_tracer("orders.instrumentation")

ここでのtracerの名前は、計装ライブラリの範囲を区別するための名前です。サービスの名前を決めるservice.nameとは、同じ位置づけではありません。2つの値に偶然同じ文字列を入れることはできますが、役割まで同じになるわけではありません。最初から値を区別しておけば、複数のライブラリが1つのサービスを計装する場合でも、出所を読み取れます。

記録とサンプリングの3つの組み合わせ

次は、このラボの公式SDKとデフォルトのエクスポート用プロセッサーで観測できる結果です。processorでの観測は、スパンが終了したあとの呼び出しを指します。

決定	記録中か	sampledビット	processorに到着	exporterに到着
DROP	いいえ	オフ	いいえ	いいえ
RECORD_ONLY	はい	オフ	はい	いいえ
RECORD_AND_SAMPLE	はい	オン	はい	はい

RECORD_ONLYが特に重要です。「記録する」という名前から、送信までされると読みやすいですが、実際の実験では、プロセッサーの終了観測だけがあり、エクスポーターのスパン一覧は空でした。メモリの中で情報を観察する目的と、リモートへ送るデータの量を決める目的は、分離できます。この表を暗記するだけで止まらず、受講者のコードで決定を1つ変えて、どの一覧が増えたり減ったりするかを実行してみてください。

サンプリングで内容が捨てられても、有効なスパンコンテキストがあることがあります。したがって、ログのtrace IDは検索の手がかりであって、保存されたスパンが必ずあるという保証書ではありません。逆に、スパンを終了したあとでis_recordingがfalseになったという事実も、最初からDROPだったという意味ではありません。状態を観測した時点まで書いておいてはじめて、2つのケースを区別できます。

ParentBasedのrootは、トレース全体のスイッチではない

ラボで作るポリシーは、親のないリクエストは記録せず、親のあるリクエストは、その親のsampledの決定に従うものです。ParentBased(root=ALWAYS_OFF)がこのポリシーを表現します。rootがオフでも、sampledのリモートの親から来た子は記録されます。rootオプションを「すべてのスパンをオフにする設定」と解釈すると、正常な子まで欠落と診断することになります。

逆に、ParentBased(root=ALWAYS_ON)だからといって、unsampledの親の子が自動的にオンになるわけではありません。rootサンプラーは、親がない場合の決定です。リモート・ローカルの親、sampled・unsampledの組み合わせには、それぞれの分岐があり、デフォルトでは親の決定に従います。今回の課題は、リモートの2つのケースとローカルの2つのケースをすべて実行して、1つのヘッダーでたまたま合っていた実装を、ポリシー全体の正解とは認めません。

親がオフなら、子も絶対にオンにできないのか

いいえ。事前実験で、ALWAYS_ONと、明示的に変更したリモートの親ポリシーは、unsampledの親と同じtrace IDを持つsampledの子を作りました。親の決定に従うのはサンプラーのポリシーであり、識別子そのものが子の記録を禁止するわけではありません。Pythonの公式のsampling APIも、always_onとparentbased_always_onを区別しています。

ただし、これは、すでに捨てた親の内容が復元されたという意味ではありません。親が記録しなかった属性・イベント・時間区間は、そのまま存在しません。子スパン1つを観察できるようになったことと、リクエスト全体のトレースが完全になったことを、区別する必要があります。現場で「サンプリングを強制的にオンにしたから、これで全体が見えるはずだ」と期待すると、別の種類の誤診が始まります。

現場での姿

普段はrootのトラフィックの一部だけを収集しているサービスに、外部パートナーのリクエストが入ってくる場合を考えてみてください。パートナーがすでにsampledのコンテキストを送ってきた場合とそうでない場合は、同じrootの比率設定だけを見ても説明できません。リクエストで受け取ったコンテキストが有効か、リモートとして解釈されたか、選択されたサンプラーが親の決定に従うかを、順に確認します。

原因がSDKのサンプリングかどうかを調べるには、collectorのログだけを増やすより、SDKプロセッサーの前後の数を比べるほうが早いことがあります。開始・終了の観測がどちらもなければ、生成経路とサンプリングを見ます。終了の観測はあるのに出力がなければ、sampledとプロセッサーの接続を見ます。すでに出力が確認できたなら、そこから送信の境界に移ります。観測する場所を1つずつ移していくと、無関係なインフラの変更を減らせます。

ラボのデータは、実際の顧客情報ではなく、合成された注文です。productionでも、エラー調査のために、注文の原文・認証ヘッダー・個人情報を、無条件にスパン属性として入れてはいけません。必要最小限の識別子と状態だけでも、処理経路を区別できるかどうかを、先に考えてください。

続けて確認すること

次の理論では、例外イベントとスパンの状態、スパンの終了とflush、受信と保存の境界を区別します。そのあとのラボは、説明に合うPython関数を自分で修正する方式です。合格表示を出すためだけの文字列ではなく、実際のSDKの観測結果が採点基準です。

公式の基準: Tracing SDK、Python sampling API。