feat: migrate realtime voice service to OpenAI provider pipeline

transports/audiosocket.py

@@ -1,8 +1,11 @@
 from __future__ import annotations
 
 import asyncio
+import audioop
 import logging
+import os
 import struct
+import time
 import uuid
 from typing import Awaitable, Callable
 
@@ -17,6 +20,16 @@ AUDIO_SOCKET_PACKET_DTMF = 0x03
 AUDIO_SOCKET_PACKET_PCM16 = 0x10
 
 
+def _float_env(name: str, default: float) -> float:
+    raw = os.getenv(name)
+    if raw is None:
+        return default
+    try:
+        return float(str(raw).strip())
+    except ValueError:
+        return default
+
+
 def normalize_session_id(value: str | bytes) -> str:
     if isinstance(value, bytes):
         try:
@@ -54,7 +67,7 @@ class AudioSocketTransport(BaseMediaTransport):
         transport_id: str,
         reader: asyncio.StreamReader,
         writer: asyncio.StreamWriter,
-        sample_rate_hz: int = 8000,
+        sample_rate_hz: int = 16000,
         frame_duration_ms: int = 20,
         read_timeout_seconds: float = 30.0,
     ) -> None:
@@ -67,6 +80,19 @@ class AudioSocketTransport(BaseMediaTransport):
         self._writer = writer
         self._read_timeout_seconds = max(read_timeout_seconds, 1.0)
         self._closed = False
+        self._rx_audio_packet_count = 0
+        self._rx_audio_bytes = 0
+        self._rx_ignored_packet_count = 0
+        self._rx_rms_sum = 0
+        self._rx_rms_count = 0
+        self._rx_peak_abs = 0
+        self._rx_low_level_packet_count = 0
+        self._rx_silence_rms_threshold = max(int(os.getenv("REALTIME_VOICE_RX_SILENCE_RMS_THRESHOLD", "80")), 0)
+        self._rx_log_interval_seconds = max(
+            _float_env("REALTIME_VOICE_AUDIO_LOG_INTERVAL_SECONDS", 1.0),
+            0.1,
+        )
+        self._last_rx_summary_monotonic = time.perf_counter()
 
     @property
     def protocol(self) -> str:
@@ -79,7 +105,7 @@ class AudioSocketTransport(BaseMediaTransport):
         writer: asyncio.StreamWriter,
         *,
         handshake_timeout_seconds: float = 5.0,
-        sample_rate_hz: int = 8000,
+        sample_rate_hz: int = 16000,
         frame_duration_ms: int = 20,
     ) -> AudioSocketTransport:
         packet_type, payload = await read_packet(reader, timeout_seconds=handshake_timeout_seconds)
@@ -103,31 +129,141 @@ class AudioSocketTransport(BaseMediaTransport):
                     self._reader,
                     timeout_seconds=self._read_timeout_seconds,
                 )
-            except (asyncio.IncompleteReadError, asyncio.TimeoutError, ConnectionError):
+            except asyncio.TimeoutError:
+                LOGGER.info(
+                    "AudioSocket receive timeout: session=%s timeout_seconds=%s rx_packets=%s rx_bytes=%s",
+                    self.transport_id,
+                    self._read_timeout_seconds,
+                    self._rx_audio_packet_count,
+                    self._rx_audio_bytes,
+                )
+                return None
+            except asyncio.IncompleteReadError as exc:
+                LOGGER.info(
+                    "AudioSocket peer closed stream: session=%s partial_bytes=%s expected_bytes=%s "
+                    "rx_packets=%s rx_bytes=%s",
+                    self.transport_id,
+                    len(exc.partial or b""),
+                    exc.expected,
+                    self._rx_audio_packet_count,
+                    self._rx_audio_bytes,
+                )
+                return None
+            except ConnectionError:
+                LOGGER.info(
+                    "AudioSocket connection error on receive: session=%s rx_packets=%s rx_bytes=%s",
+                    self.transport_id,
+                    self._rx_audio_packet_count,
+                    self._rx_audio_bytes,
+                )
                 return None
 
             if packet_type == AUDIO_SOCKET_PACKET_HANGUP:
+                LOGGER.info(
+                    "AudioSocket hangup packet: session=%s rx_packets=%s rx_bytes=%s",
+                    self.transport_id,
+                    self._rx_audio_packet_count,
+                    self._rx_audio_bytes,
+                )
                 return None
             if packet_type == AUDIO_SOCKET_PACKET_PCM16:
+                self._rx_audio_packet_count += 1
+                self._rx_audio_bytes += len(payload)
+                self._track_rx_audio_level(payload)
+                self._maybe_log_rx_summary()
                 return payload
