リトライしたリクエスト1件をいくつのスパンで描くか

目標

リトライを1つのスパンに入れたときにダンプが何を失うかを自分で見て、試行ごとにスパンを作ってエラーを正しい場所に付けたあと、同じデータからスパン基準のエラー率とリクエスト基準のエラー率がどれだけ開くかを計算します。最後に、そのルールをリンターで固めて、ルールを破ったダンプを検出します。

なぜ重要なのか

リトライはほぼすべてのサービスに入っていますが、トレースにどう描くかは、ほとんど誰も決めていません。1つのスパンの中で静かに繰り返すと、どの試行がどれだけかかったか、何が原因で失敗したかが丸ごと消え、残るのは「このスパンが長くかかった」だけです。逆に、試行ごとにスパンを作ってもエラーをどこにでも付けてしまうと、スパンで数えたエラー率がユーザーが経験した失敗の2倍以上に膨らみ、ダッシュボードが嘘をつきます。外側のスパンはユーザーが経験した1つの出来事であり、試行スパンは上流に実際に出ていった1回の呼び出しである、という2つの層を分けておけば、どの数字をどこで数えるべきかは自然に決まります。捕捉した例外をどのAPIで残すかはSDKライフサイクルのモジュールの役割で、ここで決めるのは、スパンを何個に分け、どこにエラーを付けるかです。

ステップ

/root/tp-retry/one_span.pyを作成してください。ダンプのパスは環境変数TRACELAB_OUTから先に読み、なければ/root/tp-retry/01-one.jsonlを使います。provider("shop-api", OUT)でトレーサーを取得してchargeスパンを1つだけ作り、その中でupstream.call("charge", 시도번호, idempotency_key="ord-7781")を成功するまで繰り返します(失敗したらupstream.backoff_s(시도번호)秒だけ待ちます。プレースホルダーはどちらも試行番号です)。プログラムの最後にflush()を呼んでください。そのあと/root/tp-retry/01-lost.txtに2行を書きます。attempts=の後ろには、実際に何回試行したかを整数で、lost=の後ろには、このダンプからはわからなくなったものが何かを40文字以上で書いてください。
/root/tp-retry/attempts.pyを作成してください。デフォルトのダンプのパスは/root/tp-retry/02-attempts.jsonlです。外側のchargeスパンはそのままにして、試行ごとに子スパンcharge.attemptを作り、整数属性retry.attemptに何回目の試行か(1から)を書きます。待機は試行スパンの外で行います。実行すると、ダンプにスパンが4個(外側が1+試行が3)入っている必要があります。
/root/tp-retry/error_place.pyを作成してください。デフォルトのダンプのパスは/root/tp-retry/03-error.jsonlです。失敗した試行スパンには、ステータスをERRORに設定し、文字列属性error.typeにexc.kindを書きます。成功した試行スパンのステータスには手を触れません。外側のchargeスパンは、最後にステータスをOKに設定します。ユーザーが経験した結果は成功だからです。
/root/tp-retry/rates.pyを作成してください。デフォルトのダンプのパスは/root/tp-retry/04-rates.jsonlで、4つの作業charge・quote・ship・notifyを順に処理します。作業ごとに外側のスパン<작업>.requestと試行スパン<작업>.attemptを作り(プレースホルダーは作業名です)、試行は最大3回までにします。最後まで失敗した作業の外側のスパンはERROR、成功した作業はOKです。そのあと/root/tp-retry/04-rates.tsvに、タブで区切った4つの欄の2行を書いてください。1行目はspan_level、2行目はrequest_levelで、欄は<id> <오류 수> <전체 수> <비율>(プレースホルダーは順に、エラー数、全体数、割合です)です。span_levelはダンプのすべてのスパンを数え、request_levelは親のないスパンだけを数えます。割合は小数第4位までです。
/root/tp-retry/backoff.pyを作成してください(デフォルトのダンプのパスは/root/tp-retry/05-backoff.jsonl)。chargeだけをもう一度処理しますが、待機を終えるたびに外側のスパンにイベントretry.backoffを追加し、そのイベントにretry.attempt(整数)とbackoff.ms(ミリ秒)を付けます。最後に、外側のスパンの属性retry.backoff_ms_totalに、待機時間の合計をミリ秒で書きます。そのあと/root/tp-retry/05-gap.txtに2行を書いてください。backoff_total_ms=の後ろに記録した合計を、uncovered_ms=の後ろに、外側のスパンの長さから試行スパンが覆った区間を引いた値(小数第1位まで)を書きます。
/root/tp-retry/attrs.pyを作成してください(デフォルトのダンプのパスは/root/tp-retry/06-attrs.jsonl)。chargeをもう一度処理しますが、外側のスパンにretry.count(整数、実際の試行回数)・retry.last_error(最後の失敗の種類)・idempotency.key(ord-7781)を付け、試行スパンごとにretry.attemptと、同じ値のidempotency.keyを付けます。失敗した試行には、ステップ3と同様にerror.typeとERRORステータスをそのまま残します。そして/root/tp-retry/06-rules.tsvに、タブで区切った3つの欄の4行を書いてください。1つ目の欄は属性名で、順にretry.count・retry.last_error・idempotency.key・retry.attempt、2つ目の欄はその属性が付く場所でrootまたはattempt、3つ目の欄はなぜその場所なのかを20文字以上で書きます。
/root/tp-retry/ship_spans.pyを作成してください(デフォルトのダンプのパスは/root/tp-retry/07-ship.jsonl)。材料tracelab.tp_retry.shippingのdispatch(order_id, hooks)はループをすでに持っており、attempt_begin・attempt_end・waitedの3か所だけを開けています。shipping.Hooksを継承したクラスで、その3か所でスパンを作り、サービス名shipping-apiで外側のスパンship.dispatchと試行スパンship.attemptを、ステップ6と同じ属性ルールで残してください。外側のスパンにはretry.backoff_ms_totalも一緒に付けます。冪等キーはord-7781です。
/root/tp-retry/retry_lint.pyを作成してください。python3 retry_lint.py <덤프경로>(プレースホルダーはダンプのパスです)で実行すると、ルールを破った箇所ごとに<규칙이름><탭><스팬아이디>(プレースホルダーはルール名、タブ、スパンIDです)を1行ずつ出力して終了コード1で終わり、破った箇所がなければok<탭><루트 스팬 수>(プレースホルダーはタブとルートスパン数です)の1行を出力して0で終わります。ルール名は正確に4つです。root-status(最後の試行が失敗ではないのに外側のスパンがERROR)、retry-count(外側のスパンのretry.countが子の数と異なる)、attempt-error-type(ERRORの試行スパンにerror.typeがない)、idem-key(試行スパンのidempotency.keyが外側のスパンと異なる)。作成したリンターを/root/tp-retry/06-attrs.jsonlに実行して通過するか確認し、/opt/app/tracelab/tp_retry/broken.jsonlに実行した出力を/root/tp-retry/08-lint.txtに保存してください。

