S6F11은 왔다. Host log에도 남아 있다. 그런데 설비 쪽 log에는 같은 이벤트가 timed-out으로 적혀 있다. Socket은 끊긴 적이 없고, 그 뒤에 보낸 S2F41도 정상으로 답을 받았다. Host 쪽에서 보면 아무 일도 없었다. 이게 GEM에서 host가 유일하게 갚아야 하는 답인 S6F12를 빠뜨렸을 때의 모양이다.
이 transaction은 설비가 열었다
Host 개발자가 쓰는 코드는 거의 전부 host가 primary를 보내고 설비가 secondary를 돌려주는 모양이다. S1F13/S1F14, S2F41/S2F42, S2F13/S2F14. T3 reply timeout도 host가 들고 있다. 보낸 쪽이 재는 시계니까.
S6F11은 방향이 반대다. 설비가 primary를 열고, W-bit를 세우고, host의 S6F12를 기다린다. 그래서 이 transaction의 T3는 설비 쪽에서 돈다. SEMI E37의 timeout 파라미터 표는 T3를 1–120 s 범위에 typical 45 s로 적어 둔다 — 기본값으로 못 박은 게 아니라 전형값이다. 어느 쪽이든 그 45초를 세는 주체가 host가 아니라는 점이 중요하다. Host가 S6F12를 안 보내면 host 쪽에는 아무 timer도 걸리지 않고, 아무 로그도 남지 않는다.
아래 capture는 그 상황을 네 가지로 갈라 본 것이다.
Capture: socket 하나, S6F11 네 건, 답 네 가지
설비는 simulator 저장소의 secs-gem-equipment 0.1.0을 127.0.0.1:5599(SessionID 0) passive listener로 띄운 것이다. 한 가지만 손댔다. timers.t3를 6초로 줄였다. 45초로 두면 capture 하나에 3분이 넘게 걸린다. Fault injection은 쓰지 않았다. Host는 직접 frame을 만들고 뜯는 Python socket client다.
먼저 define → link → enable → S1F17까지 평범하게 올린다. 이 순서 자체는 S2F33/S2F35/S2F37을 byte로 확인한 글에 있다.
TX S2F33 W 00 00 82 21 00 00 00 00 04 04
01 02 B1 04 00 00 00 01
01 01 01 02 B1 04 00 00 02 BC 01 02 B1 04 00 00 00 01 B1 04 00 00 00 02
RX S2F34 00 00 02 22 00 00 00 00 04 04 21 01 00
TX S2F35 W 00 00 82 23 00 00 00 00 04 05 ... CEID 10001, 10002 → RPTID 700
RX S2F36 00 00 02 24 00 00 00 00 04 05 21 01 00
TX S2F37 W 00 00 82 25 00 00 00 00 04 06 01 02 25 01 01 01 02 B1 04 00 00 27 11 B1 04 00 00 27 12
RX S2F38 00 00 02 26 00 00 00 00 04 06 21 01 00
DRACK 0, LRACK 0, ERACK 0. RPTID 700은 VID 1(CONTROL_STATE)과 VID 2(PROCESS_STATE)를 담고, CEID 10001(START)과 10002(STOP)에 붙어 있다.
1. 답을 아예 안 보낸 경우
S2F41 START를 보내면 HCACK 0 다음에 S6F11이 바로 따라온다.
00:05:15.361 TX S2F41 W START 00 00 82 29 00 00 00 00 04 08 01 02 41 05 53 54 41 52 54 01 00
00:05:15.362 RX S2F42 00 00 02 2A 00 00 00 00 04 08 01 02 21 01 00 01 00
00:05:15.362 RX S6F11 W 00 00 86 0B 00 00 00 00 00 01
01 03 B1 04 00 00 00 01
B1 04 00 00 27 11
01 01 01 02 B1 04 00 00 02 BC 01 02 A5 01 05 A5 01 03
Header를 읽으면 byte 2가 86 — W-bit 1에 stream 6, byte 3이 0B = function 11. SystemBytes는 00 00 00 01이고, host가 쓰던 00 00 04 xx 대역이 아니다. 설비가 자기 번호로 연 primary다. Body는 <L [3] <U4 1> <U4 10001> <L [1] <L [2] <U4 700> <L [2] <U1 5> <U1 3>>>>>. DATAID 1, CEID 10001, RPTID 700에 값 5와 3.
여기서 host는 9초 동안 아무것도 보내지 않았다. 설비도 아무것도 보내지 않았다. 재전송 없음, S9F9 없음, socket close 없음. Host 쪽 log는 이 9초 동안 완전히 비어 있다.
설비 쪽 log에만 이렇게 남는다.
00:05:15.362Z collection-event ceid=10001 sys=1 outcome=sent
00:05:21.369Z collection-event ceid=10001 sys=1 outcome=timed-out
00:05:21.369Z anomaly T3 (S6F11) timeout sys=1
6.007초. 설정한 T3 그대로다. 이벤트는 그 시점에 버려지고, 다시 보내려는 시도는 없다. MES에 그 이벤트가 영원히 없다는 뜻이고, 그 사실을 알고 있는 쪽은 설비뿐이다.
2. 답은 보냈는데 body 형식이 틀린 경우
이게 제일 비싼 경우다. 두 번째 S6F11(sys 2, CEID 10002)에 S6F12를 보내되 ACKC6를 binary 대신 ASCII로 실었다. 실제 host 코드에서 흔한 실수다 — ack 값을 문자열로 들고 다니다 그대로 직렬화하는 것.
00:05:24.374 RX S6F11 W 00 00 86 0B 00 00 00 00 00 02 ...
00:05:24.374 TX S6F12 00 00 06 0C 00 00 00 00 00 02 41 02 4F 4B
SystemBytes 00 00 00 02는 정확히 맞췄다. W-bit도 0으로 내렸다. 틀린 건 body 하나, 41 02 4F 4B = <A "OK">다.
설비는 이렇게 받는다.
00:05:24.374Z anomaly malformed S6F12 sys=2
00:05:30.379Z collection-event ceid=10002 sys=2 outcome=timed-out
00:05:30.379Z anomaly T3 (S6F11) timeout sys=2
ack을 받고도 T3를 끄지 않았다. 6초 뒤 그대로 만료되고 이벤트는 폐기된다. Host 쪽으로는 S9F7도, SxF0도, 아무것도 오지 않았다. Host log에는 "S6F12 전송 완료" 한 줄이 남고 끝이다.
Host 코드 입장에서 1번과 2번은 구분이 안 된다. 둘 다 조용하다. 차이는 2번이 "우리는 ack을 보내고 있다"는 증거를 host log에 남긴다는 것뿐이고, 그래서 사고 조사가 엉뚱한 데로 간다.
3. 제대로 보낸 경우
00:05:33.385 RX S6F11 W 00 00 86 0B 00 00 00 00 00 03 ...
00:05:33.385 TX S6F12 00 00 06 0C 00 00 00 00 00 03 21 01 00
21 01 00 — binary item 1바이트, 값 0. 설비 log에 1 ms 안에 outcome=acknowledged가 찍힌다. S6F12에 대한 응답은 없다. Secondary에 secondary는 없으니 정상이다.
4. ACKC6에 0이 아닌 값을 넣은 경우
00:05:36.389 TX S6F12 00 00 06 0C 00 00 00 00 00 04 21 01 01
00:05:36.389Z collection-event ceid=10002 sys=4 outcome=rejected ackCode=1
T3는 꺼진다. 받았다는 건 인정받았다. 하지만 설비는 그걸로 끝이다 — 8초 더 기다려도 재전송은 없었다. ACKC6 non-zero는 "거절했다"는 기록일 뿐이고, 그 이벤트를 다시 받을 방법은 S6F19/S6F15 같은 별도 경로뿐이다. ACKC6에 이유를 담을 field가 없다는 점은 event report 구조를 다룬 글에 정리해 뒀다.
Host 쪽에서는 네 경우가 전부 똑같이 보인다
이 capture에서 host가 받은 byte를 놓고 보면 1·2·4번을 구분할 단서가 없다. 설비는 host에게 불만을 말하지 않는다. 그래서 host 쪽 설계에서 바뀌어야 하는 건 로그 한 줄이다.
- S6F11을 받은 시각, SystemBytes, CEID를 적는다.
- S6F12를 보낸 시각과 실제로 socket에 쓴 byte를 같이 적는다. "ack 전송"이라고만 적으면 2번을 영원히 못 찾는다.
- 이 두 줄을 설비 쪽 event log와 대조할 수 있는 key는 SystemBytes뿐이다. CEID는 중복되고 시각은 clock이 다르다.
S6F12를 보내는 코드 경로에 DB commit이 걸려 있으면 그것도 여기서 터진다. T3가 45초라도 host의 동기 commit이 그보다 길어질 수 있고, 그러면 설비는 host가 살아 있는 동안 이벤트를 버린다. Ack을 먼저 보내고 저장은 뒤로 미루는 쪽이 맞다. 저장 실패는 host 쪽 문제로 남지만, T3 만료는 복구할 수 없는 손실이다.
확인하지 못한 것
- E5가 ACKC6 non-zero를 받은 설비에게 무엇을 하라고 규정하는지는 표준 본문에서 확인하지 못했다. 위 동작은 이 구현의 것이다.
- 이 설비는 T3 만료에 S9F9를 보내지 않았다. E5에 transaction timer timeout용 S9F9가 있지만, 보내는 설비도 있는지 이 capture는 말해 주지 않는다. S9를 신뢰할 수 없는 이유는 따로 정리해 뒀다.
- GEM spooling이 이 경우를 덮어 주는지도 확인하지 않았다. Spool은 연결이 끊긴 상황을 전제로 하고 여기서는 socket이 끝까지 살아 있었다. spooling이 실제로 지켜 주는 범위는 다른 글이다.
- 공개 demo listener(EQ1, 5501)로는 이 capture를 만들지 못한다. 그쪽은 socket client에 S6F11을 보내지 않는다.
Host 쪽 정리
- S6F11을 받으면 반드시 S6F12를 보낸다. W-bit가 선 primary는 답을 요구하고, 이건 host가 갚을 유일한 답이다.
- ACKC6는 binary 1바이트다.
21 01 00. 문자열도, U1도, list도 아니다. - S6F12의 SystemBytes는 S6F11에서 받은 값을 그대로 쓴다. Host의 outstanding transaction 표에서 찾으면 없다.
- S6F12의 W-bit는 0이다.
- ACKC6를 0이 아닌 값으로 보낼 거면, 그 이유를 host 쪽에 남겨라. 설비는 절대 못 배운다.
- Ack 경로에 느린 I/O를 두지 마라. T3는 host가 아니라 설비가 재고 있다.
- S6F11/S6F12를 SystemBytes로 짝지은 기록을 남기고, 주기적으로 설비 log와 대조해라. 빠진 이벤트는 그 대조에서만 보인다.
위 frame은 전부 loopback socket에 실제로 오간 byte다. 양쪽 log와 원본 export를 content/demos/s6f12-missing-ack-loses-event.json에 넣어 뒀다. 직접 재현하려면 SECS/GEM 시뮬레이터에 socket을 붙이고, S6F11에 일부러 답하지 않는 경로를 한 번 돌려 보면 된다. Host 코드에서 그 분기가 실행된 적이 있는지는 그렇게 해야 알 수 있다.