-            if packet_type in {AUDIO_SOCKET_PACKET_UUID, AUDIO_SOCKET_PACKET_DTMF}:
+            if packet_type == AUDIO_SOCKET_PACKET_DTMF:
+                self._rx_ignored_packet_count += 1
+                LOGGER.info(
+                    "AudioSocket DTMF packet ignored: session=%s payload=%r",
+                    self.transport_id,
+                    payload[:16],
+                )
                 continue
+            if packet_type == AUDIO_SOCKET_PACKET_UUID:
+                self._rx_ignored_packet_count += 1
+                LOGGER.info("AudioSocket duplicate UUID packet ignored: session=%s", self.transport_id)
+                continue
+            self._rx_ignored_packet_count += 1
+            LOGGER.warning(
+                "AudioSocket unknown packet ignored: session=%s packet_type=%s payload_bytes=%s",
+                self.transport_id,
+                packet_type,
+                len(payload),
+            )
         return None
 
-    async def send_audio(self, audio_chunk: bytes) -> None:
+    async def _send_frame(self, frame: bytes) -> None:
         if self._closed or self._writer.is_closing():
             return
-        self._writer.write(encode_audio_packet(audio_chunk))
+        self._writer.write(encode_audio_packet(frame))
         await self._writer.drain()
 
     async def close(self) -> None:
         if self._closed:
             return
         self._closed = True
+        LOGGER.info(
+            "AudioSocket transport closing: session=%s rx_packets=%s rx_bytes=%s ignored_packets=%s "
+            "avg_rms=%s peak_abs=%s low_level_packets=%s",
+            self.transport_id,
+            self._rx_audio_packet_count,
+            self._rx_audio_bytes,
+            self._rx_ignored_packet_count,
+            self._average_rx_rms(),
+            self._rx_peak_abs,
+            self._rx_low_level_packet_count,
+        )
         if not self._writer.is_closing():
             self._writer.close()
             await self._writer.wait_closed()
 
+    def _maybe_log_rx_summary(self, *, force: bool = False) -> None:
+        now = time.perf_counter()
+        if not force and (now - self._last_rx_summary_monotonic) < self._rx_log_interval_seconds:
+            return
+        self._last_rx_summary_monotonic = now
+        LOGGER.info(
+            "AudioSocket audio_rx_summary: session=%s sample_rate=%s frame_ms=%s frame_bytes=%s "
+            "rx_packets=%s rx_bytes=%s ignored_packets=%s avg_rms=%s peak_abs=%s "
+            "low_level_packets=%s low_level_ratio=%.3f",
+            self.transport_id,
+            self.sample_rate_hz,
+            self.frame_duration_ms,
+            self.frame_bytes,
+            self._rx_audio_packet_count,
+            self._rx_audio_bytes,
+            self._rx_ignored_packet_count,
+            self._average_rx_rms(),
+            self._rx_peak_abs,
+            self._rx_low_level_packet_count,
+            self._rx_low_level_ratio(),
+        )
+
+    def _track_rx_audio_level(self, payload: bytes) -> None:
+        if not payload:
+            return
+        try:
+            rms = int(audioop.rms(payload, 2))
+            peak = int(audioop.max(payload, 2))
+        except Exception:
+            return
+        self._rx_rms_sum += rms
+        self._rx_rms_count += 1
+        self._rx_peak_abs = max(self._rx_peak_abs, peak)
+        if rms <= self._rx_silence_rms_threshold:
+            self._rx_low_level_packet_count += 1
+
+    def _average_rx_rms(self) -> int:
+        if self._rx_rms_count <= 0:
+            return 0
+        return int(self._rx_rms_sum / self._rx_rms_count)
+
+    def _rx_low_level_ratio(self) -> float:
+        if self._rx_rms_count <= 0:
+            return 0.0
+        return self._rx_low_level_packet_count / float(self._rx_rms_count)
+
 
 class AudioSocketServer:
     def __init__(
@@ -137,7 +273,7 @@ class AudioSocketServer:
         port: int,
         session_handler: Callable[[AudioSocketTransport], Awaitable[None]],
         handshake_timeout_seconds: float = 5.0,
-        sample_rate_hz: int = 8000,
+        sample_rate_hz: int = 16000,
         frame_duration_ms: int = 20,
     ) -> None:
         self._host = host