参考

作業ディレクトリは/root/tp-retryです。なければ先に作ってください。
計装プログラムは必ず/opt/otel-lab/bin/python <파일>(プレースホルダーはファイル名です)で実行します。システムのpython3にはOpenTelemetry SDKがありません。逆に、ダンプだけを読むプログラムはシステムのpython3で実行してください。
材料は/opt/app/tracelab/tp_retry/upstream.py(決定論的に失敗する上流)と/opt/app/tracelab/tp_retry/shipping.py(フックだけが開いている2つ目のサービス)、そして反例のダンプ/opt/app/tracelab/tp_retry/broken.jsonlです。共通の配線は/opt/app/tracelab/dump.pyで、ダンプ読み込みのヘルパーは/opt/lab/checks/_tplib.pyです。
よくある間違い: ダンプファイルを削除せずにプログラムを2回実行してしまいます。ダンプは追記されるので、スパンが2倍になります。
よくある間違い: 待機(backoff)を試行スパンの中で行ってしまいます。そうすると、その試行が実際より長くかかったものとして記録されます。
Traces(OpenTelemetry Concepts)・Tracing API仕様・HTTPスパンのセマンティックコンベンション・error.type属性レジストリ・Python計装ドキュメント

リトライを1つのスパンに入れると、ダンプは何を失うか

