flushの成功と受信の成功の間

一言でいうと

計装は、呼び出し1回ではなく、複数の境界の連続です。例外を記録したこととエラーとして表示したこと、スパンを終了したことと出力したこと、レシーバーが受け取ったこととストレージで照会できることを、それぞれ確認する必要があります。

なぜ必要なのか

短時間で実行される注文検証ジョブがあります。ジョブはエラーを捕捉してレスポンスに変え、最後にforce_flushを呼び出して、成功したかどうかをログに残します。ログにはTrueが出力されましたが、観測画面にはリクエストがありません。この状況で「観測画面が遅れている」と結論づけると、開いたままのスパンを終了していない欠陥や、送信が拒否された事実を見逃すことがあります。

このラボの事前実験では、実際のPython SDK 1.44.0と公式のOTLP/HTTPエクスポーターを使いました。自前のレシーバーがHTTP 200と400で応答するようにして、比較しました。エクスポーターの結果はSUCCESSとFAILUREで異なりましたが、providerのforce_flushは、どちらの場合もTrueでした。以下の説明はこの観測に基づいており、すべての言語・バージョンが同じ返り値を返すと一般化することはしません。

どう動くのか

例外イベントとエラー状態は別である

Pythonコードで例外を捕捉して処理すると、その例外はwithブロックの外へ伝播しないことがあります。この場合、自動のコンテキスト管理が何を記録するだろうと推測せず、現在のスパンに残ったイベントと状態を、それぞれ確認してください。今回のラボは、start_spanで作ったスパンで、捕捉した例外を処理するので、自動のコンテキスト管理の動作とは混ざりません。

from opentelemetry.trace import Status, StatusCode

try:
    validate_order()
except ValueError as error:
    span.record_exception(error)
    span.set_status(Status(StatusCode.ERROR, "order validation failed"))

record_exceptionは、調査用のイベントを残します。ERRORは、この処理をどの状態に分類するかを決めます。事前実験で、イベントだけを記録したスパンはUNSET状態で、状態を別途指定したスパンだけがERRORでした。イベント検索では見えるのに、エラー率や状態フィルターからは漏れているなら、この区別が役に立ちます。

捕捉した例外のすべてが、必ず処理の失敗を意味するわけではありません。正常な代替経路で回復したなら、業務上の意味に合った状態を選ぶ必要があります。この課題では、注文検証の失敗を最終的なエラーとして分類すると明示したため、ERRORを求めます。SDKの呼び出し方法を暗記することと、どの業務結果にその呼び出しを適用するかを判断することは、別の学習です。

span.endとforce_flushの順序

バッチプロセッサーは、終了したスパンをためて出力します。まだ進行中のスパンの情報を勝手に完結させて出力すると、実際の処理時間や最後のイベントが間違うことがあります。したがって、開いたままのスパンを残してflushしても、そのスパンが自動で終了するわけではありません。

span.end()
flush_result = provider.force_flush(timeout_millis=3000)

事前実験では、開いたスパンを残した最初のflushはTrueでしたが、受信したリクエストは0個でした。そのあとスパンを終了して再度flushすると、1個が到着しました。最初の返り値は、開いた処理を完了したという証拠ではありませんでした。「出力するものがなくて終わった」と「目的のスパンを送って終わった」を区別しないと、短い処理でデータが消える原因を見逃します。

force_flushは、普段すべてのスパンごとに無条件に呼ぶ関数として暗記するものではありません。一般的なサービスではバッチ処理を活用し、短時間の実行やプロセスが中断されうる境界で、待機と終了のポリシーを設計します。このラボは、境界を短時間で再現するために、直接flushを使っています。バッチ処理の性能比較や、高負荷の運用指針を検証したものではありません。

5つの異なる成功

観測ポイント	その事実から言えること	まだ言えないこと
span.end以降の終了観測	スパンが終了したこと	送信されたこと
エクスポーター呼び出し	出力を試みたこと	レシーバーが受理したこと
エクスポーターのSUCCESS	当該エクスポーターが成功として処理したこと	永続保存・最終的な照会が可能であること
受信器の受理記録	実験用の受信器がリクエストを受理したこと	別のバックエンドに転送・保存されたこと
対象ストレージでIDによる照会	そのストレージで該当データが見えること	すべてのスパンが漏れなく保持されたこと

HTTP 400の実験では、リクエスト本文がレシーバーまで到着しました。そのため、receivedのスパン一覧だけを数えると1個です。しかし、レシーバーはリクエストを拒否したので、accepted_spansは0で、エクスポーターの結果はFAILUREです。本文の到着を成功と定義してしまうと、まさにこの反例を見逃します。ラボでdelivered関数は、レシーバーの受理を判定するよう求められ、永続保存の保証としては使いません。

この区別は、ログ・メトリクス・メッセージキューにも当てはまる考え方です。関数の返り値、ローカルキューへの挿入、ネットワーク送信、相手の受理、最終処理の完了のうち、どの地点を見て成功と言ったのかを、先に書いてください。システムごとに返り値の契約が違うため、単語が同じだというだけの理由で、成功の範囲をそのまま当てはめてはいけません。

service.nameはどこに入れるか

スパンの一般属性にservice.nameを書くことと、Resourceのservice.nameを設定することを、区別してください。Resourceは、そのシグナルを作ったサービスを説明します。ラボでは、2つの異なるサービス名で呼び出すので、例の文字列を1つコードに固定すると、1つのケースだけ合って、もう1つのケースは間違います。

受信したprotobufで、service.nameだけでなく、trace IDも一緒に照合します。名前が合っている別のリクエストを、現在のリクエストの成功と誤認しないためです。「画面に何かができた」という確認を、「自分がいま送ったリクエストがこの境界を通過した」という確認に絞り込む練習です。実際のサービスでは、このときに使う識別子の保管やアクセス権限も管理する必要があります。

現場での姿

バッチジョブの終了直前に観測データが消える障害を調査するなら、3つの質問から始めます。すべてのスパンを終了したか、終了の境界でexporterが実行される機会があったか、その試行の結果と受信側の結果は何か、です。単に待ち時間を延ばすだけで終わらせず、どの境界のデータが変わるかを比較する必要があります。

もう1つの落とし穴は、テスト終了時の後片付けです。テストのfinallyでprovider.shutdownを呼ぶと、欠落していたデータが、あとから送信されることがあります。そのデータを受講者のコードの成功に合算して数えると、flushを忘れたコードも合格してしまいます。今回の採点では、受講者の関数の直後の観測をコピーし、そのあとでリソースを片付けます。片付けの処理は必要ですが、正解の代わりにしてはいけません。

次のラボですること

専用環境にSDKとエクスポーターがあらかじめインストールされています。外部サービスやAPIキーは必要ありません。8つのステップで、接続、サンプリング、親ポリシー、例外、終了、受信の判定、サービスの識別、総合レポートを、順に直します。各ファイルをrunで実行すると、実際の観測と失敗の条件を一緒に見られます。採点はコードのコピーで実行し、現在のファイルを変更せず、前のステップの準備も、すでにある途中までの答案を上書きしません。

公式の基準: Python計装、OTLPエクスポーター。