Merge pull request #2705 from tzookb/tzookb/latency-logging

update UserBotLatencyLogObserver to have logging in functions that can be overidden

src/pipecat/observers/loggers/user_bot_latency_log_observer.py

@@ -61,17 +61,29 @@ class UserBotLatencyLogObserver(BaseObserver):
         elif isinstance(data.frame, UserStoppedSpeakingFrame):
             self._user_stopped_time = time.time()
         elif isinstance(data.frame, (EndFrame, CancelFrame)):
-            if self._latencies:
+            self._log_summary()
+        elif isinstance(data.frame, BotStartedSpeakingFrame) and self._user_stopped_time:
+            latency = time.time() - self._user_stopped_time
+            self._user_stopped_time = 0
+            self._latencies.append(latency)
+            self._log_latency(latency)
+
+    def _log_summary(self):
+        if not self._latencies:
+            return
         avg_latency = mean(self._latencies)
         min_latency = min(self._latencies)
         max_latency = max(self._latencies)
         logger.info(
             f"⏱️ LATENCY FROM USER STOPPED SPEAKING TO BOT STARTED SPEAKING - Avg: {avg_latency:.3f}s, Min: {min_latency:.3f}s, Max: {max_latency:.3f}s"
         )
-        elif isinstance(data.frame, BotStartedSpeakingFrame) and self._user_stopped_time:
+
-            latency = time.time() - self._user_stopped_time
+    def _log_latency(self, latency: float):
-            self._user_stopped_time = 0
+        """Log the latency.
-            self._latencies.append(latency)
+
+        Args:
+            latency: The latency to log.
+        """
         logger.debug(
             f"⏱️ LATENCY FROM USER STOPPED SPEAKING TO BOT STARTED SPEAKING: {latency:.3f}s"
         )