/root/tp-retry/one_span.pyを作成してください。ダンプのパスは環境変数TRACELAB_OUTから先に読み、なければ/root/tp-retry/01-one.jsonlを使います。provider("shop-api", OUT)でトレーサーを取得してchargeスパンを1つだけ作り、その中でupstream.call("charge", 시도번호, idempotency_key="ord-7781")を成功するまで繰り返します(失敗したらupstream.backoff_s(시도번호)秒だけ待ちます。プレースホルダーはどちらも試行番号です)。プログラムの最後にflush()を呼んでください。そのあと/root/tp-retry/01-lost.txtに2行を書きます。attempts=の後ろには、実際に何回試行したかを整数で、lost=の後ろには、このダンプからはわからなくなったものが何かを40文字以上で書いてください。

材料は/opt/app/tracelab/tp_retry/upstream.pyです。PLANを開くと、chargeが何回目の試行で成功するかが書かれています。ダンプを作り直す前にファイルを削除してください。ダンプは追記されます。プログラムは必ず/opt/otel-lab/bin/pythonで実行します(システムのpython3にはotelがありません)。

試行ごとにスパンを作って時間を見えるようにする

/root/tp-retry/attempts.pyを作成してください。デフォルトのダンプのパスは/root/tp-retry/02-attempts.jsonlです。外側のchargeスパンはそのままにして、試行ごとに子スパンcharge.attemptを作り、整数属性retry.attemptに何回目の試行か(1から)を書きます。待機は試行スパンの外で行います。実行すると、ダンプにスパンが4個(外側が1+試行が3)入っている必要があります。

with tracer.start_as_current_span(...)を入れ子にして使うと、内側のスパンの親は自動的に外側のスパンになります。待機を試行スパンの中で行うと、その試行が実際より長くかかったように見えるので、位置に注意してください。python3 /opt/lab/checks/_tplib.py summary <덤프>(プレースホルダーはダンプのパスです)でスパンの一覧を見られます。

失敗した試行だけをエラーに、外側のスパンは正常に

/root/tp-retry/error_place.pyを作成してください。デフォルトのダンプのパスは/root/tp-retry/03-error.jsonlです。失敗した試行スパンには、ステータスをERRORに設定し、文字列属性error.typeにexc.kindを書きます。成功した試行スパンのステータスには手を触れません。外側のchargeスパンは、最後にステータスをOKに設定します。ユーザーが経験した結果は成功だからです。

from opentelemetry.trace import Status, StatusCodeを使うと、set_status(Status(StatusCode.ERROR, 설명))(プレースホルダーは説明です)でステータスを設定できます。ステータスを何も設定していないスパンは、ダンプにUNSETとして残ります。OKとUNSETは異なる値であり、このステップはその違いを要求します。

スパンでエラー率を数えると、リトライが2回数えられる

/root/tp-retry/rates.pyを作成してください。デフォルトのダンプのパスは/root/tp-retry/04-rates.jsonlで、4つの作業charge・quote・ship・notifyを順に処理します。作業ごとに外側のスパン<작업>.requestと試行スパン<작업>.attemptを作り(プレースホルダーは作業名です)、試行は最大3回までにします。最後まで失敗した作業の外側のスパンはERROR、成功した作業はOKです。そのあと/root/tp-retry/04-rates.tsvに、タブで区切った4つの欄の2行を書いてください。1行目はspan_level、2行目はrequest_levelで、欄は<id> <오류 수> <전체 수> <비율>(プレースホルダーは順に、エラー数、全体数、割合です)です。span_levelはダンプのすべてのスパンを数え、request_levelは親のないスパンだけを数えます。割合は小数第4位までです。

notifyはどの試行でも成功しません。upstream.PLANを見てください。2つの割合の分母が互いに異なるということが、このステップのすべてです。数える作業は、ダンプをPythonで読んでstatusとparent_idだけを見ればよく、/opt/lab/checks/_tplib.pyのloadを使えば1行で読めます。

待機に使った時間は、どのスパンにも入っていない

/root/tp-retry/backoff.pyを作成してください(デフォルトのダンプのパスは/root/tp-retry/05-backoff.jsonl)。chargeだけをもう一度処理しますが、待機を終えるたびに外側のスパンにイベントretry.backoffを追加し、そのイベントにretry.attempt(整数)とbackoff.ms(ミリ秒)を付けます。最後に、外側のスパンの属性retry.backoff_ms_totalに、待機時間の合計をミリ秒で書きます。そのあと/root/tp-retry/05-gap.txtに2行を書いてください。backoff_total_ms=の後ろに記録した合計を、uncovered_ms=の後ろに、外側のスパンの長さから試行スパンが覆った区間を引いた値(小数第1位まで)を書きます。

