TT Lab
はじめる
学ぶ 学習パス コース

ログから原因を見つける

注文がひとつ消えたが、サービスは五つあった

TT Labで続きを見る

目標

5つのサービスのログから、注文1つの経路を最初から最後までつなぎます。W3C traceparentを4つの欄に分けて無効な値を隔離し、1つのtrace-idの行を時間順に並べ、parent-idでスパンのツリーを作り、スパンごとの所要時間を求め、ヘッダーが途切れた場所をビジネスキーでつないだうえで、sampledフラグをマスクで読みます。

なぜ重要なのか

顧客は「注文が1つ消えた」と言いますが、サービスは5つあります。時刻で推測すると、毎秒数十件のリクエストの中から、どれがその注文かを選ぶ根拠がありません。相関idはその場所を埋めますが、現場で実際にぶつかる問題は、idがないことではなく、途中の1か所で途切れることです。途切れた場所を見つけ、その前後をビジネスキーでつなぎ直して証明するところまでが調査です。その証明が、次のデプロイでヘッダーを伝えさせる根拠になります。

ステップ

  1. /root/trace/gen_trace.pyを作成して実行し、/root/trace/raw/の下に、5つのサービスのログを作ってください。
  2. /root/trace/parsed.ndjsonと/root/trace/badtp.ndjson: すべてのtraceparentを4つの欄に分け、規格に合わない値は理由とともに隔離してください。
  3. /root/trace/one_trace.ndjson: 注文ORD-2026-4117のtrace-idを探して、そのトレースのすべての行を時間順に並べてください。
  4. /root/trace/tree.ndjson: parent-idで親子関係を立てて、スパンのツリーを作ってください。
  5. /root/trace/elapsed.json: スパンごとの所要時間と自己時間を求めてください。
  6. /root/trace/bridge.ndjsonと/root/trace/gap.json: ヘッダーが途切れたサービスを探して、その前後を注文番号でつないでください。
  7. /root/trace/sampled.json: sampledフラグをマスクで読んで、記録されたトレースとされなかったトレースを分けてください。
  8. /root/trace/trace_report.md: 調査結果を報告書として残してください。

参考

5つのサービスのログを手に入れる

/root/trace/gen_trace.pyを作成して実行し、/root/traceディレクトリの下に、edge.jsonl(58行)・orders.jsonl(72行)・payments.jsonl(48行)・stock.jsonl(48行)・ledger.jsonl(48行)を作ってください。

5つのファイルとも、1行にJSONオブジェクト1つ(JSON Lines)です。大半の行には、traceparent_inとtraceparent_outが付きますが、1つのサービスの行には1つも付きません。そのサービスが、このラボの主役です。edgeには、ヘルスチェックの行と、古いモバイルゲートウェイが記録した誤ったヘッダーも混ざっています。

traceparentを4つの欄に分ける

/root/trace/parsed.ndjsonに、規格に合うtraceparentごとに、svc・line_no(1から)・field(traceparent_in|traceparent_out)・version・trace_id・parent_id・trace_flagsを、1行に1つずつ書いてください。規格に合わない値は、/root/trace/badtp.ndjsonに、svc・line_no・field・raw(原文のまま)・reasonとして残してください。

材料は、ステップ1で作った/root/trace/raw/の下の5つのファイルすべてです。traceparentは固定長です。ハイフンで分かれた4つの欄の長さが順に2・32・16・2で、文字は小文字の16進だけが許されます。reasonは、指示文が定めた検査の順序どおりに付けてください。ファイルを読むときの行番号は、元のファイルで1から数え、traceparentがまったくない行は、どちらにも入れません。

その注文のトレースを時間順に並べる

顧客が言った注文はORD-2026-4117です。edgeログでその注文のtraceparentを探してtrace-idを得て、/root/trace/one_trace.ndjsonに、そのtrace-idを持つすべての行を、ts・svc・trace_id・span_id・parent_span_id・msgとして、tsの昇順で書いてください。span_idはその行のtraceparent_outのparent-idで、parent_span_idはtraceparent_inのparent-idです(なければ空文字列)。

材料は、/root/trace/raw/の下の5つのファイルです。trace-idはトレース全体を指し、parent-idはリクエスト1つを指します。そのため、集める基準はtrace-idです。5つのサービスが関わった注文なのに、ここに何個のサービスが出てくるかを数えてみてください。その数字が、このラボの問題です。

