김민결 8회기 AI 전사 모니터 미출력
— LiveKit 다운링크 데이터채널 123초 정지 원인 분석 분석 완료 · 코드 수정 없음 · 손실 원인층 미확정

마지막 업데이트 2026-10-01

수업: 2026-09-30 21:04~21:27 · roomId 6bdcf6ae-…_8 아동 단말: Android 10 · Chrome 152 · SKT LTE(118.235.x) 모드: LiveKit half_cascade 작성: 2026-10-01

1. 결론

모니터 버그가 아닙니다. agent는 AI 전사를 즉시 보냈습니다(publish ≤23ms). 그런데 LiveKit 서버 → 아동 단말 다운링크의 reliable 데이터채널이 최대 123초 정지해서 아동 단말 자체가 전사를 받지 못했습니다. 같은 경로의 AI 음성은 정상 재생됐습니다.

정지 도중 진행자가 활동을 전환하면서 LiveKit 방이 닫혔고, 대기 중이던 전사는 영구 유실됐습니다. 수업 전체에서 agent 응답 67턴 중 22턴이 아동 단말에 도착하지 않았습니다. 같은 이유로 모니터 말풍선과 DB 대화로그의 assistant 행도 함께 빠졌습니다.

주장 등급: A로그로 직접 확인 / B수치에 근거한 추론 / C가설.

판단	등급	근거 요약
모니터·소켓 중계 정상	A	아동 저장 1079건 = 모니터 적용 1079건, 지연 ≈50ms
agent 송신 정상	A	`voice_lifecycle_publish_succeeded` publish_latency_ms 최대 23ms
아동 측 문제	A	같은 30분 다른 방 336개는 ready ack 지연 중앙값 0.02초, 123초는 이 아동만. 워커 6대·노드 3대 공통 요소는 아동
다운링크 방향만 정지	A	아동→agent 텍스트·RPC 요청·ack(68ms) 정상, agent→아동만 지연
원인은 다운링크 패킷 손실 + SCTP 재전송 백오프	B	정지 구간에만 AI 음성 `concealedRatio` 최대 18.5%. 지연값 7.0·31.0·123초 = RTO 1초 지수 백오프 누적
연속 손실 이유(LTE 버스트 / MTU)	C	로그로 판별 불가

2. 인과 체인 (1번째 세션, job AJ_HW6Pau7V9bqp)

21:10:15.292 아동 LiveKit 방 연결 (TURN 경유)
21:10:15.576 agent ready_response 송신 (21:10:18.9까지 4회 재전송)       [agent 정상]
21:10:15.594 아동 마지막 데이터 수신 ─┐
21:10:17     아동 텍스트 "대화시작" 전송 → agent 즉시 수신(업링크 정상)   │
21:10:18.4   agent response-1 전사 publish (23ms)                       │ 다운링크 데이터
21:10:19.7   아동 AI 음성 재생 시작 (음성은 정상)                         │ 123초 수신 0건
21:10:22     RPC "Connection timeout" · "No response from OpenAI"        │
21:10:31~    AI 음성 concealedRatio 3~18.5% (다운링크 손실)               │
21:12:18.569 아동 ready_response 첫 수신 ────────────────────────────────┘ 재전송 성공
21:12:18.576 "Ack received for unexpected RPC request" (늦은 RPC 응답)
21:12:18.637 agent ready_ack 수신 (아동 수신 후 68ms)
21:12:19~25  response-1~3 전사 순서대로 도착 → DB assistant 행 3개 저장
21:12:26     진행자 활동 전환 → 방 종료(CLIENT_REQUEST_LEAVE)
             → response-4~12 영구 유실 (모니터·DB 모두 없음)

3. 전사가 모니터·DB에 도달하는 경로

agent (apps/livekit-agent)
  └ agent-event-log 토픽 publish (agent_transcript_delta / done)
      │  LiveKit reliable 데이터채널 (SCTP, 순서 보장)   ← 여기서 정지
      ▼
아동 단말 RoomEvent.DataReceived (livekit-client-session.ts)
  └ handleAssistantTranscriptDelta / Done
      (entities/guest-session/lib/voice-session-event-handlers/assistant-transcript.ts)
      ├ onTranscriptUpdate → guestSocket.sendTranscript → ppi-socket → 모니터 말풍선
      └ (done일 때만) saveSessionLog(role:"assistant", occurredAt: Date.now()) → DB

행	저장 주체·시점	데이터채널 필요	이번 결과
user / text	아동 단말이 텍스트 전송 즉시 HTTP 저장 (use-ai-session.ts:817)	아니오	전부 기록
assistant / audio	아동 단말이 `agent_transcript_done` 수신 시 저장	예	늦게 기록 또는 누락

AI 발화를 DB에 저장하는 곳은 아동 단말 한 곳뿐입니다. agent 서버는 대화로그를 저장하지 않습니다. 그래서 "모니터 말풍선 없음"과 "DB assistant 행 없음"은 같은 사건의 두 결과입니다.

