id ひとつで五つのサービスを貫く
一言でいうと
サービスが5つあるシステムで「注文が1つ消えた」に答える方法は、時刻で推測することではなく、リクエストごとに付いて回るidで行をつなぐことであり、現場で実際にぶつかる問題は、idがないことではなく、途中の1か所で途切れることです。
なぜ必要なのか
時刻でまとめる方法は、リクエストがまばらに来るときにしか通用しません。毎秒数十件が入ってくると、02:01:08付近の行がサービスごとに数十行ずつ出てきて、そのうちどれがこの注文のものかを選ぶ根拠がありません。しかも、サービスごとに時計が少しずつ違えば、順序までひっくり返って見えます。
そこで、リクエストの開始時にidを1つ作り、すべての下位呼び出しに一緒に渡します。問題は、そのidを、それぞれ別の名前で呼んでいたことです。X-Request-Id、X-B3-TraceId、X-Correlation-Id。ベンダーが違えば、鎖が途切れました。W3C Trace Contextは、その名前と形式を1つに定めた標準で、今出ているほぼすべてのトレースライブラリが、このヘッダーを使います。
どう動くのか
traceparentは、固定長の値1つです。
00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01
ハイフンで分かれた4つの欄は、それぞれversion・trace-id・parent-id・trace-flagsです。現在のバージョンは00です。trace-idは16バイト(小文字の16進32文字)でトレース全体を指し、parent-idは8バイト(16文字)でこのリクエスト1つを指します。ほかのトレースシステムでは、parent-idをspan-idと呼びます。規格は、2つの値ともすべて0なら無効で、無効なtraceparentはベンダーが無視しなければならない(MUST)と書いています。parent-idに大文字の16進が混ざっている場合も同じです。
ここで、名前が紛らわしくなります。私が受け取ったヘッダーのparent-idは、私を呼んだ側のスパンidで、私が送るヘッダーのparent-idは、私のスパンidです。そのため、ログに、入ってきたヘッダーと出ていくヘッダーの両方を残しておけば、その2つの値で、親子関係がそのまま復元されます。それがスパンのツリーです。
trace-flagsは8ビットのフィールドです。今はsampledフラグ1つだけが使われていますが、規格は、16進数を数値として解釈して、その値と比較せず、マスクしなさいと明記しています。01だけがsampledなのではなく、09もsampledです(00000001と00001000が一緒にオンになった値)。Trace Context Level 2は、2番目のビットにrandom-trace-idフラグを追加したので、実際に03と02が出回り始めました。flags == "01"で数えた数字は、すでに間違っています。
tracestateは、ベンダーごとの値の名前=値の一覧で、トレースに参加したシステムが左に新しい項目を追加します。左端が、今traceparentを書いたシステムです。
ログ側の規約も、かみ合っています。OpenTelemetryのログデータモデルは、ログレコードにTraceId・SpanId・TraceFlagsのフィールドを置き、SpanIdがあればTraceIdもあるべきだ(SHOULD)と書いています。ログとトレースが同じidで出会う場所が、ここです。
現場での姿
途切れます。規格は、中間の構成要素が、最低でもtraceparentとtracestateをそのまま伝えて、トレースが途切れないようにしなければならない(MUST)と書いていますが、計装されていない古いサービス・プロキシ・メッセージキューは、ヘッダーをそのまま落とします。その後ろのサービスは、受け取ったヘッダーがないので、トレースを新しく開始します。画面には短いトレースが2つ表示され、2つの間の関係はどこにもありません。
このときに使うのが、ビジネスキーです。注文番号・決済番号のように、システムが元から持ち歩く値で前後をつなげれば、トレースが途切れた区間も、1行に並べられます。完全な解決策ではありません。ビジネスキーは、リトライまで同じ値なので、リクエスト1つを指せないからです。それでも、「どこで途切れたか」を証明するには十分で、その証明が、次のデプロイでヘッダーを伝えさせる根拠になります。
自己時間がうそのように見えます。スパンの所要時間から、子スパンの時間を引けば、そのサービスが自分で使った時間が出ます。ところが、子の1つが計装されていなくて見えないと、その時間が、親の自己時間にそのまま乗ります。「注文サービスが800msを使った」という結論は、実は「注文サービスが呼ぶ、見えない何かが800msを使った」ということです。自己時間が際立って大きいスパンは、犯人ではなく、次に計装すべき場所です。
サンプルだけが残ります。大量のトラフィックでは、すべてのトレースを保存しません。sampledがオフのトレースは、画面にまったくないか、一部しかありません。顧客が言ったその注文がサンプルから外れていたなら、トレースツールに何もないのが正常で、そのときは、ログまで下りていく必要があります。
次のラボですること
5つのサービスのログを作り、すべてのtraceparentを4つの欄に分けて、無効な値を理由とともに隔離します。顧客が言った注文のtrace-idを探して、そのトレースの行を時間順に並べ、parent-idでスパンのツリーを作り、スパンごとの所要時間と自己時間を求めます。そのあと、ヘッダーが途切れたサービスを探して、その前後を注文番号でつなぎ、sampledフラグをマスクで読んで、記録されたトレースとされなかったトレースを分けたうえで、調査結果を報告書として残します。採点ツールは、原本を自分で再度パースして、あなたの結果と突き合わせます。