김지효 3회기 — 진행자 텍스트에 AI가 57초 늦게 응답 (응답 열린 뒤 텍스트 스트림 지연) 분석원인 일부 추정 · 수정 미적용

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

2026-10-13 사건 2026-10-08 17:43–17:45 job AJ_u5hR8nWBreBm · apps/livekit-agent (half-cascade)

요약

증상: 진행자가 아동 기기를 통해 보낸 텍스트 "응 나두 달콤하다고 느꼈어"에 AI가 답하지 않았다. 이후 재전송·"다음으로 넘어가고 싶어"·대화종료 명령도 모두 무시됐다. AI 답은 56.7초 뒤에 나왔다. 이 아동의 다른 텍스트 응답은 모두 0.8~3초 안에 시작됐다.

확정: 텍스트는 에이전트에 수락됐다(drop 없음). 이후 4건은 ppi.user_text_dropped(reason agent_speaking_interruptions_disabled)로 버려졌다. 늦게 나온 응답의 내용은 그 텍스트에 맞는 답이었다. TTS는 정상이었다(Typecast 첫 프레임 1.1초).

추정: response.created는 10초 안에 왔고, 그 뒤 텍스트 스트림이 57초 늦게 도착했다. 응답이 열린 뒤 단계에는 타임아웃이 없어서 그동안 세션은 "AI 말하는 중"으로 남았고, 그 상태가 이후 입력을 모두 버리게 했다. generate_reply timed out·update_chat_ctx timed out·OpenAI 에러는 이 아동의 job 8개에서 0건이다.

진행자 화면: user_text_dropped를 처리하는 웹 코드가 없어 진행자는 입력이 버려진 것을 알 수 없었다.

1. 시간순 인과

// 2026-10-08 KST · 방 ppi-ec739297-…-pingpong02_wj01 · job AJ_u5hR8nWBreBm (17:42:11~17:46:08)
17:43:42.76  response-5 완료 ("…너도 그렇게 느꼈어?")
17:43:52.456 진행자 텍스트 "응 나두 달콤하다고 느꼈어" → 아동 기기 → LiveKit publish
             → 에이전트 수락 (drop 없음) → session.generate_reply(user_input=…)
             → response.create 송신 → response.created 10초 내 수신 (추정)
             → current_speech 생성 = "AI 말하는 중"
             → 텍스트 delta 미도착 · 이 단계는 타임아웃 없음
17:43:57     클라이언트 경고 "No response from OpenAI within 5 seconds" (경고만, 취소 없음)
17:44:11     재전송         → user_text_dropped (agent_speaking_interruptions_disabled)
17:44:20     다음으로 넘어가고 싶어 → dropped
17:44:29/39  대화종료 ×2    → dropped
17:44:39.85  진행자 회기 초기화
17:44:49.13  response-6 "오, 진짜? 나랑 똑같네!…" 시작 (trigger tts_node) = 텍스트 후 56.7초
             → Typecast 첫 프레임 1.1초, 음성 정상

진행자 PC와 iPad 사이 시계 차이 약 4.2초(추정)는 아동 기기 시각 기준으로 맞췄다.

2. 코드 경로 — 왜 57초 동안 아무 입력도 안 받았나

에이전트 텍스트 수신 (`apps/livekit-agent/agent.py`)

_attach_ppi_text_transport (~4661): 입력 게이트(input_disabled, :4709) → 말하는 중이면 버림(agent_speaking_interruptions_disabled, :4723) → session.generate_reply(user_input=…)(:4741). 수락 경로에는 로그가 없다.
_agent_is_speaking(:4512)는 current_speech가 끝나지 않았는지로 판단한다. half-cascade(_build_half_cascade_session :1268)는 interruption이 False라 말하는 중 입력은 모두 버려진다.

vendor livekit-agents (`voice/agent_activity.py`)

:5139-5156 update_chat_ctx(conversation.item.create, 5초 타임아웃). 실패해도 WARNING만 남기고 진행.
:5185 _rt_session.generate_reply → :5201 await generate_reply_fut. 실패 시 :5202-5210에서 failed to generate a reply ERROR 후 listening 복귀.
:5213 _realtime_generation_task: 텍스트 스트리밍 단계, 타임아웃 없음. 이번 사건이 머문 구간(추정).

vendor OpenAI 플러그인 (`realtime/realtime_model.py`)

generate_reply(:1958)가 response.create 송신, 10초 타이머 _on_timeout(:1989-1992)이 RealtimeError("generate_reply timed out.")을 설정.
같은 future를 실패시키는 다른 경로: 재연결 discard(:1152), realtime session closed(:1215), OpenAI error 이벤트(:2818). 각각 메시지가 다르다.
:2255-2263 타임아웃 뒤 늦게 온 response.created는 cancel하고 discarding response that arrived after it was timed out or interrupted WARNING.

웹 클라이언트: apps/web에 user_text_dropped 처리 코드가 없다. 5초 경고(No response from OpenAI within 5 seconds)도 로그만 남기고 취소하지 않는다.

3. 증거와 한계

항목	결과
텍스트 수락	drop 이벤트 없음 → 수락 (직접 수락 로그는 없음)
말하는 중 상태	이후 4건 drop reason `agent_speaking_interruptions_disabled` → `current_speech` 진행 중
응답 내용	response-6이 그 텍스트에 맞는 답
타임아웃·에러	job 8개 모두 `generate_reply timed out`/`update_chat_ctx timed out`/discard/OpenAI 에러/`agent_session_error` 0건
다른 방	같은 시간 다른 방은 정상 응답
TTS	Typecast 첫 프레임 1.1초, 정상

