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

Goal

Join the logs of four stretches, which differ in format and time zone, by GUID to find a transaction's path, vanished transactions and slow stretches, and fix a relay that breaks tracing so that it carries the GUID and the W3C traceparent to the end.

Why it matters

The speed of outage response is set by how quickly you can answer "how far did that transaction get." If the numbers differ per stretch or time zones are mixed, you cannot join them mechanically, and people end up joining by hand with time and amount. Tracing holds only when both the writing side (propagation rules) and the reading side (normalization) are aligned.

Steps

1. From /opt/lab/fixtures/eaimw/trace/logs/, read mci.log, eai.log and fep.log and create /root/eaimw/trace/events.csv. Header guid,hop,ts_kst,event,rsp; hop is MCI, EAI or FEP; ts_kst is YYYY-MM-DD HH:MM:SS.mmm (Korean time); event is the log's event as it is (MCI's event=, EAI's third column, FEP's fourth column); rsp is MCI's rsp=, the fifth column of EAI's RSP lines, and the institution code of FEP's RSP lines (blank for the rest).
2. Add core.jsonl (times are UTC, with a Z at the end). hop is CORE, event is RECV/APPLY, and rsp is blank. Convert the times to Korean time and sort the whole thing in ascending ts_kst order.
3. /root/eaimw/trace/trace.py <GUID> [--events 경로] (path; default /root/eaimw/trace/events.csv): print the rows of that GUID in time order, one line each as hop,event,ts_kst,경과ms (with the elapsed milliseconds from the first event, as an integer), and on the last line TOTAL,<첫~마지막 ms> (the milliseconds from the first to the last event).
4. Sort the GUIDs for which the hub sent to core banking (EAI, OUT) but there is no core banking record (CORE) at all, and write them one per line to /root/eaimw/trace/lost.txt.
5. Write the transactions in which MCI RECV→SEND_RSP exceeds 3000ms to /root/eaimw/trace/slow.csv: header guid,total_ms,core_ms,fep_ms, core_ms is CORE RECV→APPLY, fep_ms is FEP REQ→RSP (blank if none), in descending total_ms.
6. Start with cp /opt/lab/fixtures/eaimw/trace/relay_buggy.py /root/eaimw/trace/relay.py and fix it: when calling core banking, carry the received GUID in the JSON guid and in X-GUID, and leave structured logs, one line of JSON each, in the --log <경로> (path) file — keys ts (ISO 8601 with time zone), guid, hop (EAI), event (IN received, OUT sent to core banking, RSP responded) and rsp (the standard response code of the RSP line).
7. Carry the W3C traceparent header in the core banking call: 00-<GUID>-<호출마다 새 16자리 parent-id, 전부 0 금지>-01 (with a new 16-character parent-id for each call in the placeholder, all zeros forbidden).

Notes

• Converting to Korean time: datetime.strptime(ts, "%Y-%m-%dT%H:%M:%S.%fZ").replace(tzinfo=timezone.utc).astimezone(timezone(timedelta(hours=9))), and for the millisecond string strftime("%Y-%m-%d %H:%M:%S.%f")[:-3].
• MCI has a time zone attached as ts=…+09:00 (datetime.fromisoformat). EAI and FEP are written in Korean time without a time zone (by definition).
• In steps 6 and 7, the grader starts your relay.py directly with --port, --core and --log and checks it against the core banking fixture's log (the received X-GUID and traceparent).
• Common mistakes: leaving the CORE time as is (9 hours off), cutting the traceparent parent-id out of the GUID (it becomes the same for every call), leaving the log out on error paths.

Three log formats into one table

Normalize mci.log, eai.log and fep.log into /root/eaimw/trace/events.csv (guid,hop,ts_kst,event,rsp).

For MCI, split by whitespace and then by '='; for EAI, by '|'; FEP has five columns separated by spaces. Align all the times to 'YYYY-MM-DD HH:MM:SS.mmm'.

Core banking written in UTC into Korean time

Convert core.jsonl to Korean time and add it, and sort the whole thing in ascending ts_kst order.

The Z at the end is UTC. Attach tzinfo as UTC and then convert to +09:00. If you don't convert, it looks as if core banking processed 9 hours before the hub.

Draw the path of one GUID

/root/eaimw/trace/trace.py prints that transaction's stretch events in time order with elapsed ms, and TOTAL at the end.

Pick only the rows of events.csv with the same GUID and sort them by time. The elapsed time is the difference from the first row, as an integer number of milliseconds.

Transactions that vanished between the hub and core banking

Sort the GUIDs that have an EAI OUT but no CORE record and write them to /root/eaimw/trace/lost.txt.

It is the difference of two sets. Also check in events.csv what the hub answered for these transactions (the code of EAI RSP).

Split slow transactions into stretches

Output the core banking and external stretch times of transactions exceeding 3 seconds by MCI to /root/eaimw/trace/slow.csv (descending total_ms).

The difference between two events inside the same server (core banking RECV→APPLY, FEP REQ→RSP) is reliable. For a transaction that did not go through the external gateway, fep_ms is blank.

Fix the relay that breaks tracing

Copy relay_buggy.py and fix it to carry the received GUID as is all the way to core banking and to leave IN/OUT/RSP structured logs in --log.

The line in call_core that makes a new number with uuid is the culprit. Write the log as one line of JSON each, and since several threads write to the same file, take a lock when writing.

Carry traceparent in the HTTP stretch

Carry traceparent: 00---01 in the core banking call.

The trace-id position is the GUID as is (the reason it was set to the same shape). The parent-id is an 8-byte random number in hexadecimal — all zeros is invalid.