このスパンだけで障害を再現できるか

一言でいうと

良いスパンとは、その1行だけを見て、同じ失敗をもう一度起こせるスパンです。属性はその再現入力であり、イベントはその間にいつ何が起きたかであり、リンクはこの仕事を依頼した別のトレースが何かです。

なぜ必要なのか

明け方に決済の失敗が集中しました。トレースを開くと、スパンにはhttp.route=/checkout、http.response.status_code=502、そして1842ミリ秒がありました。ここまでは自動計装がすべてやってくれたものです。ところが、このスパンを手にしてできることがありませんでした。カートに商品がいくつあったか、キャッシュが空だったか、キューがどれだけ詰まっていたか、決済を何回やり直したか。再現に必要な値が1つもなかったのです。

逆に、「とりあえず全部入れよう」に走って事故を起こしたチームもあります。リクエスト本文をまるごと属性に入れたところ、顧客のメールアドレスと認証トークンが観測バックエンドにそのままたまり、そのバックエンドは開発者全員が見られる状態でした。それ以来そのチームは、属性に何を入れるかをコードレビューの項目に加えました。

このラボが扱うのは、その2つの間です。SDKをどう設定するかでも、service.nameをどの順序で決めるかでもなく、属性の枠を何で埋めるかです。

どう動くのか

まず、問いを逆にします。「何を入れようか」ではなく、このスパンだけで同じ失敗をもう一度起こすには、何がさらに必要かを問います。その答えを書き出せば、それがそのまま属性のリストです。再現入力(商品数、本文サイズ)、そのときの状態(キャッシュヒット、キューの深さ)、そして自分たちが行ったこと(リトライ回数)が、たいていここに入ります。

次に、入れてはいけない値を分けます。連絡先・カード番号・認証トークンのような値は、生の値のまま残しません。かといってまるごと捨てると調査のときに困るため、次の3つのうち1つに変えて残します。

生の値	変えて残す方法	それでも答えられる問い
メールアドレス・アカウント	ハッシュ(先頭の数桁)	「同じユーザーに繰り返し起きているか」
カード番号	カテゴリ(ブランド)	「特定のカード会社でだけ起きているか」
認証トークン	長さ	「トークンが途中で切れて入ってきたか」

3つ目に、時点のある事実は、属性ではなくイベントです。リトライを2回行ったというのは1つの数字なので属性ですが、1回目のリトライがいつどんな理由で起きたかは、時刻のある記録なのでイベントです。同じ事実を属性だけで残すと順序が消え、イベントだけで残すと集計が難しくなります。両者は競合関係ではなく、役割が違います。数えるものは属性で、起きた瞬間はイベントで残します。

4つ目に、関係の中には親子ではないものがあります。キューにたまった仕事をあとで処理するとき、その仕事は別のトレースで作られたものであり、処理スパンをそのトレースの子として付けると、数時間後に終わるおかしな親ができてしまいます。そういうときに使うのがリンクです。リンクは「このスパンはあのスパンと関係がある」とだけ伝え、親の位置は空けておきます。関係を属性の文字列(parent_trace_id=...)として書いておくチームが多いのですが、そうするとツールがつなげず、人が目で探すことになります。ここでは「関係は属性ではなくリンク」ということを一度書いて試すだけにして、キューの向こうのトレースをどう設計するかは、後のモジュールで別に扱います。

最後がコストです。属性キーごとに値が何種類あるかを数えてみると、性格が分かれます。注文番号はリクエストごとに違うのが正常で(識別子)、カードブランドは3種類であるのが正常です(カテゴリ)。問題は、カテゴリであるべき場所に生の値が漏れ込んだ場合です。例外メッセージに注文番号が埋め込まれていると、キー1つがあっという間に数千種類の値を持ちます。そのため、キーごとに「ユニーク値を制限しないキー」と「カテゴリ型でユニーク値が少なくなければならないキー」を分けて書いておき、ダンプを数えて、ずれている箇所を見つけます。

ここまで決めたことを文章だけで残すと、次の人は読みません。キー名・型・許容値・ユニーク値の性格を1行ずつ書いた規約ファイルにし、その規約を破ったスパンを見つける小さな検査プログラムを一緒に置きます。そうすれば、新しいハンドラーを計装するときに規約が自然についてきます。

このPodで判定できないことも書いておきます。コレクターがありません。実際の運用ではコレクターのredactionプロセッサーでもう一度ふるいにかけますが、ここではその段階を動かせないため、アプリケーションが自分で除去した結果だけを見ます。属性がバックエンドでどのようにインデックス化され、どれだけ高価になるかも、このPodでは知りえません。その代わり、ダンプを数えてユニーク値の数で代用します。そして、SDKが属性の数や長さを切り詰める設定は、このラボの範囲ではありません。

現場での姿

あるサービスは、障害のたびに「再現できない」で調査が止まりました。スパンにリクエスト識別子すらなく、どのリクエストが失敗したのかをログから探せなかったのです。属性を6つ(注文番号・商品数・本文サイズ・キャッシュヒット・キューの深さ・リトライ回数)加えてからは、失敗したスパンを1つ選んで、そのまま同じ入力を入れ直せるようになり、調査時間は時間単位から分単位に縮まりました。

別の事故は正反対でした。例外メッセージをそのまま属性に入れる慣習のせいで、キー1つが数万種類の値を持つようになり、そのキーで検索する画面が毎回タイムアウトで落ちました。直した方法はメッセージを消すことではなく、2つに分けることでした。分類できる短い種類(declined・timeout)は属性に、人が読む長い文はスパンのステータスメッセージとイベントに移しました。検索は再び速くなり、人が読む文もそのまま残りました。

次のラボですること

失敗したリクエストのスパン1行を受け取り、再現に必要なのにない値が何かをまず書き出します。その値を属性として追加し、入れてはいけない値はハッシュ・カテゴリ・長さに変えて残します。リトライやキャッシュミスのように時点のある事実はイベントに移し、200件を実行して属性キーごとのユニーク値を数え、バジェット表を作ります。そこで明らかになった漏れているキーを根拠にチームの規約ファイルを書き、その規約を検査するプログラムを作って、自分のダンプと他人のダンプに対して実行します。最後に、キューが依頼した返金ハンドラーを規約どおりに計装しながら、その仕事を生み出したトレースをリンクでつなぎます。