확인 못 한 것: response.create 송신·response.created 수신·첫 text delta 수신 시각은 로그가 없다. OpenAI 세션 ID(sess_)도 없다(로그의 request_id는 Typecast 것). 그래서 "응답은 열렸고 스트림이 늦었다"는 추정이며, OpenAI 처리 지연인지 WebSocket 구간 지연인지는 구분할 수 없다.

4. 같은 날 다른 사례 — `generate_reply timed out` 6건

Grafana(prod, ppi-livekit-agent, 검색어 generate_reply) 10/8 17:00~21:00. 김지효 건은 없다. 이벤트마다 2~3줄은 포맷 중복 출력이다.

시각	job	userId · 활동
17:51:25	AJ_WbyuzgiZpoEX	583bd4fa · newpp08_hrv1
18:37:20	AJ_DPZSgJFA4BFD	a80874c4 · pingpong02_wj01
19:06:43	AJ_ZQShYApcUvX3	233fb301 · tiki_basic
20:17:41	AJ_hGpEa9HwBpvx	00ddb4c1 · newpp06_woosung
20:18:36	AJ_GHQ6eGhoen5j	8abb6c72 · newpp16_jyv1
20:36:20	AJ_5Hhvxe5PvCeD	35df226d · tiki_basic

의미: 이 문구는 10초 타이머 한 곳에서만 만들어진다. 6건 모두 response.create를 보낸 뒤 10초 안에 response.created를 받지 못한 것이다. 그 턴은 응답 없이 끝난다(늦게 온 응답도 버림) — 아동은 그 턴 AI 응답을 듣지 못했을 것(추정).
미확인: 늦게라도 도착했는지(discarding response 유무), 요청이 실제로 OpenAI까지 나갔는지. 17:51 건만 확인했다.

// 17:51 AJ_WbyuzgiZpoEX — 세션 전체가 약 20초 막혔다가 한꺼번에 도착
17:51:07     user_turn_committed
17:51:10     STT provider final 실패 → fallback
17:51:15     update_chat_ctx timed out (WARNING)
17:51:17     user_text_dropped
17:51:25.065 generate_reply timed out
17:51:30     OpenAI error item_create_invalid_previous_item_id + discard + agent_session_error(recoverable)
17:51:37     다음 턴 정상

여기서 generate_reply timed out은 원인이 아니라 결과다. OpenAI 측인지 네트워크인지는 구분 불가.

17:22:34 AJ_jaoyiNjqxiV9 discard는 타임아웃이 아니다. 참가자 퇴장(CLIENT_INITIATED)으로 세션이 닫히며 취소됐고 0.1초 뒤 온 응답을 버린 정상 정리다.

외부 보고: LiveKit community 1367 — 2026-06 무렵부터 gpt-realtime의 generate_reply(10초)·update_chat_ctx(5초) 타임아웃 증가 보고, 원인 미상. 1508 — 타임아웃 뒤 response.cancel 미송신 버그(우리 vendor엔 discard·cancel 처리 있음).

5. 부록 — 같은 시간대 워커 배정 실패는 0건

17:00~17:59 방 244개 모두 배정. failed to assign job to worker 3건(17:09:06, 17:15:15, 17:17:56)은 3ms 안에 다른 워커로 재배정.
에이전트 로그 job 231건(13건 적음)은 17:49 이후 새 워커 4대 로그가 export에서 빠진 것.
클라이언트 쪽 배정 타임아웃: apps/web/lib/voice-agent/livekit-client-session.ts:80 LIVEKIT_AGENT_READY_TIMEOUT_MS = 10000, 재시도 1회(livekit-readiness-retry.ts, 300~1200ms).

6. 개선 제안 (미적용)

관측 로그 추가: OpenAI 세션 ID, response.create 송신 시각, response.created 수신 시각·response ID, 첫 text delta 수신 시각을 INFO로. (LK_OPENAI_DEBUG는 원문 전체라 PII가 남아 운영 사용 불가)
텍스트 수락 로그: _attach_ppi_text_transport 수락 경로에 한 줄.
응답 열린 뒤 첫 출력 감시: response.created 후 N초 안에 delta가 없으면 cancel·재요청.
진행자 화면 표시: user_text_dropped를 진행자에게 알려 "AI 응답 대기 중이라 무시됨"을 보이게.

7. 판별 방법과 데이터 출처

무응답 턴 분류: 같은 job에서 ① generate_reply timed out 있음 → response.created 10초 미수신 ② 없음 + 이후 user_text_dropped(agent_speaking…) 연속 → 응답은 열렸고 출력이 늦음(이번 사건) ③ input_disabled drop → 입력 게이트.
늦은 도착 확인: 같은 job에서 discarding response that arrived after it was timed out 검색.
사용한 자료: 세션 로그 lesson-log-20261008.jsonl.gz(실제 평문), 아동·진행자 LogRocket(아동 쪽 9000건 상한으로 17:44:52에서 끊김), agent 로그 export, Grafana CloudWatch /ppi/livekit/prod/agent, LiveKit 서버 로그.

요약