parent-idでスパンのツリーを立てる

/root/trace/tree.ndjsonに、ステップ3のトレースに出てきたスパンごとに、span_id・parent_span_id・svc・depth(ルートが0)・child_countを、1行に1つずつ書いてください。depthの昇順で、同じならspan_idの昇順です。ルートは1つである必要があります。

材料は、ステップ3で作った/root/trace/one_trace.ndjsonです。1つのスパンが複数の行を残すので、まずspan_idで畳む必要があります。depthは、parent_span_idをたどって上へ登りながら数えればよいです。child_countは、私を親として指すスパンの数です。この数字が0なのに、そのサービスが別のサービスを呼ぶことを知っているなら、その場所が途切れた場所です。

時間がどこで使われたかをスパンごとに測る

/root/trace/elapsed.jsonに、spans(スパンごとにspan_id・svc・ms・self_ms、span_idの昇順)・slowest_self_svc・slowest_self_msを書いてください。msは、そのスパンの最初の行と最後の行の時刻の差(ミリ秒の整数)で、self_msは、そこから子スパンのmsの合計を引いた値です。

材料は、ステップ3で作った/root/trace/one_trace.ndjsonです。所要時間だけを見ると、一番上のスパンが常に最大です。子を含んでいるので当然です。知りたいのは各サービスが自分で使った時間なので、子の時間を引く必要があります。時刻はすでに同じ表記に固定されているので、ミリ秒に変換して引けばよいです。自己時間が際立って大きいスパンが出たら、それが犯人だと断定する前に、ステップ6を見てください。

途切れた場所を探して注文番号でつなぐ

/root/trace/bridge.ndjsonに、注文ORD-2026-4117が書かれたすべてのサービスのすべての行を、ts・svc・trace_id(なければ空文字列)・order_id・linked_by(traceparent|order_id)として、tsの昇順で書いてください。また、/root/trace/gap.jsonに、dropped_at(traceparentを1行も残さなかったサービス)・restarted_at(そのあとで、新しいtrace-idのルートスパンを作ったサービス)・trace_ids(この注文に関わったtrace-idを、最初に出た順に)を書いてください。

材料は、再び/root/trace/raw/の下の5つのファイルです。ステップ3のトレースには3つのサービスしか出てきませんでしたが、この注文は5つのサービスを通りました。残りの2つを見つける鍵は、トレースの文脈ではなく、ビジネスキーです。dropped_atは、そのサービスのログのどの行にもtraceparentがないサービスで、restarted_atは、受け取ったヘッダーがなくて、自分で新しいtrace-idを作ったサービスです。

sampledフラグをマスクで読む

/root/trace/sampled.jsonに、total_traces・sampled_traces・unsampled_traces・flag_values(trace-flagsの値ごとのトレース数)・naive_equal_01(trace-flagsが文字列01のトレース数)を書いてください。数える対象は、ステップ2で作った/root/trace/parsed.ndjsonに出てきた異なるtrace-idのすべてで、1つのトレースの中のtrace-flagsは、すべて同じです。

trace-flagsは8ビットのフィールドです。規格は、16進数を数値として解釈してその値と比較せず、マスクするよう明記しています。Pythonではint(flags, 16) & 1です。naive_equal_01は、わざと間違った方法で数えた数字なので、2つの値を並べて置くことが、このステップの目的です。

調査結果を報告書として残す

/root/trace/trace_report.mdに、## 고객은 무엇을 물었나、## 추적이 어디서 끊겼나、## 시간은 어디서 갔나、## 다음 배포에서 고칠 것(韓国語の見出しは、順に「顧客は何を尋ねたか」「トレースはどこで途切れたか」「時間はどこで使われたか」「次のデプロイで直すこと」という意味です)の4つの節で書いてください。注文番号・ヘッダーが途切れたサービス名・最大のself_ms・無効なtraceparentの数・sampledトレースの数を、そのまま含める必要があります。

顧客に返す文は、「注文は消えておらず、ここまで進んだ」と「なぜツールで見えなかったか」の2つです。数字はでっち上げず、前のステップの成果物(/root/trace/gap.json・/root/trace/elapsed.json・/root/trace/sampled.json・/root/trace/badtp.ndjson・/root/trace/bridge.ndjson)から取り出して使ってください。最後の節には、次のデプロイで何を変えれば、この調査が不要になるかを書きます。