diff --git a/services/ai_voice_runtime_service/media_runtime.py b/services/ai_voice_runtime_service/media_runtime.py index 01879ce..e99db5d 100644 --- a/services/ai_voice_runtime_service/media_runtime.py +++ b/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", diff --git a/services/ai_voice_runtime_service/providers/asr.py b/services/ai_voice_runtime_service/providers/asr.py index 8b6eebe..4890945 100644 --- a/services/ai_voice_runtime_service/providers/asr.py +++ b/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): diff --git a/tests/test_ai_voice_media_runtime.py b/tests/test_ai_voice_media_runtime.py index 2a9e56e..112d343 100644 --- a/tests/test_ai_voice_media_runtime.py +++ b/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():