その取引はどこまで行ったか — GUID でつなぐ

目標

形式とタイムゾーンが異なる4つの区間のログをGUIDでつないで、取引1件の経路・消えた取引・遅い区間を見つけ、トレースを途切れさせる中継を直して、GUIDとW3C traceparentを最後まで載せます。

なぜ重要なのか

障害対応の速さは、「その取引はどこまで行ったのか」にどれだけ早く答えられるかで決まります。区間ごとに番号が違ったり、タイムゾーンが混ざっていたりすると、機械的につなげず、人が時刻と金額で手作業でつなぐことになります。トレースは、ログを書く側(伝播ルール)と読む側(正規化)の両方が合って初めて成り立ちます。

ステップ

/opt/lab/fixtures/eaimw/trace/logs/のmci.log・eai.log・fep.logを読み、/root/eaimw/trace/events.csvを作成してください。見出し行はguid,hop,ts_kst,event,rsp、hopはMCI・EAI・FEP、ts_kstはYYYY-MM-DD HH:MM:SS.mmm(韓国時間)、eventはログのイベントそのまま(MCIのevent=、EAIの3番目の欄、FEPの4番目の欄)、rspはMCIのrsp=・EAIのRSP行の5番目の欄・FEPのRSP行の機関コード(それ以外は空欄)です。
core.jsonl(時刻がUTCで、末尾にZ)を追加してください。hopはCORE、eventはRECV/APPLY、rspは空欄です。時刻を韓国時間に変換し、全体をts_kstの昇順で並べ替えます。
/root/eaimw/trace/trace.py <GUID> [--events 경로](プレースホルダーはパスです。既定は/root/eaimw/trace/events.csv)を作成してください。そのGUIDの行を時系列で、hop,event,ts_kst,경과ms(プレースホルダーは経過ミリ秒です。最初のイベントからの整数)として1行ずつ出力し、最後の行にTOTAL,<첫~마지막 ms>(プレースホルダーは最初から最後までのミリ秒です)を出力します。
ハブが勘定系へ送ったのに(EAI・OUT)、勘定系の記録(CORE)が1つもないGUIDを並べ替えて、/root/eaimw/trace/lost.txtに1行ずつ書いてください。
MCIのRECV→SEND_RSPが3000msを超える取引を、/root/eaimw/trace/slow.csvに出力してください。見出し行はguid,total_ms,core_ms,fep_ms、core_msはCOREのRECV→APPLY、fep_msはFEPのREQ→RSP(なければ空欄)、total_msの降順です。
cp /opt/lab/fixtures/eaimw/trace/relay_buggy.py /root/eaimw/trace/relay.pyで始めて、直してください。勘定系を呼ぶときに受け取ったGUIDをJSONのguidとX-GUIDに載せ、--log <경로>(プレースホルダーはパスです)のファイルに、構造化ログをJSON 1行ずつ残します。キーはts(タイムゾーン付きISO 8601)・guid・hop(EAI)・event(INは受信、OUTは勘定系へ送信、RSPは応答)・rsp(RSP行の標準応答コード)です。
勘定系の呼び出しに、W3Cのtraceparentヘッダーを載せてください: 00-<GUID>-<호출마다 새 16자리 parent-id, 전부 0 금지>-01(プレースホルダーは、呼び出しごとに新しく作る16桁のparent-idで、すべて0は禁止です)。

参考

韓国時間への変換: datetime.strptime(ts, "%Y-%m-%dT%H:%M:%S.%fZ").replace(tzinfo=timezone.utc).astimezone(timezone(timedelta(hours=9)))、ミリ秒の文字列はstrftime("%Y-%m-%d %H:%M:%S.%f")[:-3]です。
MCIはts=…+09:00のようにタイムゾーンが付いています(datetime.fromisoformat)。EAIとFEPは、タイムゾーンなしで韓国時間として書かれています(定義)。
採点ツールは、ステップ6・7でrelay.pyを--port・--core・--logで直接起動し、勘定系フィクスチャのログ(受け取ったX-GUID・traceparent)と照合します。
よくある間違い: COREの時刻をそのままにしてしまうこと(9時間ずれる)、traceparentのparent-idをGUIDから切り出して使ってしまうこと(呼び出しごとに同じになる)、エラー経路でログを出し忘れること。

3つの形式のログを1つの表にする

mci.log・eai.log・fep.logを/root/eaimw/trace/events.csv(guid,hop,ts_kst,event,rsp)に正規化してください。

MCIは空白で分けてから'='で分け、EAIは'|'で、FEPは空白で5つの欄に分けます。時刻はすべて'YYYY-MM-DD HH:MM:SS.mmm'にそろえます。

UTCで書かれた勘定系を韓国時間にする

core.jsonlを韓国時間に変換して追加し、全体をts_kstの昇順で並べ替えてください。

末尾のZはUTCです。tzinfoをUTCにしてから+09:00に変換します。変換しないと、勘定系がハブより9時間先に処理したように見えます。

GUID1つの経路を描く

/root/eaimw/trace/trace.py が、その取引の区間イベントを時系列・経過msで、最後にTOTALを出力するようにしてください。

events.csvからGUIDが同じ行だけを選び、時刻順に並べ替えます。経過時間は、最初の行との差をミリ秒の整数にします。

ハブと勘定系の間で消えた取引

EAI OUTはあるのにCORE記録がないGUIDを並べ替えて、/root/eaimw/trace/lost.txtに書いてください。

2つの集合の差集合です。ハブがこれらの取引に何で答えたか(EAI RSPのコード)も、events.csvで確認してみてください。

遅い取引を区間に分解する

MCI基準で3秒を超えた取引の、勘定系・外部の区間の時間を/root/eaimw/trace/slow.csvに出力してください(total_msの降順)。

同じサーバー内の2つのイベントの差(勘定系RECV→APPLY、FEP REQ→RSP)は信頼できます。FEPを通らなかった取引は、fep_msが空欄です。

トレースを途切れさせる中継を直す

relay_buggy.pyをコピーし、受け取ったGUIDを勘定系までそのまま載せ、--logにIN/OUT/RSPの構造化ログを残すように直してください。

call_coreで、uuidで新しい番号を採番している行が原因です。ログはJSON1行ずつで、複数のスレッドが同じファイルに書くので、ロックを取って書いてください。

HTTPの区間にtraceparentを載せる

勘定系の呼び出しに、traceparent: 00--<呼び出しごとに新しいparent-id>-01を載せてください。

trace-idの位置はGUIDそのままです(同じ形に定めた理由です)。parent-idは8バイトの乱数を16進数にします。すべて0は無効です。