@@ -164,9 +300,12 @@ class AudioSocketServer:
             self._port,
         )
         LOGGER.info(
-            "AudioSocket server listening on %s:%s",
+            "AudioSocket server listening on %s:%s sample_rate=%s frame_ms=%s frame_bytes=%s",
             self._host,
             self.bound_port,
+            self._sample_rate_hz,
+            self._frame_duration_ms,
+            int((self._sample_rate_hz * self._frame_duration_ms / 1000.0) * 2),
         )
 
     async def stop(self) -> None:
@@ -205,9 +344,12 @@ class AudioSocketServer:
                 frame_duration_ms=self._frame_duration_ms,
             )
             LOGGER.info(
-                "AudioSocket client accepted: session=%s peer=%s",
+                "AudioSocket client accepted: session=%s peer=%s sample_rate=%s frame_ms=%s frame_bytes=%s",
                 transport.transport_id,
                 peer,
+                transport.sample_rate_hz,
+                transport.frame_duration_ms,
+                transport.frame_bytes,
             )
             await self._session_handler(transport)
         except asyncio.CancelledError:
@@ -216,9 +358,11 @@ class AudioSocketServer:
             LOGGER.exception("AudioSocket connection failed from peer=%s", peer)
         finally:
             if transport is not None:
+                transport._maybe_log_rx_summary(force=True)
                 await transport.close()
             elif not writer.is_closing():
                 writer.close()
                 await writer.wait_closed()
+            LOGGER.info("AudioSocket connection finished: peer=%s session=%s", peer, transport.transport_id if transport else None)
             if current_task is not None:
                 self._connection_tasks.discard(current_task)

transports/base.py

@@ -1,19 +1,53 @@
 from __future__ import annotations
 
+import asyncio
+import logging
+import os
+import time
 from abc import ABC, abstractmethod
 
+from realtime_voice_service.core.audio_pacer import AudioPacer
+
+
+LOGGER = logging.getLogger("uvicorn.error")
+
+
+def _float_env(name: str, default: float) -> float:
+    raw = os.getenv(name)
+    if raw is None:
+        return default
+    try:
+        return float(str(raw).strip())
+    except ValueError:
+        return default
+
 
 class BaseMediaTransport(ABC):
     def __init__(
         self,
         *,
         transport_id: str,
-        sample_rate_hz: int = 8000,
+        sample_rate_hz: int = 16000,
         frame_duration_ms: int = 20,
     ) -> None:
         self._transport_id = transport_id
         self._sample_rate_hz = sample_rate_hz
         self._frame_duration_ms = frame_duration_ms
+        self._audio_pacer = AudioPacer(frame_bytes=self.frame_bytes)
+        self._send_lock = asyncio.Lock()
+        self._next_frame_monotonic: float | None = None
+        self._send_generation = 0
+        self._audio_log_interval_seconds = max(
+            _float_env("REALTIME_VOICE_AUDIO_LOG_INTERVAL_SECONDS", 1.0),
+            0.1,
+        )
+        self._last_tx_summary_monotonic = time.perf_counter()
+        self._tx_chunk_count = 0
+        self._tx_input_bytes = 0
+        self._tx_frame_count = 0
+        self._tx_frame_bytes = 0
+        self._tx_flush_count = 0
+        self._tx_clear_count = 0
 
     @property
     def transport_id(self) -> str:
@@ -40,10 +74,131 @@ class BaseMediaTransport(ABC):
     async def receive_audio(self) -> bytes | None:
         raise NotImplementedError
 
-    @abstractmethod
     async def send_audio(self, audio_chunk: bytes) -> None:
