AI 미발화 원인 확정 — 빈 전사 캐시 키가 앞 턴 판정을 재생해 superseded_by_new_speech 오판 분석미수정

결론 — 앞 턴의 판정 결과가 다음 턴에 그대로 재생됐다

아동이 말을 끝내고 턴이 정상 커밋되고 전사까지 생성됐는데 핑퐁이가 16.7초간 아무 말도 하지 않았다. 원인은 SFU·전송·TTS가 아니라 agent의 턴 판정 캐시다.

1. 무엇을 확인했나 — 아동 발화 37턴 전수 검증

세션 로그(guest 11,828줄 + monitor 860줄)에서 guest_voice_event_normalized를 턴 단위로 재구성했다. 발화 37건 → 커밋 32 / drop 5.

정상 턴의 커밋→응답 지연은 예외 없이 0.37~1.08초다. 이 범위를 벗어난 턴만 이상으로 본다.

2. 응답 없는 5턴 — 메커니즘 3종

3. user_turn_dropped 이벤트 이름만 보면 오진한다

drop 5건 중 2건은 응답이 정상으로 나왔다. 이벤트 이름이 아니라 pending→종료 소요시간이 가르는 축이다.

4. 근본 원인 — 캐시 키가 전사 텍스트인데 전사가 항상 비어 있다

아래 사슬은 9절에서 실제 DeferredInputGate로 재현해 prod 로그값과 일치를 확인했다. resolve_completion()은 판정 결과를 정규화된 전사 문자열을 키로 캐시한다. 그런데 훅이 볼 때 전사는 항상 비어 있다 — 세션 전체 트레이스가 예외 없이 transcript_length: 0이고, user_stt_segment는 커밋보다 0.7초 늦게 도착한다. 따라서 모든 턴이 키 "" 하나를 공유한다.

# apps/livekit-agent/input_gate.py
176 def resolve_completion(self, transcript: str) -> bool | None:
177     normalized = self._normalize_transcript(transcript)          # == "" (빈 전사)
178     turn_ids = self._transcript_turn_ids.get(normalized) if normalized else None
                                                                    # ↑ normalized 비어서 정확 매칭 스킵
183     else:
184         recent_outcome = self._recent_completion_outcomes.pop(normalized, None)
                                                                    # ↑ pop("") → (turn-3, False) 히트
185         if recent_outcome is not None:
186             turn_id, outcome = recent_outcome
187             self.last_resolved_turn_id = turn_id                 # ← turn-3 으로 고착
188             return outcome                                      # turn-4 는 resolve조차 안 됨
             ...
212                     if not normalized:
213                         return None                              # 빈 전사 가드가 여기에만 있다
             ...
227             self._recent_completion_outcomes[normalized] = (turn_id, outcome)
                                                                    # ↑ 키 "" 에 (turn-3, False) 저장 = 오염

# apps/livekit-agent/agent.py
1583     if resolved_turn_id and self._input_gate.has_newer_turn_after(resolved_turn_id):
1584         return "superseded_by_new_speech"          # turn-4 가 turn-3 보다 최신 → True
      ...
1632     raise StopResponse()                            # 응답 생성 취소 = 미발화

5. 시간순 인과 사슬

10:50:06.367  turn-3 (거부 턴, _turn_acceptance=False) 이 input_gate.py:197 경로로 resolve
              → complete_user_turn(turn-3) → outcome=False
              → :227  _recent_completion_outcomes[""] = (turn-3, False)   ★ 오염
              → 이 시점엔 has_newer_turn_after(turn-3)=False → 응답 정상 발화 (+0.54s)

10:50:22.366  아동 turn-4 발화 시작 (4.55초)   last_observed_turn_id = turn-4
10:50:26.918  user_turn_pending_started turn-4
10:50:28.817  user_turn_committed turn-4 + 훅 진입 (transcript="")
10:50:28.815  :178  정확 매칭 스킵  →  :184  pop("") → (turn-3, False) 히트
              :187  last_resolved_turn_id = turn-3      ← turn-4 는 판정되지 않음
              :188  return False
              agent.py:1583  has_newer_turn_after("turn-3") → True
              agent.py:1584  block_reason = "superseded_by_new_speech"
              agent.py:1632  raise StopResponse()        → 미발화
10:50:29.527  user_stt_segment turn-4 (전사는 정상 생성 — 겉보기 정상의 원인)
              ✗ agent_response_started 없음 — 8.5초간 agent 이벤트 0건
10:50:38.016  아동 재발화 turn-5
10:50:45.537  agent_response_started  (pop("") 이 비어 정상 경로 → 응답 정상)

turn-5·turn-6 트레이스도 resolved=turn-3으로 남아 있다 — resolver가 끝까지 전진하지 못했음을 보여주지만, 판정이 none이라 응답은 통과했다.

6. 발동 빈도 — 수업 전체 훅 33회 중 1회

phase="resolved" 판정이 none이 아닌 건 전체에서 딱 2회이고, 둘 다 user_turn_dropped가 발생한 세션이다. 그리고 그 직후 턴이 두 번 다 응답을 잃었다.

나머지 세션(18795a78·e49b60e7 등)에는 해당 턴의 훅 트레이스가 존재하지 않는다 — 메커니즘 A는 훅에 도달조차 못 한다는 뜻이고, 이것이 A와 C를 가르는 로그 지표다.

7. 판별법 — 다음 신고 때 이 순서로

1. 세션 로그(guest)에서 턴 원장을 만든다. guest_voice_event_normalized의 turnId별로 user_speech_started → user_speech_stopped → user_input_window_started → user_input_window_stopped | user_turn_dropped 를 묶고, 종료 시각 뒤 같은 voiceSessionId 안에서 agent_response_started가 있는지 본다. 세션 경계를 넘겨 매칭하면 다음 세션 오프닝 멘트를 응답으로 오인한다.
2. pending→종료 소요시간이 1.90초면 정상 만료, 그보다 짧으면 재발화 조기 drop(메커니즘 A).
3. 커밋됐는데 무응답이면 agent 로그의 on_user_turn_completed_trace phase="resolved"를 본다. turn_id(=last_resolved_turn_id)가 last_observed_turn_id와 다르면 캐시 오염(메커니즘 C) 확정이다.
4. publish_decision이 dropped_*_sdk_only면 StopResponse()로 응답이 취소된 것이다.
5. 훅 트레이스 자체가 없으면 훅 미실행(메커니즘 A 또는 B) — AI 발화 중 커밋인지 allow_interruptions·직전 agent_response_completed 시각으로 가른다.

8. 조회 경로 — prod agent 로그

prod agent 로그는 Loki가 아니라 CloudWatch Logs Insights에 있고, Grafana 데이터소스 프록시로 뚫는다. Loki service_name에는 ppi-livekit-agent가 없다(있는 compose_service="agent"는 livekit-test 호스트다).

POST https://ppim.dubuhealth.in/api/ds/query
{
  "queries": [{
    "datasource": { "type": "cloudwatch", "uid": "P034F075C744B399F" },
    "queryMode": "Logs", "queryLanguage": "CWLI", "region": "default",
    "logGroups": [{ "name": "/ppi/livekit/prod/agent" }],
    "expression": "fields @timestamp, @message
                   | filter @logStream like /^agent\/ppi-livekit-agent\//
                   | filter @message like \"<voice_session_id>\"
                   | sort @timestamp asc | limit 2000"
  }],
  "from": "<epoch_ms>", "to": "<epoch_ms>"
}

LiveKit 서버(service_name="ppi-livekit")는 해당 구간 warn/error 0건, 방 이벤트도 10:49:02~10:51:17 사이 공백이라 전송 경로는 무관함이 배제된다. 같은 구간의 not dispatching agent job since no worker is available는 agentName: ppi-agent-local(개발용) 건으로 무관하다.

