PPI-1012
로그 분석 v2
서버 로그 확정 v3

호스트·게스트 모두 접속했으나 매칭이 안 되는 현상

마지막 업데이트 2026-07-22

발생일: 2026-06-05 14:00 KST 담당: 철수 분석일: 2026-06-05 우선순위: 매우 높음
v1 결론 수정: 최초 분석에서는 "cross-instance peer-store 분리"를 1순위로 결론했으나, AWS 확인 결과 현재 소켓 서버는 단일 EC2 인스턴스로 운영 중임이 확인됨. cross-instance 가설은 폐기. 로그 심층 분석으로 실제 원인을 새로 추적함.
★ 수정 결론: 호스트 모니터링 클레임이 소켓 공식 단절(05:10:08) 이전에 이미 사라졌고, 소켓 재연결 후 hasStartedRef.current = true 플래그 때문에 HOST_START_MONITORING이 재발송되지 않아 게스트가 RoomNotFound를 받음.
v2 미확인 → v3 확정 (Grafana/Loki ppi-socket 서버 로그): v2가 "메커니즘 미확인"으로 남긴 클레임 제거의 정체가 서버 로그로 확정됨. 호스트 소켓은 서버 입장에서 04:55:55.10Z에 이미 disconnect됐고 (클라이언트가 인지한 05:10:08이 아님 — 백그라운드 탭 freeze로 클라/서버 단절 시각이 ~14분 괴리), 그 disconnect 핸들러가 호스트의 모니터링 클레임 monitoring:952d9107-…-monitoring-…_17을 직접 정리함. tab-hidden(04:55:38) 직후 Socket.IO pingTimeout으로 서버가 소켓을 끊은 것이 근본 트리거. 재연결(05:19:08) 후엔 JOIN_ROOM만 수행하고 START_MONITORING 재등록 0건 → hasStartedRef 버그도 서버 로그로 재확인.

사건 개요

2026-06-05 14:00 KST 아동059 아동 수업. 게스트(아동059)와 호스트(션) 모두 접속했으나 서로 인식하지 못함. 호스트는 노쇼 처리(completionStatus=300), 게스트는 standalone 모드로 AI와 수업 진행.

roomId: dc8e7ac9-dfe2-4a96-8684-de59d56c88ed_17

실패 세션 타임라인 — dc8e7ac9-..._17

게스트 측 (UTC)

04:54:07PageInitialized (/guest)
04:54:08PermissionGranted
04:54:20EntryRequest → WaitingApproval 응답 수신 ← 이 시점 호스트 모니터링 클레임 존재 확정
05:00:05V2FlowRedirect (입장 허용 신호)
05:00:10★ "RoomNotFound" — standalone 모드 진입 (1차)
05:00:42★ "RoomNotFound" — standalone 모드 진입 (2차)
05:00:43AI 응답: "시환아, 안녕! 잘 지냈어?" — AI와 수업 진행 확정

호스트 측 (UTC)

04:52:38monitor-dashboard 진입 (dc8e7ac9-..._17)
04:52:39get-peers 응답: {peers:[0]} — 아직 게스트 미접속이라 정상
04:52:39"No persisted room state found" — 최초 접속이라 정상
04:55:38★ Tab hidden (게스트 대기 중 호스트 자리 비움) — 클라이언트 기준
04:55:55★★ 서버 기준 Socket DISCONNECT (pingTimeout) → 호스트 monitoring 클레임 정리 [v3 서버 로그 확정]
05:00:10게스트 RoomNotFound — 클레임은 이미 4분 15초 전 제거됨
05:10:08클라이언트가 뒤늦게 "transport close" 인지 (탭 freeze로 지연, 서버 단절보다 14분 늦음)
05:18:56Socket 재연결 (V8bbpscP5O8NbNGlAAGr) — 서버 로그상 05:19:08
05:19:08재연결 후 JOIN_ROOM만 수행, START_MONITORING 재등록 0건 — 모니터링 클레임 미복구
05:19:07알림톡 발송 (노쇼 안내)
05:19:33completionStatus=300 (노쇼 처리)