-        raise NotImplementedError
+        if not audio_chunk:
+            return
+        async with self._send_lock:
+            generation = self._send_generation
+            frames = self._audio_pacer.push(audio_chunk)
+            self._tx_chunk_count += 1
+            self._tx_input_bytes += len(audio_chunk)
+            self._tx_frame_count += len(frames)
+            self._tx_frame_bytes += sum(len(frame) for frame in frames)
+            self._maybe_log_tx_summary(generation=generation)
+            for frame in frames:
+                if generation != self._send_generation:
+                    return
+                await self._pace_and_send_frame(frame, generation=generation)
+
+    async def flush_audio(self, *, pad_final_frame: bool = True) -> None:
+        async with self._send_lock:
+            generation = self._send_generation
+            buffered_before = self._audio_pacer.buffered_bytes
+            frames = self._audio_pacer.flush(pad_final_frame=pad_final_frame)
+            self._tx_flush_count += 1
+            self._tx_frame_count += len(frames)
+            self._tx_frame_bytes += sum(len(frame) for frame in frames)
+            LOGGER.info(
+                "transport %s flush_audio protocol=%s generation=%s frames=%s frame_bytes=%s "
+                "buffered_before=%s pad_final_frame=%s",
+                self.transport_id,
+                self.protocol,
+                generation,
+                len(frames),
+                sum(len(frame) for frame in frames),
+                buffered_before,
+                pad_final_frame,
+            )
+            self._maybe_log_tx_summary(generation=generation, force=True)
+            for frame in frames:
+                if generation != self._send_generation:
+                    return
+                await self._pace_and_send_frame(frame, generation=generation)
+
+    def clear_buffer(self) -> None:
+        previous_generation = self._send_generation
+        buffered_before = self._audio_pacer.buffered_bytes
+        self._send_generation += 1
+        self._tx_clear_count += 1
+        self._audio_pacer.clear()
+        self._next_frame_monotonic = None
+        LOGGER.info(
+            "transport %s clear_buffer protocol=%s generation=%s->%s buffered_bytes=%s "
+            "tx_chunks=%s tx_frames=%s tx_bytes=%s clears=%s",
+            self.transport_id,
+            self.protocol,
+            previous_generation,
+            self._send_generation,
+            buffered_before,
+            self._tx_chunk_count,
+            self._tx_frame_count,
+            self._tx_frame_bytes,
+            self._tx_clear_count,
+        )
+
+    def discard_audio_buffer(self) -> None:
+        self.clear_buffer()
 
     @abstractmethod
     async def close(self) -> None:
         raise NotImplementedError
+
+    @abstractmethod
+    async def _send_frame(self, frame: bytes) -> None:
+        raise NotImplementedError
+
+    async def _pace_and_send_frame(self, frame: bytes, *, generation: int) -> None:
+        if generation != self._send_generation:
+            return
+        frame_duration_seconds = self.frame_duration_ms / 1000.0
+        now = time.perf_counter()
+        if (
+            self._next_frame_monotonic is None
+            or now > (self._next_frame_monotonic + (frame_duration_seconds * 4.0))
+        ):
+            self._next_frame_monotonic = now
+        sleep_for = self._next_frame_monotonic - now
+        if sleep_for > 0:
+            await asyncio.sleep(sleep_for)
+        if generation != self._send_generation:
+            return
+        send_started_monotonic = time.perf_counter()
+        await self._send_frame(frame)
+        send_duration_ms = int((time.perf_counter() - send_started_monotonic) * 1000.0)
+        if send_duration_ms > (self.frame_duration_ms * 2):
+            LOGGER.warning(
+                "transport %s slow_frame_send protocol=%s generation=%s duration_ms=%s frame_bytes=%s",
+                self.transport_id,
+                self.protocol,
+                generation,
+                send_duration_ms,
+                len(frame),
+            )
+        if generation != self._send_generation:
+            return
+        baseline = max(time.perf_counter(), self._next_frame_monotonic)
+        self._next_frame_monotonic = baseline + frame_duration_seconds
+
+    def _maybe_log_tx_summary(self, *, generation: int, force: bool = False) -> None:
+        now = time.perf_counter()
+        if not force and (now - self._last_tx_summary_monotonic) < self._audio_log_interval_seconds:
+            return
+        self._last_tx_summary_monotonic = now
+        LOGGER.info(
+            "transport %s audio_tx_summary protocol=%s generation=%s sample_rate=%s frame_ms=%s "
+            "frame_bytes=%s chunks=%s input_bytes=%s frames=%s frame_payload_bytes=%s "
+            "pacer_buffered=%s flushes=%s clears=%s",
+            self.transport_id,
+            self.protocol,
+            generation,
+            self.sample_rate_hz,
+            self.frame_duration_ms,
+            self.frame_bytes,
+            self._tx_chunk_count,
+            self._tx_input_bytes,
+            self._tx_frame_count,
+            self._tx_frame_bytes,
+            self._audio_pacer.buffered_bytes,
+            self._tx_flush_count,
+            self._tx_clear_count,
+        )

transports/websocket.py

@@ -15,7 +15,7 @@ class WebSocketMediaTransport(BaseMediaTransport):
         *,
         websocket: WebSocket,
         transport_id: str,
-        sample_rate_hz: int = 8000,
+        sample_rate_hz: int = 16000,
         frame_duration_ms: int = 20,
     ) -> None:
         super().__init__(
@@ -52,10 +52,10 @@ class WebSocketMediaTransport(BaseMediaTransport):
             return decoded
         return None
 
-    async def send_audio(self, audio_chunk: bytes) -> None:
+    async def _send_frame(self, frame: bytes) -> None:
         if self._closed:
             return
-        await self._websocket.send_bytes(audio_chunk)
+        await self._websocket.send_bytes(frame)
 
     async def close(self) -> None:
         if self._closed: