How Far Did That Transaction Get? — Join It by GUID

목표

형식과 시간대가 다른 네 구간 로그를 GUID 로 이어 한 거래의 경로·사라진 거래·느린 구간을 찾고, 추적을 끊는 중계를 고쳐 GUID 와 W3C traceparent 를 끝까지 싣는다.

왜 중요한가

장애 대응의 속도는 "그 거래가 어디까지 갔는가" 에 얼마나 빨리 답하느냐로 정해진다. 구간마다 번호가 다르거나 시간대가 섞여 있으면 기계적으로 이을 수 없고, 사람이 시각과 금액으로 손으로 잇게 된다. 추적은 로그를 쓰는 쪽(전파 규칙)과 읽는 쪽(정규화) 양쪽이 맞아야 성립한다.

단계

1. /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 줄의 기관 코드(나머지는 빈칸).
2. core.jsonl(시각이 UTC, 끝에 Z)을 더한다. hop 은 CORE, event 는 RECV/APPLY, rsp 는 빈칸. 시각을 한국 시각으로 바꾸고, 전체를 ts_kst 오름차순으로 정렬한다.
3. /root/eaimw/trace/trace.py <GUID> [--events 경로](기본 /root/eaimw/trace/events.csv): 그 GUID 의 행을 시간순으로 hop,event,ts_kst,경과ms(첫 이벤트부터, 정수) 한 줄씩 출력하고 마지막 줄에 TOTAL,<첫~마지막 ms>.
4. 허브가 계정계로 보냈는데(EAI·OUT) 계정계 기록(CORE)이 하나도 없는 GUID 를 정렬해 /root/eaimw/trace/lost.txt 에 한 줄씩 쓴다.
5. 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 내림차순.
6. 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 줄의 표준 응답코드).
7. 계정계 호출에 W3C traceparent 헤더를 싣는다: 00-<GUID>-<호출마다 새 16자리 parent-id, 전부 0 금지>-01.

참고

• 한국 시각 변환: 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 에서 잘라 쓰는 것(호출마다 같아진다), 오류 경로에서 로그를 빠뜨리는 것.

세 형식의 로그를 한 표로

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 가 그 거래의 구간 이벤트를 시간순·경과 ms 로, 마지막에 TOTAL 을 출력한다.

events.csv 에서 GUID 가 같은 행만 골라 시각순으로 정렬합니다. 경과 시간은 첫 행과의 차이를 밀리초 정수로.

허브와 계정계 사이에서 사라진 거래

EAI OUT 은 있는데 CORE 기록이 없는 GUID 를 정렬해 /root/eaimw/trace/lost.txt 에 쓴다.

두 집합의 차집합입니다. 허브가 이 거래들에 무엇으로 답했는지(EAI RSP 의 코드)도 events.csv 에서 확인해 보세요.

느린 거래를 구간으로 쪼갠다

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바이트 난수를 16진수로 — 전부 0 이면 무효입니다.