핵심 발견: WaitingApproval = 모니터링 클레임 존재 증명

서버의 GUEST_REQUEST_ENTRY 핸들러는 peers Map에서 role === "host" && monitoringRoomId === roomId인 peer를 찾은 경우에만 WaitingApproval을 반환합니다.

// room-handlers.ts:228
const hostPeer = Array.from(peers.values()).find(
  (p) => p.role === "host" && p.monitoringRoomId === roomId,
);

if (!hostPeer) {
  callback({ error: "RoomNotFound" });  // line 253
  return;
}
// hostPeer 있을 때만 아래로 내려가서 WaitingApproval 반환
callback({ status: "WaitingApproval", ... });

따라서 04:54:20 WaitingApproval = 그 시점 peers Map에 호스트 모니터링 클레임이 확실히 존재했음. 그 이후 04:55:55 서버측 소켓 disconnect 시점에 클레임이 제거됨 (v3에서 서버 로그로 확정 — 아래 참조).

타임라인 핵심 불일치

시각 (UTC) 이벤트 의미
04:54:20 게스트 → WaitingApproval 호스트 모니터링 클레임 peers Map에 존재 (확정)
04:55:38 호스트 tab hidden (클라) 클라이언트가 ping 응답 중단 시작 → 서버 pingTimeout 카운트다운
04:55:55 서버 Socket DISCONNECT [v3 확정] 서버 기준 단절. disconnect 핸들러가 호스트 monitoring 클레임 정리 → 여기서 클레임 소멸
05:00:10 게스트 → RoomNotFound 클레임은 이미 04:55:55에 제거됨 (4분 15초 전) → 당연한 결과
05:10:08 클라 "transport close" 인지 탭 freeze로 클라이언트가 단절을 14분 늦게 인지한 것. 서버 단절은 04:55:55이 진짜
05:19:08 호스트 소켓 재연결 JOIN_ROOM만 수행, START_MONITORING 재등록 없음 — 클레임 미복구
결정적 순서 [v3 정정]: 서버 단절(04:55:55) → 클레임 제거 → 게스트 RoomNotFound(05:00:10)
v2에서는 "소켓 단절(05:10:08)이 RoomNotFound(05:00:10)보다 뒤라 단절이 원인이 아니다"라고 봤으나, 이는 클라이언트가 인지한 단절 시각일 뿐. 서버 로그상 호스트 소켓은 04:55:55에 이미 disconnect됐고 그 즉시 클레임이 제거됐다. 즉 "소켓 끊겨서(서버 04:55:55) → 클레임 제거 → RoomNotFound(05:00:10)"가 맞는 인과. 클라/서버 단절 시각의 ~14분 괴리(탭 freeze)가 v2 분석을 오도했다.

get-peers:{peers:[0]}의 올바른 해석

v1 분석에서 04:52:39의 peers:[0]을 "호스트 클레임 없음"으로 해석했으나 이는 잘못된 해석입니다.

// connection-handlers.ts:484 — GET_PEERS 핸들러
for (const [, peerInfo] of peers.entries()) {
  if (peerInfo.roomId === roomId) {  // ← roomId 기준
    peersInRoom.push({ ... });
  }
}

모니터링 클레임(HOST_START_MONITORING으로 등록)은 roomId: null, monitoringRoomId: <실제 roomId>로 저장됩니다. GET_PEERS는 peerInfo.roomId만 확인하므로 모니터링 클레임은 항상 GET_PEERS 결과에 나타나지 않습니다. peers:[0]은 "방에 일반 peer가 없다"는 것이지 "모니터링 클레임이 없다"는 게 아님.

구조적 버그: hasStartedRef.current 미리셋 문제

소켓 재연결 후 HOST_START_MONITORING이 재발송되지 않는 이유:

// apps/web/features/monitor/room-monitoring/model/use-room-monitoring.ts:140
useEffect(() => {
  if (enabled && monitoringPeerId && !hasStartedRef.current) {
    hasStartedRef.current = true;  // ← 한 번 true가 되면 재연결 시에도 리셋 안 됨
    startMonitoring();
  }
}, [enabled, monitoringPeerId, startMonitoring]);

소켓이 재연결되어 새 socketId를 발급받아도, hasStartedRef.current는 컴포넌트가 언마운트되지 않는 한 true를 유지합니다. 즉, 소켓 재연결 후 호스트 쪽에서 모니터링 클레임을 서버에 재등록하지 않습니다.

tab-hidden 상태에서 서버가 peer를 일시적으로 정리(reaper 또는 brief transport drop)한 경우, 소켓 자체는 공식 단절 없이 복구되더라도 클레임은 사라진 채로 남습니다.

재현 시나리오 (v3 서버 로그 반영)

[04:52:50] 호스트 소켓 x8PY5tqkRRnGUV9bAAFL CONNECTED + JOIN_ROOM (서버 로그)
[04:52:39] 서버: peers Map에 모니터링 클레임 등록 (role:host, monitoringRoomId:roomId, roomId:null)
[04:54:20] 게스트 GUEST_REQUEST_ENTRY → peers Map에서 클레임 발견 → WaitingApproval
 
[04:55:38] 호스트 tab hidden (클라) → 브라우저가 ping 응답 throttle
[04:55:55] 서버 pingTimeout → Socket DISCONNECT (socketId x8PY…, matchingPeers:3)
disconnect 핸들러가 socketId에 묶인 3개 peer 일괄 정리:
  ① host base peer  ② monitoring 클레임  ③ host mediasoup transport
 
[05:00:05] V2FlowRedirect — 입장 허용 신호
[05:00:10] 게스트 GUEST_REQUEST_ENTRY → peers Map에 클레임 없음(이미 4분 전 제거) → RoomNotFound
 
[05:10:08] 클라이언트가 뒤늦게 "transport close" 인지 (탭 freeze, 서버보다 14분 늦음)
[05:19:08] 소켓 재연결 V8bbpscP…JOIN_ROOM만 수행 (서버 로그)
hasStartedRef.current === true → HOST_START_MONITORING 재발송 0건 (서버 로그 확인)
클레임 미복구 상태 지속 → 노쇼 처리

성공 세션 비교 — 411421c4-..._19

실패 세션 (dc8e7ac9-..._17)

04:52:38호스트 접속
04:55:38Tab hidden
05:00:10RoomNotFound (tab hidden 상태)
05:10:08소켓 단절
05:19:33노쇼 처리

성공 세션 (411421c4-..._19)

05:23:49호스트 접속
게스트 연결 전까지 Tab visible 유지
05:29:58게스트 접속 → 매칭 성공
소켓 단절 없음

핵심 차이: 게스트가 연결 시도하는 시점에 호스트 tab이 visible인지 여부. 성공 세션에서는 호스트가 tab hidden 없이 대기했고 소켓 단절도 없었음.

인프라 확인: 단일 EC2 인스턴스

❌ 폐기된 가설: Cross-instance peer-store 분리

v1에서는 소켓 서버가 여러 인스턴스로 운영될 경우 호스트·게스트가 다른 인스턴스에 붙어 로컬 메모리를 공유 못 하는 것이 원인이라고 결론했으나, AWS 콘솔 확인 결과 ppi-socket-prod EC2 인스턴스는 단 1개임이 확인됨. 동일 프로세스 내 메모리 공유는 보장되므로 cross-instance 가설은 현 장애의 원인이 아님.

* peer-ops.ts의 "Phase 3 shadow write" 설계는 향후 다중 인스턴스 확장 시 여전히 잠재적 위험 요소이나 현재 장애와 무관.

클레임 제거 메커니즘 — 확정 (v3, Grafana/Loki 서버 로그)

