콘텐츠로 이동
무료 평가 시작

연결과 시간 초과

이 장은 HSMS 연결이 맺어지지 않거나 요청이 시간 초과(timeout)로 끝날 때 원인을 찾는 방법을 설명합니다. 각 절의 출력과 로그는 튜토리얼 예제를 실제로 실행해 얻은 것입니다. 로그는 PDCOMM_LOG=debug로 켠 진단 로그(JSONL)이며, 읽기 쉽게 level, component, event, fields만 남겼습니다. 실제 레코드에는 timestamp_unix_ms, instance_id, sequence 같은 필드가 더 있습니다. 로그를 켜는 방법은 실패 진단과 피드백을 참고합니다.

HSMS의 상태와 타이머 개념은 HSMS 배경 지식에 있습니다.

Active (Host) Passive (Equipment)
| TCP 연결 ---------------------------> | 실패하면 RetryWait, T5 뒤 다시 연결
| Select.req -------------------------> | T6 안에 Select.rsp가 와야 함
| <------------------------ Select.rsp | Selected (TCP 연결 뒤 T7 안에)
| S1F13 (W) --------------------------> | T3 안에 S1F14가 와야 함
| <----------------------------- S1F14 | Communicating
타이머 지키는 것 시간이 지나면 PDComm은 로그에서 보이는 것
T3 데이터 메시지 응답 대기 시간 그 요청만 FAILED(이유 2)로 끝냅니다. 연결은 유지됩니다. transaction_failed, T3Timeout
T5 연결을 끊은 뒤 다시 연결할 때까지의 간격(Active만) RetryWait에서 Connecting으로 바꾸고 새 세대(generation)로 다시 연결합니다. state_changed RetryWait → Connecting
T6 Select, Deselect, Linktest 응답 대기 시간 그 요청을 FAILED(이유 3)로 끝내고 연결을 끊습니다. transaction_failed, T6Timeout
T7 TCP 연결 뒤 Selected가 될 때까지의 시간 연결을 끊습니다. 별도의 실패 코드는 없습니다. state_changed NotSelected → RetryWait 또는 Listening
T8 한 메시지 안의 바이트 사이 간격 연결을 끊습니다. 별도의 실패 코드는 없습니다. state_changed, 대기 중인 요청은 Disconnected

연결이 끊기면 대기 중이던 요청은 모두 FAILED(이유 4, Disconnected)로 끝납니다. 다시 연결되면 세대 번호가 1 늘어납니다. 이전 세대의 토큰이나 이벤트를 쓰면 StaleToken이 됩니다. GEM 통신 상태도 처음으로 돌아가므로 Host는 다시 S1F13을 보내야 합니다.

타이머와 한도는 PdcommTcpOptions(.NET HsmsOptions)에 밀리초 단위로 넣습니다. 0은 허용되지 않으며 InvalidArgument가 됩니다. PDComm은 기본값을 정하지 않습니다.

  • 실제 장비와 연결할 때는 장비의 GEM 매뉴얼이나 인터페이스 사양서에 적힌 값을 씁니다. 양쪽이 같은 값을 써야 원인을 설명하기 쉽습니다.
  • T3는 상대가 가장 느리게 응답하는 메시지보다 길게 잡습니다. 공정 프로그램 전송처럼 큰 메시지는 더 오래 걸립니다.
  • T5가 너무 짧으면 상대가 준비되지 않았을 때 연결 시도가 지나치게 많아집니다.
  • T8은 네트워크 지연의 변동보다 충분히 길게 잡습니다.

튜토리얼 예제는 한 컴퓨터 안에서 빨리 실패를 확인하도록 짧은 값을 씁니다. 실제 장비에 그대로 옮기지 않습니다. headless 시뮬레이터의 external-peer 시나리오는 외부 프로그램과 연결하므로 더 긴 값을 씁니다.

옵션 C++ 튜토리얼 C# 튜토리얼 headless external-peer
T3 (t3_ms, T3Milliseconds) 5000 2000 45000
T5 (t5_ms) 1000 20 10000
T6 (t6_ms) 2000 2000 5000
T7 (t7_ms) 2000 5000 10000
T8 (t8_ms) 1000 2000 5000
연결 시도 (connect_timeout_ms) 20 100 10
쓰기 (write_timeout_ms) 2000 2000 5000

connect_timeout_ms는 Active 쪽 연결 시도 한 번에 쓰는 시간입니다. 이 동안 poll 호출이 멈출 수 있습니다. write_timeout_ms 안에 쓰기가 끝나지 않으면 TRANSPORT_ERROR(작업 Write, 종류 TimedOut)가 납니다.

튜토리얼 예제의 옵션 코드
tutorial/tutorial_options.hpp
#pragma once
#include "pdcomm_gem.hpp"
namespace tutorial {
PdcommSecsLimits itemLimits() {
return pdcomm::secsLimits(4096, 4096, 128, 8);
}
PdcommTcpOptions tcpOptions(uint32_t mode) {
PdcommTcpOptions value = {};
value.struct_size = sizeof(value);
value.version = PDCOMM_TCP_OPTIONS_VERSION;
value.mode = mode;
value.session_id = 7;
value.initial_system_bytes = 100;
value.t3_ms = 5000;
value.t5_ms = 1000;
value.t6_ms = 2000;
value.t7_ms = 2000;
value.t8_ms = 1000;
value.connect_timeout_ms = 20;
value.shutdown_timeout_ms = 200;
value.write_timeout_ms = 2000;
value.max_frame_bytes = 4110;
value.max_events = 96;
value.max_queued_bytes = 32768;
value.max_write_frames = 8;
value.max_write_bytes = 16384;
value.max_io_chunk = 4096;
value.max_application_events = 96;
value.max_application_bytes = 32768;
value.poll_budget = 16;
value.item_limits = itemLimits();
return value;
}
}
tutorial/PDComm.Tutorial/TutorialOptions.cs
using PDComm;
internal static class TutorialOptions
{
internal static readonly SecsLimits Limits = new(8192,4096,512,24);
internal static GemFormattedProgramConfiguration Configuration() => new(
new(4, 128, 512, 8, 8, 16, 32), new(4, 4, 8, 1024, 8, 8, 16, 32),
new(4, 4, 8, 1024, 8, 2048, 8, 8, 16, 32), new(4, 4, 8, 1024, 8, 8, 16, 32),
new(4, 32, 4, 8, 4, 32, 1024, 4096, 8, 8, 16, 32), new(4, 128, 512, 8, 8, 8, 16, 32));
internal static GemFormattedProgramCapabilityCommand Capability() => new("RUN", "Run", true, 0, [], [], [], 0, [], [], []);
internal static HsmsOptions Transport(HsmsMode mode) => new()
{ Mode = mode, SessionId = 7, InitialSystemBytes = 1, T3Milliseconds = 2000, T5Milliseconds = 20,
T6Milliseconds = 2000, T7Milliseconds = 5000, T8Milliseconds = 2000, ConnectTimeoutMilliseconds = 100,
ShutdownTimeoutMilliseconds = 1000, WriteTimeoutMilliseconds = 2000, MaxFrameBytes = 8206,
MaxEvents = 128, MaxQueuedBytes = 65536, MaxWriteFrames = 64, MaxWriteBytes = 65536,
MaxIoChunk = 4096, MaxApplicationEvents = 128, MaxApplicationBytes = 65536, PollBudget = 32, ItemLimits = Limits };
internal static GemHostOptions HostOptions() => new() { MaxPendingIds = 64, ItemLimits = Limits };
internal static GemEquipmentOptions EquipmentOptions() => new()
{ Model = "PDComm", SoftwareRevision = "0.1.0", InitialControl = GemControlState.HostOffline,
OnlineMode = GemOnlineMode.Remote, MaxVariables = 8, MaxMetadataBytes = 1024, MaxValueBytes = 8192, ItemLimits = Limits };
internal static HsmsWorkerOptions WorkerOptions() => new()
{ CommandCapacity = 32, MaxCommandBytes = 65536, EventCapacity = 32, MaxEventBytes = 131072,
PollIntervalMilliseconds = 1, ShutdownTimeoutMilliseconds = 2000 };
}

증상: Active 쪽이 STATE tcp=5 gem=0(RetryWait)을 반복합니다.

아무도 기다리지 않는 포트로 Host를 연결하면 로그에 다음이 남습니다. T5(1초)마다 세대 번호를 늘려 다시 연결합니다.

{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"Stopped","to":"Connecting"},"generation":1}}
{"level":"error","component":"hsms","event":"transport_error","fields":{"connection_id":1,"detail":{"error_kind":"ConnectionRefused","generation":1,"operation":"Connect"},"generation":1}}
{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"Connecting","to":"RetryWait"},"generation":1}}
{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"RetryWait","to":"Connecting"},"generation":2}}
{"level":"error","component":"hsms","event":"transport_error","fields":{"connection_id":1,"detail":{"error_kind":"ConnectionRefused","generation":2,"operation":"Connect"},"generation":2}}

애플리케이션에는 TRANSPORT_ERROR 이벤트(작업 3 Connect, 종류 3 Refused)가 옵니다. 운영체제에 따라 다른 종류(예: TimedOut)로 보고될 수 있습니다. 시뮬레이터 GUI에서는 Diagnostics 독의 Application activity 표에 TCP state: Connecting -> RetryWait 바로 앞 행으로 TCP connect failed: connection refused가 표시됩니다. Windows는 닫힌 loopback 포트로의 연결을 약 2초 동안 다시 시도한 뒤에 거부를 알리므로, 그 전에 연결 제한 시간이 끝나 TCP connect failed: timed out이 표시될 수 있습니다.

확인할 것

  • Passive 프로그램이 실행 중이고 같은 포트에서 LISTEN을 출력했는지 확인합니다.
  • Passive 쪽이 127.0.0.1에 바인드했다면 다른 컴퓨터에서는 연결할 수 없습니다. 실제 네트워크 주소로 바인드합니다.
  • 방화벽이 포트를 막는지 확인합니다.
  • 양쪽이 모두 Active이면 아무도 기다리지 않으므로 연결되지 않습니다.

증상: Passive 프로그램이 시작하자마자 끝납니다. Passive 끝점은 만들 때 바로 포트에 바인드하므로 pdcomm_tcp_create가 PDCOMM_IO_ERROR를 반환합니다. 이벤트는 생기지 않습니다.

같은 포트를 쓰는 Equipment를 두 개 실행하면 두 번째 프로그램이 다음을 출력하고 종료 코드 1로 끝납니다.

PDComm native operation failed

C# 예제는 다음 예외를 출력합니다.

PDComm.PdcommException: PDComm native operation failed with status IoError.

시뮬레이터 GUI에서는 Start session을 누르면 SESSION 카드가 Faulted로 바뀌고, 상태 표시줄과 Diagnostics 패널의 Application activity에 다음 메시지가 남습니다.

start failed [CORE_FAILURE]: core operation failed with status 12 (IO_ERROR); check that the address is free and reachable
Address가 127.0.0.1:5000인 Equipment 세션의 SESSION 카드가 Faulted이고, Diagnostics 패널에 status 12 (IO_ERROR) 시작 실패가 기록된 Session overview 화면Address가 127.0.0.1:5000인 Equipment 세션의 SESSION 카드가 Faulted이고, Diagnostics 패널에 status 12 (IO_ERROR) 시작 실패가 기록된 Session overview 화면

확인할 것: 그 포트를 쓰는 프로그램을 찾습니다.

터미널 창
lsof -nP -iTCP:5000 -sTCP:LISTEN
터미널 창
Get-NetTCPConnection -LocalPort 5000 -State Listen

macOS에서는 제어 센터(Control Center)의 AirPlay 수신 모드가 5000번 포트를 모든 주소(*:5000)에서 기다립니다. 위 lsof 명령을 실행하면 ControlCe 프로세스가 보입니다.

COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
ControlCe 1305 user 11u IPv4 0x32a01e9144f8b294 0t0 TCP *:5000 (LISTEN)

이때 127.0.0.1:5000에는 바인드할 수 있지만 0.0.0.0:5000은 실패합니다. 다른 포트를 쓰거나 시스템 설정 > 일반 > AirDrop 및 Handoff에서 AirPlay 수신 모드를 끕니다.

TCP는 연결되지만 Selected가 되지 않음

섹션 제목: “TCP는 연결되지만 Selected가 되지 않음”

증상: Active 쪽이 STATE tcp=3 gem=0(NotSelected)에 머무르다가 끊기고 다시 연결합니다.

TCP 연결은 받지만 Select.req에 답하지 않는 상대에 연결하면 로그에 다음이 남습니다. T6(2초)가 지나면 연결을 끊고, T5 뒤 다시 연결합니다.

{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"Connecting","to":"NotSelected"},"generation":1}}
{"level":"error","component":"hsms","event":"transaction_failed","fields":{"connection_id":1,"detail":{"generation":1,"reason":"T6Timeout","system_bytes":100},"generation":1}}
{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"NotSelected","to":"RetryWait"},"generation":1}}
{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"RetryWait","to":"Connecting"},"generation":2}}

확인할 것

  • 상대 포트가 HSMS 서버인지 확인합니다. 다른 종류의 서버도 TCP 연결은 받습니다.
  • 상대에 이미 다른 Host가 연결되어 있는지 확인합니다. 다음 절을 참고합니다.
  • 상대가 너무 바빠 T6 안에 답하지 못한다면 T6를 늘립니다.

HSMS-SS 연결 하나에는 Host 하나만 붙습니다. PDComm Passive 끝점은 연결이 이미 있으면 새 연결을 받지 않습니다. 두 번째 Host의 TCP 연결은 운영체제 대기열에서 완료되지만 HSMS 응답이 없으므로 T6가 지납니다.

첫 번째 Host가 통신 중인 튜토리얼 Equipment에 두 번째 Host를 연결하면 두 번째 Host는 STATE tcp=3 gem=0을 출력하고, 로그에는 다음이 남습니다.

{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"Connecting","to":"NotSelected"},"generation":1}}
{"level":"error","component":"hsms","event":"transaction_failed","fields":{"connection_id":1,"detail":{"generation":1,"reason":"T6Timeout","system_bytes":100},"generation":1}}
{"level":"info","component":"hsms","event":"state_changed","fields":{"connection_id":1,"detail":{"from":"NotSelected","to":"RetryWait"},"generation":1}}

다른 구현의 장비는 Select.rsp에 상태 1(이미 활성)로 답하기도 합니다. 그러면 FAILED(이유 7, SelectStatus)가 오고 value1이 1입니다. 로그의 이유는 SelectStatus(1)입니다.

해결: 첫 번째 Host 연결을 끝낸 뒤 연결합니다. 장비 하나에 여러 Host가 필요하면 장비가 여러 포트나 여러 세션을 제공하는지 확인합니다.

SEMI E37은 Select.rsp의 상태 값을 다음과 같이 정합니다(SEMI E37, Select 절차).

상태 뜻 PDComm
0 통신 수립 Passive 끝점이 정상 Select에 보냅니다.
1 이미 통신 중 이미 Selected일 때 보냅니다.
2 준비되지 않음 보내지 않습니다.
3 연결 한도 초과 보내지 않습니다.

0이 아닌 상태를 받으면 PDComm은 FAILED(이유 7)를 알리고 NotSelected에 머뭅니다. T7이 지나면 연결을 끊고 다시 시도합니다.

PDComm이 보내는 Reject.req의 이유는 다음과 같습니다.

이유 뜻 보내는 경우
1 지원하지 않는 SType 알 수 없는 메시지 종류를 받았습니다.
2 지원하지 않는 PType SECS-II가 아닌 본문 형식을 받았습니다.
3 열린 거래 없음 요청하지 않은 Select.rsp, Deselect.rsp, Linktest.rsp를 받았습니다.
4 선택되지 않음 Selected가 아닌데 데이터 메시지를 받았습니다.

상대가 내 요청을 Reject.req로 거부하면 FAILED(이유 6)가 오고 value1에 거부된 유형, value2에 이유가 들어 있습니다.

Deselect.req를 받으면 PDComm은 상태 0으로 답하고, 대기 중인 요청을 FAILED(이유 5, Deselected)로 끝낸 뒤 NotSelected로 돌아갑니다. Separate.req를 받으면 연결을 끊습니다. 애플리케이션이 Selected 상태에서 끝점을 멈추면 PDComm이 Separate.req를 보내고 대기 중인 요청을 FAILED(이유 1, Cancelled)로 끝냅니다.

증상: tcp=4(Selected)까지는 되지만 S1F13이 응답 없이 실패합니다.

HSMS-SS의 Select 같은 제어 메시지는 세션 ID로 0xFFFF를 쓰므로 세션 ID가 달라도 Selected가 됩니다. 그러나 데이터 메시지는 받는 쪽에서 버려집니다. 세션 ID 8로 설정한 Equipment에 세션 ID 7인 튜토리얼 Host를 연결하면 Host는 T3(5초) 뒤 다음을 출력합니다.

RESULT kind=3 request=1 outcome=0
STATE tcp=4 gem=1

Equipment 로그에는 받은 메시지를 버린 기록이 남습니다.

{"level":"error","component":"hsms","event":"protocol_error","fields":{"connection_id":5,"detail":{"error":"WrongSession { expected: 8, received: 7 }","generation":1,"system_bytes":101},"generation":1}}

Host 로그에는 T3 시간 초과가 남습니다.

{"level":"error","component":"hsms","event":"transaction_failed","fields":{"connection_id":1,"detail":{"generation":1,"reason":"T3Timeout","system_bytes":101},"generation":1}}

해결: 양쪽 세션 ID를 같게 맞춥니다. 튜토리얼 예제는 7을 씁니다. 시뮬레이터 GUI의 Session ID 기본값은 0이므로 튜토리얼과 연결할 때는 7로 바꿉니다.

증상: 요청이 RESULT kind=3(Failed)로 끝납니다. 로그의 이유는 T3Timeout입니다.

다음 순서로 T3 시간 초과를 직접 재현할 수 있습니다. macOS와 Linux 터미널 세 개를 씁니다.

  1. 터미널 A에서 Equipment를 시작합니다.

    터미널 창
    "$PDCOMM_ROOT/bin/pdcomm-tutorial" equipment passive 127.0.0.1:5000
  2. 터미널 B에서 로그를 켜고 Host를 시작한 뒤 establish를 입력합니다.

    터미널 창
    mkdir -p logs
    PDCOMM_LOG=debug PDCOMM_LOG_FILE=./logs/host.jsonl "$PDCOMM_ROOT/bin/pdcomm-tutorial" host active 127.0.0.1:5000
  3. 터미널 C에서 Equipment 프로세스를 일시 정지합니다.

    터미널 창
    kill -STOP $(pgrep -f 'pdcomm-tutorial equipment')
  4. 터미널 B에서 values 1 2를 입력합니다. C++ 튜토리얼의 T3인 5초 뒤 다음이 출력됩니다.

    RESULT kind=3 request=3 outcome=0
  5. 터미널 C에서 Equipment를 다시 실행합니다.

    터미널 창
    kill -CONT $(pgrep -f 'pdcomm-tutorial equipment')

    Equipment는 멈춰 있던 동안 받은 S1F3을 처리하고 늦은 S1F4를 보냅니다.

  6. 터미널 B에서 다시 values 1 2를 입력합니다. 이번에는 RESULT kind=2 request=3 outcome=5가 나옵니다. 연결은 끊기지 않았습니다.

로그를 확인합니다.

터미널 창
grep -E '"event":"(transaction_failed|protocol_error)"' ./logs/host.jsonl
{"level":"error","component":"hsms","event":"transaction_failed","fields":{"connection_id":1,"detail":{"generation":1,"reason":"T3Timeout","system_bytes":102},"generation":1}}
{"level":"error","component":"hsms","event":"protocol_error","fields":{"connection_id":1,"detail":{"error":"UnexpectedReply","generation":1,"system_bytes":102},"generation":1}}

첫 줄은 시스템 바이트 102인 요청이 T3 안에 응답을 받지 못했다는 기록입니다. 둘째 줄은 같은 시스템 바이트의 늦은 응답이 도착했지만 열린 거래가 없어 버렸다는 기록입니다.

흔한 원인

  • 상대가 그 메시지를 처리하지 않고 응답도 보내지 않습니다. 처리되지 않은 메시지를 참고합니다.
  • 세션 ID가 다릅니다. 위 세션 ID가 다름을 참고합니다.
  • 상대의 처리 시간이 T3보다 깁니다. 상대 사양에 맞게 T3를 늘립니다.
  • 상대 애플리케이션이 이벤트를 꺼내 처리하지 않습니다. PDComm은 내부 스레드가 없으므로 poll과 이벤트 처리를 계속 호출해야 응답이 나갑니다.

S1F13이 T3 안에 응답을 받지 못하면 결과는 RESULT kind=3 request=1 outcome=0이고, GEM 통신 상태는 NotCommunicating(1)으로 돌아갑니다. 상대가 COMMACK 1로 거부하면 결과는 RESULT kind=2 request=1 outcome=3(CommunicationRejected)이고, 역시 NotCommunicating으로 돌아갑니다.

PDComm은 S1F13을 자동으로 다시 보내지 않습니다. 원인을 고친 뒤 pdcomm_gem_begin_communication(튜토리얼의 establish)를 다시 호출합니다. NotCommunicating이 아닐 때 호출하면 InvalidState입니다.

T7과 T8에는 별도의 실패 코드가 없습니다. 로그에는 상태 변화와, 대기 중이던 요청이 있었다면 Disconnected 실패만 남습니다.

  • T7: TCP 연결 뒤 T7 안에 Selected가 되지 않으면 연결을 끊습니다. Active 쪽은 NotSelected → RetryWait, Passive 쪽은 NotSelected → Listening으로 바뀝니다. 상대가 TCP만 연결하고 Select.req를 보내지 않을 때 Passive 쪽에서 볼 수 있습니다.
  • T8: 한 메시지를 받는 도중 바이트 사이 간격이 T8을 넘으면 연결을 끊습니다. 네트워크가 멈췄거나 상대가 메시지를 나눠 쓰다가 멈춘 경우입니다.