Skip to content

Commit eb06fa1

Browse files
authored
fix(backend): report undecodable listen streams instead of dropping them silently (#11732) (#11733)
An audio frame the decoder rejects is dropped so the socket survives, which makes it a fail-open branch: the user records the whole session and gets no transcript, no ring buffer, and no mixed audio. The only trace was one `Listen audio frame decode failed codec=opus type=OpusError` line per frame — a class name that cannot separate a corrupt client stream (libopus: `corrupted stream`) from a decoder the receiver sized wrong (`buffer too small`, the #10701 regression) — and no metric at all, against a fail-open contract that requires one (docs/agents/fallback-telemetry.md). Prod is doing this right now: one dg-canary session on the current image dropped 5,000+ consecutive frames at a flat 100 ms cadence over 10 minutes (#11732), and the logs cannot say which failure it is. Carry the codec's own message, the payload size, and the streak into the warning, and report the session once the streak proves the entire stream is failing rather than one packet: record_fallback(component='silent_mic', outcome='exhausted'), once per session, at 50 consecutive drops (1 s at the 20 ms omi cadence). A successful decode resets the streak, so an isolated corrupt packet never reports. Verified: backend/test.sh over the listen/receiver files (6 files, all green) plus a test that drives the receiver with a real opuslib decoder and asserts the log now carries `corrupted stream`. Failure-Class: FC-typed-failure-collapsed-to-generic
1 parent 61dea91 commit eb06fa1

2 files changed

Lines changed: 207 additions & 8 deletions

File tree

backend/routers/listen/receiver.py

Lines changed: 44 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,7 @@
6767
)
6868
from utils.log_sanitizer import sanitize
6969
from utils.listen_audio import ChannelConfig, mix_n_channel_buffers, resample_pcm
70+
from utils.observability.fallback import record_fallback
7071

7172
logger = logging.getLogger(__name__)
7273

@@ -77,6 +78,10 @@
7778
# Longest frame the Opus format can carry, in milliseconds.
7879
OPUS_MAX_FRAME_MS = 120
7980

81+
# Consecutive undecodable frames that mean the session's whole stream is unusable rather
82+
# than one corrupt packet: 1 s of audio at the 20 ms cadence omi clients encode with.
83+
DECODE_FAILURE_STREAK_ALERT = 50
84+
8085

8186
def opus_decode_capacity(sample_rate: int) -> int:
8287
"""Samples to hand `Decoder.decode` as its output-buffer size.
@@ -117,6 +122,8 @@ def __init__(self, host: Any, channel_configs: List[ChannelConfig], channel_id_t
117122
self.vad_gate: Any = None
118123
self.image_chunks: OrderedDict[str, Dict[str, Any]] = OrderedDict()
119124
self.last_image_chunk_cleanup = 0.0
125+
self.decode_failure_streak = 0
126+
self.decode_stream_reported = False
120127

121128
def _capture(self, method: str, *args: Any) -> None:
122129
"""Keep optional dev capture out of the production audio failure domain."""
@@ -128,6 +135,39 @@ def _capture(self, method: str, *args: Any) -> None:
128135
except Exception as error:
129136
logger.warning('Listen parity capture failed method=%s type=%s', method, type(error).__name__)
130137

138+
def _record_decode_failure(
139+
self, codec: str, error: BaseException, payload_len: int, channel: Optional[int] = None
140+
) -> None:
141+
"""Report an undecodable audio frame with enough detail to act on it.
142+
143+
Dropping the frame keeps the socket alive, so an undecodable stream is a fail-open
144+
branch: the user records a whole session and gets no transcript, no ring buffer, and
145+
no mixed audio, while the only trace is one `type=OpusError` line per frame. That name
146+
cannot tell a corrupt client stream from a decoder the receiver sized wrong (#10701),
147+
so carry the codec's own message and the payload size, and once the streak proves the
148+
entire stream is failing, report it as the silent mic it is.
149+
"""
150+
self.decode_failure_streak += 1
151+
logger.warning(
152+
'Listen audio frame decode failed codec=%s channel=%s type=%s bytes=%s streak=%s detail=%s',
153+
codec,
154+
channel,
155+
type(error).__name__,
156+
payload_len,
157+
self.decode_failure_streak,
158+
sanitize(error)[:120],
159+
)
160+
if self.decode_stream_reported or self.decode_failure_streak < DECODE_FAILURE_STREAK_ALERT:
161+
return
162+
self.decode_stream_reported = True
163+
record_fallback(
164+
component='silent_mic',
165+
from_mode=codec,
166+
to_mode='none',
167+
reason='capability_mismatch',
168+
outcome='exhausted',
169+
)
170+
131171
def _serving_provider(self) -> str:
132172
"""Resolve the provider actually serving this session, read at use time.
133173
@@ -426,12 +466,9 @@ async def _handle_multi_channel_audio(self, data: bytes) -> None:
426466
bytes(audio), opus_decode_capacity(request.sample_rate)
427467
)
428468
except Exception as error:
429-
logger.warning(
430-
'Listen audio frame decode failed codec=opus channel=%s type=%s',
431-
channel_index,
432-
type(error).__name__,
433-
)
469+
self._record_decode_failure('opus', error, len(audio), channel=channel_index)
434470
return
471+
self.decode_failure_streak = 0
435472
if not audio:
436473
return
437474
pcm = resample_pcm(bytes(audio), request.sample_rate, TARGET_SAMPLE_RATE)
@@ -590,10 +627,9 @@ async def receive_data(self) -> None:
590627
elif request.codec == 'pcm8':
591628
decoded = audioop.lin2lin(audioop.bias(data, 1, -128), 1, 2)
592629
except Exception as error:
593-
logger.warning(
594-
'Listen audio frame decode failed codec=%s type=%s', request.codec, type(error).__name__
595-
)
630+
self._record_decode_failure(request.codec, error, len(data))
596631
continue
632+
self.decode_failure_streak = 0
597633
if not decoded:
598634
continue
599635
self._capture('capture_client_audio', decoded)
Lines changed: 163 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,163 @@
1+
"""An undecodable listen stream must report itself, not just drop frames silently.
2+
3+
Dropping a frame keeps the socket alive, so a stream the decoder cannot read is a fail-open
4+
branch: the user records a whole session and gets no transcript, no ring buffer, and no mixed
5+
audio. Prod logged only `Listen audio frame decode failed codec=opus type=OpusError`, one line
6+
per frame — a name that cannot separate a corrupt client stream (`corrupted stream`) from a
7+
decoder the receiver sized wrong (`buffer too small`, the #10701 regression), and no metric to
8+
alert on. The receiver now carries the codec's own message plus the payload size, and reports
9+
the session once the streak proves the whole stream is failing.
10+
"""
11+
12+
import logging
13+
from types import SimpleNamespace
14+
15+
import pytest
16+
17+
from routers.listen import receiver as receiver_module
18+
from routers.listen.receiver import DECODE_FAILURE_STREAK_ALERT, ListenReceiver
19+
20+
21+
@pytest.fixture
22+
def anyio_backend():
23+
return 'asyncio'
24+
25+
26+
class _OpusError(Exception):
27+
"""Stands in for opuslib.OpusError, whose str() is the libopus message."""
28+
29+
30+
class _ScriptedDecoder:
31+
"""Raises for the frames named in `fail_on`, decodes the rest."""
32+
33+
def __init__(self, fail_on):
34+
self.fail_on = set(fail_on)
35+
36+
def decode(self, data: bytes, frame_size: int = 0, **_kwargs) -> bytes:
37+
if data in self.fail_on:
38+
raise _OpusError("b'corrupted stream'")
39+
return b'\x01\x02' * 320
40+
41+
42+
class _FramesWebSocket:
43+
def __init__(self, frames):
44+
self.frames = iter(frames)
45+
46+
async def receive(self):
47+
return next(self.frames)
48+
49+
50+
def _host(websocket):
51+
return SimpleNamespace(
52+
request=SimpleNamespace(websocket=websocket, codec='opus', sample_rate=16000),
53+
state=SimpleNamespace(
54+
active=True,
55+
close_code=1001,
56+
last_audio_received_time=None,
57+
last_activity_time=None,
58+
first_audio_byte_timestamp=None,
59+
last_usage_record_timestamp=None,
60+
audio_ring_buffer=None,
61+
),
62+
limits=SimpleNamespace(ws_receive_timeout=1.0),
63+
is_multi_channel=False,
64+
use_custom_stt=True,
65+
audio_bytes_send=None,
66+
transcripts=SimpleNamespace(enqueue=lambda _segments: None),
67+
start_live_transcription=lambda: None,
68+
)
69+
70+
71+
def _receiver(frames, decoder):
72+
websocket = _FramesWebSocket(list(frames) + [{'type': 'websocket.disconnect', 'code': 1000}])
73+
instance = ListenReceiver(_host(websocket), [], {})
74+
instance.opus_decoder = decoder
75+
return instance
76+
77+
78+
@pytest.fixture
79+
def recorded_fallbacks(monkeypatch):
80+
calls = []
81+
monkeypatch.setattr(receiver_module, 'record_fallback', lambda **kwargs: calls.append(kwargs))
82+
return calls
83+
84+
85+
@pytest.mark.anyio
86+
async def test_decode_failure_log_names_the_codec_message_and_payload_size(caplog, recorded_fallbacks):
87+
frame = b'\xff\xff\xff'
88+
receiver = _receiver([{'bytes': frame}], _ScriptedDecoder({frame}))
89+
90+
with caplog.at_level(logging.WARNING, logger=receiver_module.__name__):
91+
await receiver.receive_data()
92+
93+
(message,) = [record.getMessage() for record in caplog.records if 'decode failed' in record.getMessage()]
94+
assert 'codec=opus' in message
95+
assert 'type=_OpusError' in message
96+
assert f'bytes={len(frame)}' in message
97+
assert 'corrupted stream' in message
98+
assert 'streak=1' in message
99+
100+
101+
@pytest.mark.anyio
102+
async def test_whole_stream_undecodable_reports_a_silent_mic_once(recorded_fallbacks):
103+
frame = b'\xff\xff\xff'
104+
frames = [{'bytes': frame}] * (DECODE_FAILURE_STREAK_ALERT + 3)
105+
receiver = _receiver(frames, _ScriptedDecoder({frame}))
106+
107+
await receiver.receive_data()
108+
109+
assert receiver.decode_failure_streak == DECODE_FAILURE_STREAK_ALERT + 3
110+
assert recorded_fallbacks == [
111+
{
112+
'component': 'silent_mic',
113+
'from_mode': 'opus',
114+
'to_mode': 'none',
115+
'reason': 'capability_mismatch',
116+
'outcome': 'exhausted',
117+
}
118+
]
119+
120+
121+
@pytest.mark.anyio
122+
async def test_a_corrupt_packet_among_good_frames_never_reports(recorded_fallbacks):
123+
bad, good = b'\xff\xff\xff', b'opus-frame'
124+
frames = [{'bytes': bad}, {'bytes': good}] * (DECODE_FAILURE_STREAK_ALERT + 3)
125+
receiver = _receiver(frames, _ScriptedDecoder({bad}))
126+
127+
await receiver.receive_data()
128+
129+
assert receiver.decode_failure_streak == 0
130+
assert recorded_fallbacks == []
131+
132+
133+
@pytest.mark.anyio
134+
async def test_multi_channel_decode_failure_names_its_channel(caplog, recorded_fallbacks):
135+
frame = b'\xff\xff\xff'
136+
receiver = _receiver([], _ScriptedDecoder({frame}))
137+
receiver.host.is_multi_channel = True
138+
receiver.channel_id_to_index = {7: 1}
139+
receiver.multi_opus_decoders = [None, _ScriptedDecoder({frame})]
140+
141+
with caplog.at_level(logging.WARNING, logger=receiver_module.__name__):
142+
await receiver._handle_multi_channel_audio(bytes([7]) + frame)
143+
144+
(message,) = [record.getMessage() for record in caplog.records if 'decode failed' in record.getMessage()]
145+
assert 'channel=1' in message
146+
assert f'bytes={len(frame)}' in message
147+
assert receiver.decode_failure_streak == 1
148+
149+
150+
@pytest.mark.skipif(receiver_module.opuslib is None, reason='opuslib/libopus unavailable')
151+
@pytest.mark.anyio
152+
async def test_real_libopus_rejection_is_reported_with_its_own_message(caplog, recorded_fallbacks):
153+
# libopus decodes most arbitrary bytes; b'\xff\xff\xff' is a packet it actually rejects,
154+
# which is how prod's storm looked from the inside.
155+
frame = b'\xff\xff\xff'
156+
receiver = _receiver([{'bytes': frame}], receiver_module.opuslib.Decoder(16000, 1))
157+
158+
with caplog.at_level(logging.WARNING, logger=receiver_module.__name__):
159+
await receiver.receive_data()
160+
161+
(message,) = [record.getMessage() for record in caplog.records if 'decode failed' in record.getMessage()]
162+
assert 'type=OpusError' in message
163+
assert 'corrupted stream' in message

0 commit comments

Comments
 (0)