9. 재현 확인 — 로컬 테스트로 확정

4·5절의 사슬은 로그에 직접 찍히지 않는다. _recent_completion_outcomes 상태나 "캐시 히트" 자체를 남기는 로그 라인이 없기 때문이다. 실제 DeferredInputGate 클래스로 재현해 prod 로그값과 대조했다.

# 재현 조건 세 가지만 필요하다
1 훅에 전달하는 전사를 "" 로 고정            # transcript_length: 0
2 turn-3 만 발화 시작 시점에 입력 비활성        # _turn_acceptance[turn-3] = False (거부 턴)
3 나머지 턴은 정상 수락

# 결과
turn-1: resolve_completion('') -> None    last_resolved=None
turn-2: resolve_completion('') -> None    last_resolved=None
turn-3: resolve_completion('') -> False   last_resolved=turn-3
        dict 상태: {'': ('turn-3', False)}                    ← 빈 키 저장
turn-4: resolve_completion('') -> False
        last_observed_turn_id = turn-4
        last_resolved_turn_id = turn-3                        ← 고착
        has_newer_turn_after(turn-3) = True
        block_reason = 'superseded_by_new_speech'
        publish_decision = 'dropped_superseded_by_new_speech_sdk_only'   ← 미발화
turn-5: resolve_completion('') -> None    # dict 비어 정상 경로

10. 재현 절차 — 실기기 / 모니터 UI

거부 턴(_turn_acceptance = False) 하나를 만들면 다음 턴이 응답을 잃는다. 만드는 방법이 두 가지다.

실제 사례가 만들어진 조건 — 발화 종료 직후 0.5초 입력 플랩

10:49:55.082  agent_response_completed              desired=False effective=False   # 핑퐁이 발화 끝
10:49:55.613  input_enabled_updated                 desired=True  effective=True    # 입력 재개
10:49:55.922  input_enabled_updated                 desired=False effective=False   ★ 0.31초 뒤 다시 OFF
10:49:56.064  user_state_changed (speaking) turn-3   desired=False effective=False   ← 아동이 이 창에서 발화 시작 = 거부 턴
10:49:56.422  input_enabled_updated                 desired=True  effective=True    # 0.5초 만에 복귀

즉 핑퐁이 말이 끝나자마자 아동이 즉시 겹쳐 말하기 시작하면 조작 없이도 같은 상태가 된다. 이 ON→OFF→ON 플랩은 세션 전체에서 반복적으로 나타나며 desired까지 함께 뒤집히므로 웹 클라이언트의 듣기 의도 재적용 경로다.

모니터 UI로 그 0.5초 창을 사람이 조작 가능한 길이로 늘린다

// apps/web/lib/voice-agent/livekit-client-session.ts:1177-1180
const inputStateApplier = createLiveKitAgentOnlyInputStateApplier({
  // `듣기 OFF` must not mute the SDK LocalAudioTrack: livekit-client
  // implements LocalTrack.mute() by flipping the source MediaStreamTrack.enabled,
  // and that same source feeds the processed host relay output.

조작 위치: 모니터 사이드바 / 세션 카드의 듣기 ON·OFF 토글 (monitor-control-sidebar.tsx · session-controls.tsx → host-toggle-microphone → use-guest-controls.ts:99). 아동 세션이 AI 활동 스텝(full:ai)에 진입해 있어야 한다.

확진 지표

6단계에서 에이전트 로그(/ppi/livekit/prod/agent, 8절 참조)의 on_user_turn_completed_trace phase="resolved"가 아래처럼 나오면 성공이다. turn_id ≠ last_observed_turn_id 가 확진 지표다.

{"turn_id": "…:turn-N",  "last_observed_turn_id": "…:turn-N+1",
 "accepted_turn": false,
 "publish_decision": "dropped_superseded_by_new_speech_sdk_only"}

실패하기 쉬운 지점

11. 수정 방향 (미적용)

관련 문서