DB에 기록된 assistant 행 (기록 시각 = 수신 시각)

메시지	실제 발화(agent publish)	DB Created At	지연
민결아! 반가워~~ 여기서 만나니까 신기하다!	21:10:18.4	21:12:21	≈123초
그치? 우리 진짜 친구 됐다! 잘 지냈어?	21:10:27.2	21:12:23	≈116초
오케이! 그러면 오늘 뭐 제일 재밌었어?	21:10:34.3	21:12:25	≈111초

DB에서는 AI 행 3개가 user 행 12개 뒤에 몰려 있어 대화 순서가 뒤틀려 보입니다. 그 뒤 9턴은 행 자체가 없습니다.

4. 근거

4-1. agent 송신 시각 vs 아동 수신 시각 (agentResponseId 조인) A

정상 세션에서는 차이가 0.0초여서 단말 시계 차이는 없습니다.

1번째 세션 (HW6) 메시지별 지연 — agent publish 후 아동 수신까지 약 123초

메시지	agent publish (agent 로그)	아동 수신 (아동 로그)	지연
`ppi.ready_response`	21:10:15.576	21:12:18.569	122.99초
response-1 시작	21:10:18.053	21:12:19.592	121.5초
response-1 전사 완료 "민결아! 반가워~~"	21:10:18.363	21:12:21.007	122.6초
response-2 시작	21:10:26.935	21:12:22.273	115.3초
response-3 시작	21:10:34.037	21:12:24.642	110.6초
response-4~12	21:10:43 ~ 21:12:14	미수신	21:12:26 방 종료

21:10:15.594  아동 마지막 수신 (agent_input_lifecycle)
21:10:15.576~ agent는 계속 publish (≤23ms)   ── 아동 수신 0건 123초 ──
21:12:18.569  아동 첫 수신 (ready_response) → 밀린 메시지가 보낸 순서대로 도착

지연이 123초 → 110초로 줄어든 이유: 정지가 풀린 뒤 밀린 메시지가 원래 송신 간격보다 빠르게 몰려 들어왔기 때문입니다.

세션별 요약

job (연결 시각)	연결	agent→아동 지연	미수신
HW6 (21:10:15)	TURN	110~122초	12턴 중 9턴
7Gm (21:12:59)	TURN	0.4초	13초 만에 종료
G4U (21:13:13)	TURN	7~45초	13턴 중 3턴
avh (21:16:38)	TURN	0초 → 21:17:52부터 정지	10턴 중 4턴
de7 (21:19:04)	TURN	0초 → 21:20:04부터 정지	6턴 중 3턴
gS9 (21:20:41)	TURN	31.0·19.7·11.2초	8턴 중 1턴
ZJ2 (21:23:15)	TURN	7.0초 1회	7턴 중 2턴
iEP (21:24:26)	UDP	≤1초	0
zuz (21:26:18)	UDP	7.0·20·24초	0

TURN 상관은 UDP 세션(zuz)에서도 지연이 나서 기각했습니다.

4-2. ready 응답 → ack 지연, 같은 30분 전체 337개 job A

전체 중앙값              0.02초
AJ_HW6Pau7V9bqp (김민결)  123.06초   ← 유일한 이상값
다른 방 최대              3.26초 (1건)
상위 7개 중 김민결 job    5개 (0.84~1.09초, 평소에도 40~50배 느림)

아동 단말은 ready 응답을 받은 지 68ms 만에 ack를 보냈습니다. 늦은 것은 응답의 도착입니다. 이 아동의 job 9개는 agent 워커 6대·LiveKit 노드 3대에 흩어져 있었고, 같은 워커(172.31.3.157)에서도 정지 세션과 정상 세션이 섞여 있습니다. 공통 요소는 아동 연결뿐입니다.

4-3. 다운링크 패킷 손실의 정황 — AI 음성 concealedRatio B

Playout drift sample(5초 간격)의 concealedRatio = Δ concealedSamples / Δ totalSamplesReceived입니다(livekit-playout-drift-monitor.ts:275). RED·FEC·NACK로도 복구하지 못해 브라우저 PLC가 지어 채운 샘플의 비율이라, 실제 손실률은 이보다 높았을 수 있습니다.

HW6  21:10:31  3.1%  ███
     21:10:36  3.8%  ████
     21:10:46  6.2%  ██████
     21:11:01 18.5%  ██████████████████
     21:11:11  8.0%  ████████
     21:11:51  4.2%  ████
     21:12:16  6.1%  ██████          ← 123초 정지 구간
7Gm  21:13:05  2.3%  ██
G4U  21:13:20 13.5%  ██████████████  ← 33초 정지 구간
     21:13:25 ~ 21:27  전부 0 (샘플 161개)

같은 구간 jitterBufferAvgMs는 37~67ms로 평소 수준이라, 늦은 도착이 아니라 손실로 해석했습니다.

4-4. 재전송 백오프 지문 B

RTO 1초부터 2배씩, 최대 60초 (pion SCTP 기본)
  1+2+4                 =   7초   ← 관측 7.0초 3회
  1+2+4+8+16            =  31초   ← 관측 31.0초 3회
  1+2+4+8+16+32+60      = 123초   ← 관측 123.06초

같은 데이터 패킷의 재전송이 3·5·7번 연속 손실됐다고 보면 설명됩니다. reliable 채널은 순서를 보장하므로 그동안 뒤 메시지가 전부 대기합니다. 음성은 손실분을 PLC로 메우기 때문에 계속 들렸습니다.

4-5. 배제한 요인

모니터 렌더·필터: monitor-transcript-filter.ts, transcript-chat-area.tsx에 assistant를 버리는 조건 없음. 모니터 적용 로그가 아동 저장과 1:1로 일치함.
agent 처리 지연: publish ≤23ms.
아동 앱 큐잉: 수신 로그가 DataReceived 첫 줄에서 바로 기록됨.
업링크·일반 회선 단절: 같은 구간에 ppi-socket 미디어 연결의 RTT·손실이 정상이었고(heartbeat 생략 300회), ICE·연결 상태 변화도 0건.
방 끊김의 원인: 매번 CLIENT_REQUEST_LEAVE, 즉 앱이 활동 전환 때문에 스스로 나간 것으로 네트워크 단절이 아님.

5. 판별법 (재발 시)

아동 세션로그에서 LiveKit data received 공백 ≥7초와, 같은 구간의 AI_SPEAKING_START 존재를 확인 → 음성은 오는데 데이터만 정지.
Failed to flush … Connection timeout, Ack received for unexpected RPC request가 동반되는지 확인.
agent 로그(/ppi/livekit/prod/agent)의 agent_response_started publish 시각을 아동 수신 시각과 agentResponseId로 조인 → 지연이 7/31/123초 계열이면 이 케이스.
agent livekit_ready_ack_received − 첫 livekit_ready_response_sent가 수 초 이상이면 세션 시작부터 정지한 것.
Playout drift sample의 concealedRatio가 0보다 크면 다운링크 손실을 동반한 정지.

6. 미확정 · 한계

데이터채널 손실을 직접 센 카운터는 없습니다. 브라우저 getStats()는 SCTP 재전송 횟수를 제공하지 않고, LiveKit 서버 INFO 로그에도 없습니다.
agent → SFU 구간은 정황(다른 방 정상, 아동을 따라다니는 패턴)으로만 배제했습니다. publish_succeeded는 SDK 큐 적재까지만 보장합니다.
21:14 이후 7~31초 소형 정지 때는 concealedRatio가 0이었습니다. 이 정지들은 회선 손실인지 단말(Android 10 Chrome) SCTP 문제인지 구분하지 못합니다.
다운링크 대역폭·RTT는 기록되지 않습니다. ppi-socket 업링크 추정치는 0.27~1.0Mbps, RTT 23~54ms였고, 158~394ms 순간 급등이 7회 있었습니다.
연속 손실의 이유(LTE 버스트 손실 / TURN·LTE 오버헤드로 인한 MTU 초과)는 미확정입니다.

7. 개선 제안 (미적용)

제안	효과
agent 서버가 assistant 대화로그를 직접 저장 (또는 소켓 등 별도 경로로 전사 전달)	데이터채널이 막혀도 모니터·DB 유실 방지 — 근본 대책
assistant `occurredAt`에 agent 이벤트의 `source_timestamp` 사용	지연이 생겨도 대화 순서 보존
아동 단말: AI 발화 중 데이터 수신 공백 ≥7초면 LiveKit 방 재연결	막힌 SCTP association 초기화
`Playout drift sample`에 `packetsLost`·`nackCount`, `candidate-pair` RTT·candidateType, `data-channel` messagesReceived 추가	다음 재발 시 손실 여부를 로그로 직접 확정

8. 관련 문서 · 자료

LiveKit RPC 2초 response timeout · ACK pending 경고 원인 분석 — 같은 데이터채널 위의 RPC 시간 초과 기전.
LiveKit 도입 voice-agent 추상화 전체 플로우 — agent-event-log 이벤트 발행 위치.
이전 사례(최이안 20회기 9/1): 전사 말풍선이 183초간 안 뜨다가 한꺼번에 출력됨. 같은 시그니처이고, 당시에는 방이 닫히기 전에 풀려서 "버스트"로 보였음.
근거 원본: 아동 세션로그 session-20260930.jsonl.gz, LogRocket 아동 recording 01a0f236-c946-7522-bc00-13aa5296704e(8,000건 상한으로 21:22:58에서 잘림), agent 로그 ppi-livekit-agent-prod-20260930_2100-2130.log, Loki ppi-livekit 서버 로그, ppi-socket Guest transport state.