那笔交易走到哪了 — 用 GUID 串起来

在 TT Lab 中继续学习

目标

用 GUID 把格式和时区各不相同的四个环节的日志串起来，找出一笔交易的路径、丢失的交易和缓慢的环节，并修复切断跟踪的中继，使它把 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 的第三栏，FEP 的第四栏），rsp 取 MCI 的 rsp=、EAI RSP 行的第五栏、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（占位符为经过毫秒数，自第一个事件起，整数），最后一行输出 TOTAL,<첫~마지막 ms>（占位符为从第一个到最后一个事件的毫秒数）。
对于枢纽已发往账户系统（EAI·OUT）、但账户系统记录（CORE）一条都没有的 GUID，排好序后逐行写入 /root/eaimw/trace/lost.txt。
把 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 的结构化日志——键为 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 步会用 --port·--core·--log 直接启动你的 relay.py，并与账户系统夹具的日志（收到的 X-GUID·traceparent）核对。
常见错误：原样保留 CORE 的时刻（差 9 个小时）；从 GUID 中截取一段作为 traceparent 的 parent-id（每次调用都会变成相同的）；在错误路径中漏掉日志。

把三种格式的日志汇总成一张表

把 mci.log、eai.log、fep.log 规范化为 /root/eaimw/trace/events.csv（guid,hop,ts_kst,event,rsp）。

MCI 先按空格分隔，再按 '=' 分隔，EAI 按 '|'，FEP 是五个空格。时刻全部统一为 'YYYY-MM-DD HH:MM:SS.mmm'。

把以 UTC 记录的账户系统转为韩国时间

把 core.jsonl 转换成韩国时间后加入，并把全部按 ts_kst 升序排序。

末尾的 Z 是 UTC。把 tzinfo 设为 UTC 之后，再转为 +09:00。如果不转换，账户系统看上去就会比枢纽早 9 个小时处理。

绘制一个 GUID 的路径

让 /root/eaimw/trace/trace.py 按时间顺序、带经过毫秒数输出该交易的环节事件，最后输出 TOTAL。

从 events.csv 中只挑出 GUID 相同的行，并按时刻排序。经过时间用与第一行的差，取毫秒整数。

枢纽与账户系统之间丢失的交易

把有 EAI OUT、却没有 CORE 记录的 GUID 排好序，写入 /root/eaimw/trace/lost.txt。

这是两个集合的差集。也请在 events.csv 中确认枢纽对这些交易是用什么应答的（EAI RSP 的代码）。

把缓慢的交易拆解到各个环节

把以 MCI 为基准超过 3 秒的交易的账户系统、外部环节耗时，输出到 /root/eaimw/trace/slow.csv（按 total_ms 降序）。

同一台服务器内部两个事件的差值（账户系统 RECV→APPLY、FEP REQ→RSP）是可信的。没有经过外联前置机的交易，fep_ms 留空。

修复切断跟踪的中继

复制 relay_buggy.py，把收到的 GUID 原样携带到账户系统，并修复为在 --log 中留下 IN/OUT/RSP 结构化日志。

call_core 中用 uuid 重新生成编号的那一行就是元凶。日志逐行写 JSON，多个线程会写同一个文件，所以要加锁再写。

在 HTTP 环节加上 traceparent

在对账户系统的调用中加入 traceparent: 00--<每次调用重新生成的 parent-id>-01。

trace-id 的位置原样放 GUID（这就是把它们定为相同形态的原因）。parent-id 是 8 字节随机数的十六进制——全 0 则无效。