v2에서 "미확인"으로 남겼던 04:55:38~05:00:10 구간 클레임 제거를 ppi-socket 서버 로그(Loki)로 조회한 결과 완전히 특정됨. 후보 3개 중 "tab-hidden → 서버측 소켓 disconnect"가 정답이며, 메커니즘은 reaper가 아닌 Socket.IO pingTimeout disconnect 핸들러였다.

① 호스트 소켓은 서버 기준 04:55:55에 끊겼다 (socketId x8PY5tqkRRnGUV9bAAFL)
// {service="ppi-socket"} |= "x8PY5tqkRRnGUV9bAAFL"
04:52:50.567  [DIAG] Socket CONNECTED
04:52:50.817  [DIAG] JOIN_ROOM received
04:55:55.210  [DIAG] Socket DISCONNECT event        // ← tab hidden(04:55:38) +17초
04:55:55.210  [DIAG] Disconnect scanning peers
② 그 disconnect가 호스트 monitoring 클레임을 직접 정리했다
04:55:55.100Z WARN [DIAG] Disconnect scanning peers
   { socketId: x8PY5tqkRRnGUV9bAAFL, totalPeersInMap: 5,
     matchingPeersForThisSocket: 3, matchingPeerIds: [ 952d9107-…, role:host … ] }
04:55:55.101Z INFO Cleaning up peer 952d9107-…                                  after disconnect  // host base
04:55:55.101Z INFO Cleaning up peer monitoring:952d9107-…-monitoring-…_17 after disconnect  // ★ 클레임
04:55:55.102Z INFO Cleaning up peer 952d9107-…-…_17-65230892-…                  after disconnect  // transport (Closed 1)

socketId에 묶인 3개 peer(base / monitoring 클레임 / mediasoup transport)가 일괄 제거됨. 이 시점이 게스트 RoomNotFound(05:00:10)보다 4분 15초 앞 → RoomNotFound는 당연한 결과.

③ 재연결 후 모니터링 재등록은 끝까지 없었다 (hasStartedRef 버그 재확인)
// {service="ppi-socket"} |= "V8bbpscP5O8NbNGlAAGr"
05:19:08.193  [DIAG] Socket CONNECTED
05:19:08.445  [DIAG] JOIN_ROOM received        // ← JOIN_ROOM만. START_MONITORING 없음
05:20:34.646  [DIAG] Socket DISCONNECT event

// roomId 전 구간 START_MONITORING/monitoring 재등록 검색 결과: 0건
남은 확인거리 (사소)

서버 pingTimeout 임계값(~17초로 관측)이 Socket.IO pingInterval/pingTimeout 기본/설정값과 일치하는지, 그리고 모바일 백그라운드 탭에서 이 타임아웃이 얼마나 흔히 트리거되는지는 별도 측정 가치가 있음. 다만 이는 본 장애의 인과 사슬과 무관(원인은 이미 확정).

재현용 LogQL 쿼리 (Grafana → Loki, datasource P8E80F9AEF21F6940)

시간 범위: 2026-06-05 04:50~05:20 UTC (= 13:50~14:20 KST). Explore에서 datasource Loki 선택 후 아래 쿼리 실행. roomId / socketId만 바꾸면 다른 세션에도 재사용 가능.

# 1. 세션 전체 흐름 (roomId 기준) — 노이즈(MFCC/transcript) 많으니 아래 2~4로 좁히는 걸 권장 {service="ppi-socket"} |= "dc8e7ac9-dfe2-4a96-8684-de59d56c88ed_17"
# 2. ★ 호스트 소켓 생명주기 (CONNECT / JOIN_ROOM / DISCONNECT) — 가장 결정적 {service="ppi-socket"} |= "x8PY5tqkRRnGUV9bAAFL" # 최초 호스트 소켓 {service="ppi-socket"} |= "V8bbpscP5O8NbNGlAAGr" # 재연결 호스트 소켓
# 3. ★ 호스트 peer/monitoring 클레임 정리 추적 (monitor peerId 기준) {service="ppi-socket"} |= "uuid-0649"
# 4. disconnect / 클레임 정리 / 입장 이벤트만 필터 (roomId + 정규식) {service="ppi-socket"} |= "dc8e7ac9-dfe2-4a96-8684-de59d56c88ed_17" |~ "(?i)(disconnect|scanning peers|Cleaning up peer|RoomNotFound|REQUEST_ENTRY|START_MONITORING|reap|pending|grace)"

