diff --git a/src/pipecat/services/elevenlabs/tts.py b/src/pipecat/services/elevenlabs/tts.py index ea67963fb..45864758a 100644 --- a/src/pipecat/services/elevenlabs/tts.py +++ b/src/pipecat/services/elevenlabs/tts.py @@ -616,6 +616,9 @@ class ElevenLabsTTSService(AudioContextWordTTSService): ) frame = TTSAudioRawFrame(audio, self.sample_rate, 1) + logger.debug( + f"[ELEVENLABS_AUDIO] Creating TTSAudioRawFrame with {len(audio)} bytes for context {received_ctx_id}" + ) await self.append_to_audio_context(received_ctx_id, frame) if msg.get("alignment"): @@ -1027,6 +1030,9 @@ class ElevenLabsHttpTTSService(WordTTSService): if data and "audio_base64" in data: await self.stop_ttfb_metrics() audio = base64.b64decode(data["audio_base64"]) + logger.debug( + f"[ELEVENLABS_AUDIO] Yielding TTSAudioRawFrame with {len(audio)} bytes" + ) yield TTSAudioRawFrame(audio, self.sample_rate, 1) # Process alignment if present diff --git a/src/pipecat/services/tts_service.py b/src/pipecat/services/tts_service.py index 9be28f319..a01ad2977 100644 --- a/src/pipecat/services/tts_service.py +++ b/src/pipecat/services/tts_service.py @@ -333,6 +333,9 @@ class TTSService(AIService): elif isinstance(frame, TTSUpdateSettingsFrame): await self._update_settings(frame.settings) elif isinstance(frame, BotStoppedSpeakingFrame): + logger.warning( + f"[TTS_RESUME] {self.__class__.__name__} received BotStoppedSpeakingFrame" + ) await self._maybe_resume_frame_processing() await self.push_frame(frame, direction) else: @@ -376,11 +379,15 @@ class TTSService(AIService): async def _maybe_pause_frame_processing(self): if self._processing_text and self._pause_frame_processing: + logger.warning(f"[TTS_PAUSE] {self.__class__.__name__} pausing frame processing") await self.pause_processing_frames() async def _maybe_resume_frame_processing(self): if self._pause_frame_processing: + logger.warning(f"[TTS_RESUME] {self.__class__.__name__} resuming frame processing") await self.resume_processing_frames() + else: + logger.debug(f"[TTS_RESUME] {self.__class__.__name__} resume called but not paused") async def _process_text_frame(self, frame: TextFrame): text: Optional[str] = None diff --git a/src/pipecat/transports/base_output.py b/src/pipecat/transports/base_output.py index 9c2da1d22..b7d3c1af4 100644 --- a/src/pipecat/transports/base_output.py +++ b/src/pipecat/transports/base_output.py @@ -503,6 +503,9 @@ class BaseOutputTransport(FrameProcessor): num_channels=frame.num_channels, ) chunk.transport_destination = self._destination + logger.debug( + f"[AUDIO_QUEUE] Putting {chunk.__class__.__name__} with {len(chunk.audio)} bytes into audio queue" + ) await self._audio_queue.put(chunk) self._audio_buffer = self._audio_buffer[self._audio_chunk_size :] @@ -582,15 +585,18 @@ class BaseOutputTransport(FrameProcessor): async def _bot_stopped_speaking(self): """Handle bot stopped speaking event.""" if self._bot_speaking: - logger.debug( - f"Bot{f' [{self._destination}]' if self._destination else ''} stopped speaking" + logger.warning( + f"[BOT_STOPPED] Bot stopped speaking - sending BotStoppedSpeakingFrame upstream" ) downstream_frame = BotStoppedSpeakingFrame() downstream_frame.transport_destination = self._destination upstream_frame = BotStoppedSpeakingFrame() upstream_frame.transport_destination = self._destination + + logger.debug(f"[BOT_STOPPED] Pushing downstream BotStoppedSpeakingFrame") await self._transport.push_frame(downstream_frame) + logger.debug(f"[BOT_STOPPED] Pushing upstream BotStoppedSpeakingFrame") await self._transport.push_frame(upstream_frame, FrameDirection.UPSTREAM) self._bot_speaking = False @@ -598,6 +604,8 @@ class BaseOutputTransport(FrameProcessor): # Clean audio buffer (there could be tiny left overs if not multiple # to our output chunk size). self._audio_buffer = bytearray() + else: + logger.debug(f"[BOT_STOPPED] _bot_stopped_speaking called but bot was not speaking") async def _handle_frame(self, frame: Frame): """Handle various frame types with appropriate processing. @@ -624,12 +632,24 @@ class BaseOutputTransport(FrameProcessor): async def without_mixer(vad_stop_secs: float) -> AsyncGenerator[Frame, None]: while True: try: + logger.debug( + f"[AUDIO_QUEUE] Waiting for audio frame (timeout={vad_stop_secs}s)" + ) + start_time = time.time() frame = await asyncio.wait_for( self._audio_queue.get(), timeout=vad_stop_secs ) + wait_time = time.time() - start_time + logger.debug( + f"[AUDIO_QUEUE] Got frame {frame.__class__.__name__} after {wait_time:.3f}s" + ) self._transport.reset_watchdog() yield frame except asyncio.TimeoutError: + wait_time = time.time() - start_time + logger.warning( + f"[AUDIO_QUEUE] TIMEOUT after {wait_time:.3f}s - triggering bot_stopped_speaking" + ) self._transport.reset_watchdog() # Notify the bot stopped speaking upstream if necessary. await self._bot_stopped_speaking()