feat: enhance low signal transcript handling with finalization checks and logging

services/ai_voice_runtime_service/media_runtime.py

@@ -234,35 +234,52 @@ class AudioSocketMediaRuntime:
             compact = compact.replace(char, " ")
         return " ".join(compact.split())
 
+    _FINAL_LOW_SIGNAL_PHRASES = {
+        "алло",
+        "ой",
+        "слышу",
+        "слышно",
+        "твой",
+        "поргай что это",
+    }
+
     @classmethod
-    def _is_low_signal_transcript(cls, text: str | None) -> bool:
+    def _is_low_signal_partial_transcript(cls, text: str | None) -> bool:
+        """Broad filler check used only for mid-utterance ack/early-plan gating."""
         normalized = cls._normalize_intent_text(text)
         if not normalized:
             return True
-        return normalized in {
+        return normalized in cls._FINAL_LOW_SIGNAL_PHRASES | {
             "ага",
-            "алло",
             "да",
             "добрый день",
             "здравствуйте",
             "ладно",
             "неа",
             "нет",
-            "ой",
             "ок",
             "понял",
             "поняла",
             "привет",
-            "слышу",
-            "слышно",
-            "твой",
             "угу",
             "хорошо",
             "ясно",
             "давай",
-            "поргай что это",
         }
 
+    @classmethod
+    def _is_low_signal_final_transcript(cls, text: str | None) -> bool:
+        """Narrow filler check for a *finalized* caller turn.
+
+        Unlike the partial-transcript check, this must not swallow real answers
+        such as "да"/"нет"/"хорошо" — those are legitimate replies and a caller
+        who says only that deserves a response, not silence.
+        """
+        normalized = cls._normalize_intent_text(text)
+        if not normalized:
+            return True
+        return normalized in cls._FINAL_LOW_SIGNAL_PHRASES
+
     def _detect_early_intent(self, text: str) -> str:
         normalized = self._normalize_intent_text(text)
         if not normalized:
@@ -341,7 +358,7 @@ class AudioSocketMediaRuntime:
 
     def _should_emit_partial_ack(self, actor: MediaActor, partial_transcript: str, partial_intent: str) -> bool:
         transcript_text = str(partial_transcript or "").strip()
-        if not transcript_text or self._is_low_signal_transcript(transcript_text):
+        if not transcript_text or self._is_low_signal_partial_transcript(transcript_text):
             return False
         normalized_intent = str(partial_intent or "").strip() or "unknown"
         if actor.finalized_caller_turn_count > 0:
@@ -689,7 +706,7 @@ class AudioSocketMediaRuntime:
     def _should_schedule_early_plan(self, actor: MediaActor, transcript_text: str, intent: str) -> bool:
         if not self._early_plan_enabled or not self._should_use_voice_v2(actor.registration):
             return False
-        if actor.closed or self._is_low_signal_transcript(transcript_text):
+        if actor.closed or self._is_low_signal_partial_transcript(transcript_text):
             return False
         normalized_intent = str(intent or "").strip().lower() or "unknown"
         if normalized_intent not in self._early_plan_intents:
@@ -814,6 +831,14 @@ class AudioSocketMediaRuntime:
         transcript_text = str(partial.text or "").strip()
         if not transcript_text:
             return
+        if transcript_text != actor.partial_transcript:
+            logger.info(
+                "audiosocket.streaming_asr_partial session_id=%s stable=%s final=%s text=%s",
+                actor.registration.voice_session_id,
+                bool(partial.is_stable),
+                bool(partial.is_final),
+                transcript_text[:160],
+            )
         actor.partial_transcript = transcript_text
         self._update_stable_partial_transcript(actor, transcript_text, provider_stable=bool(partial.is_stable or partial.is_final))
         intent = self._detect_early_intent(transcript_text)
@@ -863,13 +888,21 @@ class AudioSocketMediaRuntime:
         if not actor.asr_streaming_enabled or not actor.asr_stream_id:
             raise StreamingASRUnavailable("Streaming ASR stream is not active")
         stream_id = actor.asr_stream_id
+        start_monotonic = time.monotonic()
         await self._stop_streaming_asr_push_loop(actor, drain=True)
         if actor.asr_streaming_failed:
             raise StreamingASRUnavailable("Streaming ASR push failed before finalize")
         try:
-            return await asyncio.to_thread(self._streaming_asr_provider.finalize, stream_id)
+            transcription = await asyncio.to_thread(self._streaming_asr_provider.finalize, stream_id)
         finally:
             await self._close_streaming_asr(actor)
+        logger.info(
+            "audiosocket.streaming_asr_finalized session_id=%s elapsed_ms=%s text=%s",
+            actor.registration.voice_session_id,
+            int((time.monotonic() - start_monotonic) * 1000),
+            str(transcription.text or "")[:160],
+        )
+        return transcription
 
     async def _record_reply_status(
         self,
@@ -1512,6 +1545,7 @@ class AudioSocketMediaRuntime:
                 )
 
         transcript_source = "batch"
+        asr_start_monotonic = time.monotonic()
         if actor.asr_streaming_enabled and not actor.asr_streaming_failed:
             try:
                 transcription = await self._finalize_streaming_transcription(actor)
@@ -1525,7 +1559,7 @@ class AudioSocketMediaRuntime:
                 self._mark_streaming_asr_backoff(actor)
                 await self._close_streaming_asr(actor, drain=False)
                 partial_first_text = str(actor.stable_partial_transcript or actor.partial_transcript or "").strip()
-                if self._partial_first_final_enabled and partial_first_text and not self._is_low_signal_transcript(partial_first_text):
+                if self._partial_first_final_enabled and partial_first_text and not self._is_low_signal_final_transcript(partial_first_text):
                     transcription = ASRTranscription(
                         text=partial_first_text,
                         language=actor.registration.language,
@@ -1550,17 +1584,21 @@ class AudioSocketMediaRuntime:
             transcript_source = "batch"
         transcript_text = str(transcription.text or "").strip() or partial_transcript
         logger.info(
-            "audiosocket.asr_turn_ready session_id=%s provider=%s utterance_ms=%s text_len=%s empty=%s",
+            "audiosocket.asr_turn_ready session_id=%s provider=%s source=%s utterance_ms=%s elapsed_ms=%s "
+            "text_len=%s empty=%s text=%s",
             actor.registration.voice_session_id,
             getattr(self._asr_provider, "name", "unknown"),
+            transcript_source,
             int(len(pcm_bytes) / 16),
+            int((time.monotonic() - asr_start_monotonic) * 1000),
             len(str(transcript_text or "").strip()),
             not bool(str(transcript_text or "").strip()),
+            transcript_text[:160],
         )
         if not transcript_text:
             await self._set_actor_state(actor, "listening")
             return
-        if self._is_low_signal_transcript(transcript_text):
+        if self._is_low_signal_final_transcript(transcript_text):
             actor.finalized_utterance_generation = max(actor.finalized_utterance_generation, utterance_generation)
             logger.info(
                 "audiosocket.low_signal_ignored session_id=%s transcript=%s",

services/ai_voice_runtime_service/providers/asr.py

@@ -3,6 +3,7 @@ from __future__ import annotations
 import base64
 import io
 import json
+import logging
 import os
 import queue
 import threading
@@ -19,6 +20,8 @@ from services.ai_voice_runtime_service.audiosocket import pcm16le_to_wav_bytes,
 from services.shared.audioop_compat import audioop
 from services.shared.security import issue_app_token
 
+logger = logging.getLogger("uvicorn.error")
+
 
 def _api_base() -> str:
     return (os.getenv("AI_API_BASE", "https://api.openai.com/v1").strip() or "https://api.openai.com/v1").rstrip("/")
@@ -721,6 +724,11 @@ class ElevenLabsRealtimeStreamingASRProvider(StreamingASRProvider):
                 if message_type == "partial_transcript":
                     text = self._payload_text(payload)
                     if text:
+                        logger.info(
+                            "asr.elevenlabs_realtime.partial stream_id=%s text=%s",
+                            state.stream_id,
+                            text[:160],
+                        )
                         state.updates_queue.put(
                             StreamingASRPartial(
                                 text=text,
@@ -735,6 +743,12 @@ class ElevenLabsRealtimeStreamingASRProvider(StreamingASRProvider):
                     text = self._payload_text(payload)
                     language = self._payload_language(payload, state.language)
                     if text:
+                        logger.info(
+                            "asr.elevenlabs_realtime.committed stream_id=%s language=%s text=%s",
+                            state.stream_id,
+                            language,
+                            text[:160],
+                        )
                         state.updates_queue.put(
                             StreamingASRPartial(
                                 text=text,
@@ -755,6 +769,12 @@ class ElevenLabsRealtimeStreamingASRProvider(StreamingASRProvider):
                 if not state.close_requested:
                     state.error = exc
                 state.final_event.set()
+            if not state.close_requested:
+                logger.warning(
+                    "asr.elevenlabs_realtime.reader_error stream_id=%s error=%s",
+                    state.stream_id,
+                    str(exc)[:500],
+                )
 
     def _state(self, stream_id: str) -> _ElevenLabsRealtimeStreamState:
         with self._lock:
@@ -784,6 +804,17 @@ class ElevenLabsRealtimeStreamingASRProvider(StreamingASRProvider):
         with self._lock:
             self._streams[stream_id] = state
         thread.start()
+        logger.info(
+            "asr.elevenlabs_realtime.stream_open stream_id=%s session_id=%s language=%s model=%s "
+            "audio_format=%s sample_rate=%s commit_strategy=%s",
+            stream_id,
+            state.session_id,
+            language,
+            self._model_id,
+            self._audio_format,
+            self._sample_rate_hz,
+            self._commit_strategy,
+        )
         return stream_id
 
     def push_pcm(self, stream_id: str, pcm_8k_chunk: bytes) -> None:
@@ -817,6 +848,18 @@ class ElevenLabsRealtimeStreamingASRProvider(StreamingASRProvider):
 
     def finalize(self, stream_id: str) -> ASRTranscription:
         state = self._state(stream_id)
+        start_monotonic = time.monotonic()
+
+        def _log_and_return(transcription: ASRTranscription, note: str) -> ASRTranscription:
+            logger.info(
+                "asr.elevenlabs_realtime.finalize stream_id=%s note=%s elapsed_ms=%s text=%s",
+                stream_id,
+                note,
+                int((time.monotonic() - start_monotonic) * 1000),
+                transcription.text[:160],
+            )
+            return transcription
+
         silence = b"\x00\x00" * int(self._sample_rate_hz * 0.1)
         try:
             self._send_json(
@@ -831,25 +874,28 @@ class ElevenLabsRealtimeStreamingASRProvider(StreamingASRProvider):
         except StreamingASRUnavailable:
             partial_transcription = self._best_partial_transcription(state)
             if partial_transcription is not None and partial_transcription.text.strip():
-                return partial_transcription
+                return _log_and_return(partial_transcription, "partial_after_send_failure")
             raise
         deadline = time.monotonic() + self._finalize_timeout_seconds
         while True:
             self._drain_updates(state)
             with state.lock:
                 if state.final_transcription is not None:
-                    return state.final_transcription
+                    return _log_and_return(state.final_transcription, "final")
                 latest_partial = state.stable_partial or state.latest_partial
                 error = state.error
                 event_is_set = state.final_event.is_set()
             if event_is_set or time.monotonic() >= deadline:
                 if latest_partial is not None:
-                    return self._transcription_from_partial(latest_partial, fallback_language=state.language)
+                    return _log_and_return(
+                        self._transcription_from_partial(latest_partial, fallback_language=state.language),
+                        "partial_on_event_or_deadline",
+                    )
                 if error is not None:
                     raise StreamingASRUnavailable(str(error)[:500])
                 if time.monotonic() >= deadline:
                     raise StreamingASRUnavailable("ElevenLabs realtime ASR finalize timed out")
-                return ASRTranscription(text="", language=state.language, confidence=None)
+                return _log_and_return(ASRTranscription(text="", language=state.language, confidence=None), "empty")
             state.final_event.wait(timeout=0.05)
 
     def close_stream(self, stream_id: str) -> None:
@@ -871,6 +917,7 @@ class ElevenLabsRealtimeStreamingASRProvider(StreamingASRProvider):
             thread.join(timeout=0.5)
         with self._lock:
             self._streams.pop(stream_id, None)
+        logger.info("asr.elevenlabs_realtime.stream_close stream_id=%s", stream_id)
 
 
 class YandexSpeechKitASRProvider(ASRProvider):

tests/test_ai_voice_media_runtime.py

@@ -1248,9 +1248,17 @@ def test_media_runtime_voice_v2_emits_blind_ack_on_first_turn_without_partial_si
 
 
 def test_media_runtime_low_signal_filter_catches_short_asr_noise():
-    assert AudioSocketMediaRuntime._is_low_signal_transcript("Давай")
-    assert AudioSocketMediaRuntime._is_low_signal_transcript("твой")
-    assert AudioSocketMediaRuntime._is_low_signal_transcript("Поргай, что это")
+    assert AudioSocketMediaRuntime._is_low_signal_partial_transcript("Давай")
+    assert AudioSocketMediaRuntime._is_low_signal_partial_transcript("твой")
+    assert AudioSocketMediaRuntime._is_low_signal_partial_transcript("Поргай, что это")
+    assert AudioSocketMediaRuntime._is_low_signal_final_transcript("твой")
+    assert AudioSocketMediaRuntime._is_low_signal_final_transcript("Поргай, что это")
+
+
+def test_media_runtime_final_low_signal_filter_keeps_real_answers():
+    # A finalized "да"/"нет"/etc. is a real answer, not noise — must not be silently dropped.
+    for real_answer in ("Да", "Нет", "Хорошо", "Ладно", "Давай", "Привет"):
+        assert not AudioSocketMediaRuntime._is_low_signal_final_transcript(real_answer)
 
 
 def test_media_runtime_ignores_low_signal_utterance_without_ack_or_turn():