※ Grafana 프록시 직접 호출 시: /api/datasources/proxy/uid/P8E80F9AEF21F6940/loki/api/v1/query_range?query=…&start=<ns>&end=<ns>&limit=2000&direction=forward (start/end는 epoch nanoseconds). 라벨은 service = ppi-socket.

관련 코드 위치

파일라인내용
apps/socket/src/sfu-socket/handlers/room-handlers.ts 228–253 GUEST_REQUEST_ENTRY — 로컬 메모리 조회 + RoomNotFound 반환
apps/web/features/monitor/room-monitoring/model/use-room-monitoring.ts 140–144 ★ hasStartedRef.current 버그 — 소켓 재연결 시 미리셋
apps/socket/src/sfu-socket/handlers/monitoring-handlers.ts 139 HOST_START_MONITORING — 클레임 등록 (role:host, monitoringRoomId)
apps/socket/src/sfu-socket/handlers/connection-handlers.ts 484 GET_PEERS — roomId 기준만 조회 (모니터링 클레임 제외)
apps/socket/src/sfu-socket/peer-ops.ts 12–16 Phase 3 shadow write — 메모리 SoT, Redis shadow
apps/socket/src/sfu-socket/signalingHandler.ts 40 peers = new Map() — 프로세스 로컬 선언
apps/web/app/monitor-dashboard/[group]/[roomId]/page.tsx 135 enabled: hasHydrated && !!hostId — use-room-monitoring 활성화 조건

Fix 방향

1
★ hasStartedRef.current 소켓 재연결 시 리셋 (핵심)
소켓 재연결 이벤트 수신 시 hasStartedRef.current = false로 리셋하여 HOST_START_MONITORING이 재발송되도록 함.
// use-room-monitoring.ts — 소켓 재연결 감지 useEffect 추가
useEffect(() => {
  const handleReconnect = () => {
    hasStartedRef.current = false;  // 재연결 시 리셋
  };
  socket?.on("connect", handleReconnect);
  return () => { socket?.off("connect", handleReconnect); };
}, [socket]);
2
tab-hidden 중 소켓 pingTimeout 방지 / 서버측 클레임 복구 [원인 확정됨]
확정된 원인: tab-hidden 시 브라우저가 ping 응답을 throttle → 서버 pingTimeout(~17초 관측)으로 호스트 소켓 강제 disconnect → 클레임 정리.
→ ① 모니터 탭 hidden 시에도 keep-alive(주기 ping 또는 Web Worker 기반 heartbeat)로 소켓 유지, 또는 ② Socket.IO pingTimeout 상향, 또는 ③ disconnect 시 클레임을 즉시 제거하지 말고 grace 윈도우(예: 60초) 동안 보존 후 재연결되면 re-claim.
3
게스트 RoomNotFound UX 개선
현재: RoomNotFound → silent standalone 진입 (학생이 선생님 없이 수업하는 줄 모름)
개선: "선생님 연결을 기다리는 중입니다" 안내 + 30초 주기 재시도 (3회) + 1분 이상 미연결 시 알림
4
GUEST_REQUEST_ENTRY Redis fallback 추가 (중장기)
현재는 단일 인스턴스라 로컬 메모리 조회로 충분하나, 향후 다중 인스턴스 확장 대비. monitoring-handlers.ts:62resolveOtherMonitor 패턴 참조하여 hostPeer 없을 때 Redis peer-store 조회 경로 추가.
5
노쇼 자동 처리 가드
호스트가 noshow 처리 전 동일 학생의 다른 socket session 존재 여부 확인.
"이 학생이 다른 경로로 접속한 이력이 있습니다. 정말 노쇼 처리하시겠습니까?" prompt.

결정적 증거 요약