From ceb2836371566547d5930e7598960ffbd4368775 Mon Sep 17 00:00:00 2001 From: Logan Cusano Date: Tue, 4 Aug 2026 22:34:17 -0400 Subject: [PATCH] Raise tail pad to 3s so short transmissions are not clipped The recording window is anchored to OP25 control-channel timestamps, but the buffered audio lags those by roughly 1.5s. Trim logs across seven calls measured the offset at 0.84-1.62s, consistently present. At a 1.0s pad a short call closed its window before the voice arrived: a 0.97s control-channel call closed at T+1.97 while voice started around T+1.5, capturing ~0.4s of speech and cutting mid-word. Confirmed by a 0.57s file whose final 0.10s measured -12.2dB against its own -18.2dB average - clipped speech, not a tail - and by two short calls that logged no trim at all because no trailing silence remained. Being generous is free here: trim_silence already strips trailing silence back to the guard margin before upload, so long calls are unaffected while short ones gain the window they need. Over-capture costs nothing; under-capture loses words permanently. Co-Authored-By: Claude Opus 5 --- .env.example | 10 +++- drb-edge-node/app/config.py | 27 +++++++-- .../app/internal/metadata_watcher.py | 9 ++- drb-edge-node/tests/test_metadata_watcher.py | 58 ++++++++++++++++--- 4 files changed, 87 insertions(+), 17 deletions(-) diff --git a/.env.example b/.env.example index 0ff5bca..4e57722 100644 --- a/.env.example +++ b/.env.example @@ -38,9 +38,13 @@ CALL_IDLE_TIMEOUT=3 # Seconds of audio kept after the last transmission ends. This is the only # headroom protecting the final word of a transmission — usually the disposition -# or the address. Measured at 0.5s it left ~0.3s of real margin and one recording -# ended mid-word, hence 1.0. -CALL_TAIL_PAD_SECONDS=1.0 +# or the address. Raised 1.0 -> 3.0 after field measurement showed the +# grant-to-speech offset is ~0.84-1.62s (typically ~1.5s): at 1.0s pad, short +# calls had their recording window close before the voice even started, +# clipping speech mid-word. Safe to be generous — trim_silence already strips +# the extra back off long calls before upload, so only short transmissions +# actually benefit from the larger window. +CALL_TAIL_PAD_SECONDS=3.0 # Strip leading/trailing dead air before upload. ~63% of an untrimmed recording # is silence, which costs Whisper spend and makes it hallucinate text that was diff --git a/drb-edge-node/app/config.py b/drb-edge-node/app/config.py index a550dfc..57b923a 100644 --- a/drb-edge-node/app/config.py +++ b/drb-edge-node/app/config.py @@ -47,10 +47,29 @@ class Settings(BaseSettings): # Audio kept after the observed end of the last transmission. The srcaddr # 1→0 edge can be up to one poll (0.5 s) late and the encoder adds its own # latency, so this is the only headroom protecting the last word of a - # transmission — which is usually the disposition or the address. Field - # measurement at 0.5 s left only 0.29–0.37 s of real trailing margin and one - # recording ended mid-word, hence 1.0 s. - call_tail_pad_seconds: float = 1.0 + # transmission — which is usually the disposition or the address. + # + # Raised 1.0 -> 3.0 after field measurement showed the recording WINDOW + # (anchored to OP25 control-channel timestamps) closing well before the + # actual voice audio arrives: grant->speech offset measured 0.84-1.62s + # across 7 calls (~1.5s typical). At the old 1.0s pad, a short + # transmission (e.g. a 0.97s control-channel call) had its window close + # at T+1.97 while voice didn't start until ~T+1.5 — leaving ~0.4s of + # captured speech, clipped mid-word. Confirmed by a 0.57s output file + # whose final 0.10s measured -12.2dB, louder than its own -18.2dB + # average (i.e. clipped speech, not trailing silence), and by two short + # calls that produced no "Trimmed" log line at all because there was no + # trailing silence left to trim. + # + # Safe to be generous here: trim_silence already strips trailing silence + # back to trim_silence_guard_seconds before upload, so a larger pad costs + # long calls nothing (the extra is trimmed away) while giving short + # transmissions enough window to actually capture the voice. Over-capture + # is free; under-capture loses words permanently. Do not tune this back + # down without new field data showing the grant->speech offset has + # shrunk — see DEFERRED.md for the call_idle_timeout coupling this value + # now sits at. + call_tail_pad_seconds: float = 3.0 # Strip leading/trailing dead air before upload. ~63% of a typical recording # is silence (the grant→speech delay plus the tail pad), which inflates diff --git a/drb-edge-node/app/internal/metadata_watcher.py b/drb-edge-node/app/internal/metadata_watcher.py index 4108588..c04a86e 100644 --- a/drb-edge-node/app/internal/metadata_watcher.py +++ b/drb-edge-node/app/internal/metadata_watcher.py @@ -58,8 +58,13 @@ def _tail_pad() -> float: edge (up to one poll late) plus encoder latency never clips the tail. Read live from settings (env CALL_TAIL_PAD_SECONDS) rather than frozen into a - module constant, so it is tunable per node. See the setting for why the - default moved 0.5 → 1.0. + module constant, so it is tunable per node. See the setting in config.py for + why the default moved 1.0 → 3.0 (short calls' recording window was closing + before the ~1.5s grant→speech offset let voice audio even start). + + Only the idle-timeout close path below uses this pad — the tgid_change and + tgid_change_unlogged paths close at an exact, already-known boundary (the + new grant's timestamp, or the same poll tick) and intentionally add none. """ return settings.call_tail_pad_seconds diff --git a/drb-edge-node/tests/test_metadata_watcher.py b/drb-edge-node/tests/test_metadata_watcher.py index 3e6f00a..4b1ce13 100644 --- a/drb-edge-node/tests/test_metadata_watcher.py +++ b/drb-edge-node/tests/test_metadata_watcher.py @@ -233,15 +233,17 @@ async def test_srcaddr_edge_then_idle_timeout_ends_call(watcher, clock): @pytest.mark.asyncio -async def test_tail_pad_is_configurable_and_defaults_to_one_second(watcher, clock, monkeypatch): +async def test_tail_pad_is_configurable_and_defaults_to_three_seconds(watcher, clock, monkeypatch): """ - 0.5s left only ~0.3s of real trailing margin in field measurement and one - recording ended mid-word, so the default moved to 1.0 — and it has to be a - setting, not a magic number, so it can be tuned per node. + Field measurement showed the grant->speech offset runs ~0.84-1.62s, so a + 1.0s pad let short calls' windows close before voice audio even started + (clipping mid-word). The default moved to 3.0 — and it has to be a + setting, not a magic number, so it can be tuned per node without a code + change (and so tests can prove it isn't hardcoded anywhere downstream). """ - assert settings.call_tail_pad_seconds == 1.0 + assert settings.call_tail_pad_seconds == 3.0 - monkeypatch.setattr(settings, "call_tail_pad_seconds", 2.5) + monkeypatch.setattr(settings, "call_tail_pad_seconds", 5.0) await tick(watcher, update( call_log=[grant(1234, clock.now)], @@ -251,11 +253,51 @@ async def test_tail_pad_is_configurable_and_defaults_to_one_second(watcher, cloc edge_time = clock.now await tick(watcher, update(channels=[channel(tgid=1234, srcaddr=0, hold_tgid=1234)])) - clock.advance(settings.call_idle_timeout + 1.0) + # Advance well past both the idle timeout AND the monkeypatched 5.0s pad so + # the "now" cap in _handle_channels never masks the pad value under test. + clock.advance(settings.call_idle_timeout + 6.0) await tick(watcher, update(channels=[channel()])) payload = watcher.on_call_end.call_args[0][0] - assert payload["ended_at_epoch"] == pytest.approx(edge_time + 2.5) + assert payload["ended_at_epoch"] == pytest.approx(edge_time + 5.0) + + +@pytest.mark.asyncio +async def test_short_call_window_now_covers_delayed_voice_arrival(watcher, clock): + """ + Regression test for the truncation bug: a ~0.97s control-channel call + (grant to srcaddr-drop) previously closed its window at + last_tx_end + 1.0s pad, i.e. ~1.97s after the grant — but field + measurement shows voice audio doesn't start until ~1.5s after the grant + (0.84-1.62s measured), so the old window left as little as ~0.4s of + captured speech and clipped it mid-word. + + With the 3.0s default pad, the same short call's window must extend well + past the ~1.5s point where voice actually starts. + """ + call_start = clock.now + await tick(watcher, update( + call_log=[grant(1234, call_start)], + channels=[channel(tgid=1234, srcaddr=555)], + )) + + # The control-channel call itself is short — under 1 second. + clock.advance(0.97) + edge_time = clock.now + await tick(watcher, update(channels=[channel(tgid=1234, srcaddr=0, hold_tgid=1234)])) + + clock.advance(settings.call_idle_timeout + 0.5) + await tick(watcher, update(channels=[channel()])) + + payload = watcher.on_call_end.call_args[0][0] + assert payload["end_reason"] == "idle_timeout" + + voice_arrival = call_start + 1.5 # measured grant->speech offset, typical case + assert payload["ended_at_epoch"] == pytest.approx(edge_time + settings.call_tail_pad_seconds) + assert payload["ended_at_epoch"] > voice_arrival, ( + "recording window must extend past the point voice audio actually arrives, " + "not just past the control-channel call_log timestamps" + ) @pytest.mark.asyncio