span.add_event(이름, {속성})(プレースホルダーはイベント名と属性です)でイベントを付けます。覆われていない区間は、/opt/lab/checks/_tplib.pyのcovered_ns(부모, 자식들)(プレースホルダーは親と子たちです)で求めてから、親の長さから引けば済みます。その関数は重なる子を2回数えません。2つの数字は近いはずですが、ぴったり同じにはならないでしょう。なぜそうなるのか、考えてみてください。

属性のルールを決めて、そのとおりに計装する

/root/tp-retry/attrs.pyを作成してください(デフォルトのダンプのパスは/root/tp-retry/06-attrs.jsonl)。chargeをもう一度処理しますが、外側のスパンにretry.count(整数、実際の試行回数)・retry.last_error(最後の失敗の種類)・idempotency.key(ord-7781)を付け、試行スパンごとにretry.attemptと、同じ値のidempotency.keyを付けます。失敗した試行には、ステップ3と同様にerror.typeとERRORステータスをそのまま残します。そして/root/tp-retry/06-rules.tsvに、タブで区切った3つの欄の4行を書いてください。1つ目の欄は属性名で、順にretry.count・retry.last_error・idempotency.key・retry.attempt、2つ目の欄はその属性が付く場所でrootまたはattempt、3つ目の欄はなぜその場所なのかを20文字以上で書きます。

場所を選ぶ基準は1つです。その値が、論理的なリクエスト1つにつき決まるのか、試行ごとに変わるのか。冪等キーは両方に同じ値で置きます。同じキーで何回も出ていったという事実そのものが、重複処理の事故を見分ける手がかりになるからです。

直せない他人のループに、同じルールを差し込む

/root/tp-retry/ship_spans.pyを作成してください(デフォルトのダンプのパスは/root/tp-retry/07-ship.jsonl)。材料tracelab.tp_retry.shippingのdispatch(order_id, hooks)はループをすでに持っており、attempt_begin・attempt_end・waitedの3か所だけを開けています。shipping.Hooksを継承したクラスで、その3か所でスパンを作り、サービス名shipping-apiで外側のスパンship.dispatchと試行スパンship.attemptを、ステップ6と同じ属性ルールで残してください。外側のスパンにはretry.backoff_ms_totalも一緒に付けます。冪等キーはord-7781です。

provider("shipping-api", OUT, set_global=False)で2つ目のサービスのプロバイダーを作ります。フックの中ではwithを使えないので、tracer.start_span(...)で作り、attempt_endでend()を呼んでください。外側のスパンが現在のスパンであれば、試行スパンの親は自動的に決まります。

ルールをリンターで固めて、破ったダンプを検出する

/root/tp-retry/retry_lint.pyを作成してください。python3 retry_lint.py <덤프경로>(プレースホルダーはダンプのパスです)で実行すると、ルールを破った箇所ごとに<규칙이름><탭><스팬아이디>(プレースホルダーはルール名、タブ、スパンIDです)を1行ずつ出力して終了コード1で終わり、破った箇所がなければok<탭><루트 스팬 수>(プレースホルダーはタブとルートスパン数です)の1行を出力して0で終わります。ルール名は正確に4つです。root-status(最後の試行が失敗ではないのに外側のスパンがERROR)、retry-count(外側のスパンのretry.countが子の数と異なる)、attempt-error-type(ERRORの試行スパンにerror.typeがない)、idem-key(試行スパンのidempotency.keyが外側のスパンと異なる)。作成したリンターを/root/tp-retry/06-attrs.jsonlに実行して通過するか確認し、/opt/app/tracelab/tp_retry/broken.jsonlに実行した出力を/root/tp-retry/08-lint.txtに保存してください。

リンターにotelは不要です。標準ライブラリだけでJSONLを読めばよいので、システムのpython3で動くように書いてください。子スパンは、parent_idが親のspan_idである行です。最後の試行は、start_nsが最も大きい子です。採点ツールは作成したリンターをほかのダンプにも実行するので、ファイル名や特定のIDで判定してはいけません。