자동전환 미반영 — 게스트 socket.io 업링크 26초 stall 원인 분석 및 로깅 추가 분석로깅

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

작성일: 2026-06-16 사고일: 2026-06-15 room: id-011…_42 상태: 🟢 원인 확정(서버 로그) · 감지 로깅 추가(tsc 클린) · 재전송/모니터 표시 후속

증상 VOC

핑퐁이(AI)가 자동전환 멘트 "정말 고마워… 그러면 같이 한번 찾으러 가보자!"를 말해 조건이 매칭됐는데, 진행자 모니터에서 다음 스텝으로 안 넘어감. 진행자가 수동 점프·"새로고침"으로 개입했고, 그 과정에서 아동이 직전 활동(하랑대화1)으로 되돌아가 같은 대화를 다시 시작함.
분석 방법: LogRocket 아동/진행자 세션 양쪽 + Grafana ppi-socket Loki 서버 로그를 같은 roomId·시각으로 교차 정렬. (아동 세션 → roomId → 진행자 세션 매칭)

결론 — 한 줄

자동전환 자체는 아동 쪽에서 정상 발동(06:04:54)했으나, 아동의 전환 통지(guest-step-update act1 + guest-auto-finish) emit이 서버에 도달하는 데 약 26초 지연됐다. 서버가 06:05:20까지 전환을 몰랐으므로 모니터도 받을 수 없었고, 그 사이 진행자의 수동 개입이 stale 상태를 덮어써 아동을 회귀시켰다. 병목은 게스트의 socket.io 업링크(guest→server 송신)였다 — 서버·인프라·다른 룸·앱 코드는 모두 정상.

타임라인 (게스트 클라 · 서버 · 진행자)

06:04:54.317  [게스트] auto-finish 발동 → goToNextStep (하랑대화1→2 자체 전환)
06:04:54.322  [게스트] socket.emit(guest-step-update act1) · notifyAutoFinish 호출 ✅
              └ 클라는 emit 호출했으나… 서버 미도달
06:04:56.7    [게스트] 호스트 "응" 메시지 수신 정상(다운링크 OK)
06:05:00.909  [서버]  Host changed step act1 ← 진행자 수동 점프(host→server 실시간 정상)
06:05:06.507  [서버]  monitoring peer …c7c32921 disconnect ← 진행자 모니터 새로고침
06:05:07.046  [서버]  Host requested room state {hasState:true} → stale(act0/1) 복원
06:05:17/18   [서버]  Host changed step act0/1 ← 진행자 "새로고침" 버튼(stale push) → 아동 회귀
06:05:20.580  [서버]  Guest auto-finish {matchedCondition} ← 26초 만에 첫 도달
06:05:20.623  [서버]  Guest step update act1 ← 26초 만에 첫 도달
정상일 땐 게스트 emit→서버 수신이 ~0.05초(직전 act0/1은 06:04:53.319 emit → 06:04:53.272 수신). act1만 26.3초 지연.

근거 — 서버 로그로 확정

Grafana ppi-socket 조회로 stall 확인

대시보드 실시간 로그 패널(ppi-logs)은 행 가상화로 스크롤이 안 돼, Loki query_range API를 직접 호출해 roomId로 필터링했다.

# LogQL — 룸 단위 전 인스턴스, 시각 윈도우
{service="ppi-socket", env=~"prod"} |= "id-011-586a-4d1f-a415-747776dec5c7_42"

# 패널이 가상화돼 스크롤 불가 → Grafana 프록시로 직접 호출
GET /api/datasources/proxy/uid/<lokiUid>/loki/api/v1/query_range
    ?query=...&start=<ns>&end=<ns>&direction=forward&limit=5000

① 게스트→서버 step-update 수신 (26초 공백)

06:04:53.272  Guest step update in room …_42 {"activityIndex":0,"stepIndex":1}   ← 마지막
              ⟨ 06:04:54 게스트가 act1 emit… 서버 수신 0건 ⟩
06:05:20.580  Guest auto-finish from guest-…_42 {"matchedCondition":"그러면같이한번찾으러가보자!"}  ← 26s 만에
06:05:20.623  Guest step update in room …_42 {"activityIndex":1,"stepIndex":0}   ← 26s 만에

② 호스트 모니터 새로고침(리마운트) + stale 복원

06:05:00.909  Host changed step …_42 {act1}                       ← 진행자 수동 점프(정상 실시간)
06:05:06.507  Cleaning up peer monitoring:…c7c32921… after disconnect ← 모니터 소켓 끊김
06:05:07.040  Peer …c7c32921…-545e7890 joined room, found 3 existing producers ← 재입장
06:05:07.046  Host requested room state …_42 {"hasState":true}    ← stale(act0/1) 복원

③ 게스트 mediasoup transport RTT — 동일 28초 공백

# {…} |= "Guest transport state: guest-id-011…_42"
04:52.307  RTT=9ms      ← 정상(초당 보고)
   ⟨ 04:52 → 05:20  보고 0건 (step-update 공백과 동일 구간) ⟩
05:20.580  RTT=9ms / 05:20.715  RTT=102ms  ← 복구 찰나 스파이크

RTT 값이 아니라 보고 자체가 28초 끊김 = 게스트發 모든 데이터(step-update·auto-finish·transport stat)가 그 구간 안 올라감.

④ 다른 룸과 비교 — 같은 시각 정상 (서버/인스턴스 무죄)

# {…} |= "Guest step update in room" — 06:04:50~06:05:22, 룸별 최대 공백
a77c4cf8…_5    6건   maxGap 5.4s   ← 정상 연속
id-011…_42   7건   maxGap 27.4s  ← 우리 룸만 이상
결론: 같은 시각 다른 룸은 정상, 우리 룸의 host→server·server→guest도 정상 → 서버·인스턴스 장애 아님. 오직 이 게스트의 업링크(guest→server)만 26초 stall.

왜 disconnect가 안 떴나 (= 복구도 안 걸림)

engine.io 하트비트는 서버 PING(다운링크) → 클라 PONG(업링크). PONG도 같은 WebSocket/TCP 스트림이라 stall 동안 같이 묶인다. 그런데:

26초 stall이 engine.io ping 타임아웃 허용범위(기본 pingInterval 25s + pingTimeout 20s, 약 20~45초) 안에 들어, 업링크 복구 시 밀린 PONG이 타임아웃 전에 전달됨 → 서버가 disconnect로 처리하지 않음.

disconnect 이벤트가 없으니 socket.io 재연결·앱의 connect 기반 복구가 하나도 안 걸렸고, 보낸 emit은 그냥 26초 대기. (※ 25/20s는 기본값 — 단, "disconnect 미발생" 경험 사실만으로 "한계 미초과"는 확정)

왜 모니터 네트워크 경보도 안 떴나 (탐지 사각지대)

useMonitorNetworkLevel은 4개 입력을 보는데, 이 stall은 전부 미충족:

입력감시 대상stall 중
guestTransportRtt ≥400ms ×2WebRTC(UDP) 미디어 RTT업데이트 끊겨 마지막 ~9ms에 stale → 임계 미달
트랙 7초 끊김track.readyState==="live"미디어 안 흘러도 "live" 유지
socketConnected 7초모니터 자신의 소켓게스트 소켓 아님 + connected
bitrate/packetLossWebRTC stats업데이트 끊겨 stale
핵심 사각지대: 경보는 WebRTC 미디어(UDP) 채널을 보는데 실제 막힌 건 socket.io 시그널링(TCP) 업링크 — 서로 다른 채널. 게다가 stall은 "나쁜 값"이 아니라 "값이 안 옴(stale)"으로 나타나 RTT 임계 로직에 안 걸림. 그래서 진행자는 아무 경고 없이 멈춘 화면을 보고 수동 개입했다(2차 피해).

2차 피해 — "새로고침" 버튼의 stale push

진행자 모니터의 guestCurrentStep게스트發 이벤트로만 갱신된다(use-host-socket.ts). 호스트 자신의 수동 점프는 갱신하지 않음. 26초간 게스트 업데이트 미수신 + 06:05:06 리마운트의 stale 복원으로 그 값은 하랑대화1에 멈춤.

"새로고침" 버튼(handleRefreshCurrentStep)은 그 stale한 guestCurrentStep(하랑대화1)을 게스트에 그대로 push → 이미 하랑대화2로 넘어간 아동을 하랑대화1로 되돌려 같은 대화를 재시작시킴.

단말 — 안드로이드 태블릿 추정 + 모바일 업링크

참고(미확정 경계): "socket.io 업링크가 막혀 서버 도달 26초 지연"은 확정. 다만 그게 socket.io(TCP) 한정인지 기기 전체 업링크(미디어 UDP 포함)인지, 물리 원인(radio/Wi-Fi/혼잡)이 무엇인지는 단말 네트워크 텔레메트리(WS bufferedAmount·WebRTC stats·radio)가 있어야 확정.

조치 — 업링크 stall 감지 로깅 추가 (LogRocket)

연결은 유지(disconnect 미발생)되나 emit이 서버에 안 닿는 stall을 클라가 ack+타임아웃으로 감지해 LogRocket 커스텀 이벤트로 기록. 사후 분석 시 "자동전환 미반영 = 업링크 stall"을 즉시 식별.

// apps/web/lib/socket-uplink-stall-detector.ts (신규)
export function emitWithUplinkStallDetection(eventName, payload, { timeoutMs = 5000, roomId }) {
  if (!socket.connected) { socket.emit(eventName, payload); return; } // 미연결은 버퍼링·판정 제외
  socket.timeout(timeoutMs).emit(eventName, payload, (err) => {
    if (err) trackEvent("GuestUplinkStall", {...});        // ack 미수신 = 업링크 정체 (시작 1회)
    else if (wasStalled) trackEvent("GuestUplinkRecovered", { stalledMs }); // 복구 1회
  });
}
파일변경
apps/web/lib/socket-uplink-stall-detector.ts신규 — ack+타임아웃 헬퍼 + LogRocket 기록
apps/web/lib/guest-step-utils.tsemitGuestStepUpdate → 헬퍼 경유
apps/web/entities/guest-socket/model/use-guest-socket.tsnotifyAutoFinish → 헬퍼 경유
apps/socket/src/sfu-socket/handlers/session-handlers.tsGUEST_STEP_UPDATE·GUEST_AUTO_FINISH 핸들러가 ack 응답
배포 순서 주의: ack는 서버가 응답해야 동작 → 서버(apps/socket) 먼저/동시 배포. 클라만 먼저 나가면 구버전 서버가 ack를 안 보내 모든 emit이 5s마다 타임아웃 → 거짓 GuestUplinkStall 폭주.
검증: web·socket 양쪽 tsc --noEmit 클린. 단 ack 왕복/타임아웃은 런타임 통합 동작이라 dev에서 네트워크 throttle로 실측 권장.

범위 & 후속

이번 작업은 감지·로깅만 — stall을 고치거나 재전송하지 않음. 백로그:

분석·로깅: 2026-06-16 / chulsu · 사고 LogRocket room id-011…_42 (2026-06-15 06:04~06:05 UTC) · Grafana ppi-socket Loki 교차검증