Compare commits
2 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| d6dfe5a293 | |||
| 085fcdf1a1 |
+38
-18
@@ -29,29 +29,49 @@ PULSE_SOURCE=drb_sink.monitor
|
|||||||
# Seconds to wait for the shared PulseAudio socket before giving up and retrying.
|
# Seconds to wait for the shared PulseAudio socket before giving up and retrying.
|
||||||
PULSE_WAIT_TIMEOUT=30
|
PULSE_WAIT_TIMEOUT=30
|
||||||
|
|
||||||
# Call segmentation: seconds of radio silence before the current recording is
|
# --- Call segmentation -------------------------------------------------------
|
||||||
# closed. Grants on the same talkgroup within this window stay in ONE recording.
|
# Recording boundaries come from the AUDIO, not the control channel: a recording
|
||||||
# Tune ONLY from the "measured control-channel idle" line the edge node logs on
|
# starts at voice onset and ends after this many seconds of silence actually
|
||||||
# every idle-timeout close — silence measured in the audio is a different clock
|
# heard in the stream. Transmissions on the same talkgroup separated by less
|
||||||
# (it also contains the ~1.9s P25 grant-to-speech delay).
|
# than this stay in ONE recording, so back-and-forth traffic is one file.
|
||||||
|
# Tune from the "measured trailing silence" line logged on every close.
|
||||||
|
CALL_SILENCE_TIMEOUT=3.0
|
||||||
|
|
||||||
|
# dBFS (RMS over one ~46ms chunk) below which audio counts as silence and the
|
||||||
|
# recording is allowed to close.
|
||||||
|
#
|
||||||
|
# This does NOT need calibrating against your radio's noise floor. Between
|
||||||
|
# transmissions the capture is the monitor of a PulseAudio *null sink*, which
|
||||||
|
# emits DIGITAL silence: measured on a live node it sits at about -91 dBFS —
|
||||||
|
# one least-significant bit of a 16-bit sample — while speech averages about
|
||||||
|
# -18 dBFS. Anything from roughly -70 to -40 behaves identically. Only change
|
||||||
|
# this if you have replaced the audio path with something that has a real
|
||||||
|
# analog noise floor.
|
||||||
|
CALL_SILENCE_THRESHOLD_DB=-50
|
||||||
|
|
||||||
|
# DEPRECATED as a primary control. Used ONLY when PulseAudio capture is not
|
||||||
|
# producing audio, where the old control-channel state machine takes over so
|
||||||
|
# the node still reports radio activity (with no recordings) while its audio
|
||||||
|
# path is broken.
|
||||||
CALL_IDLE_TIMEOUT=3
|
CALL_IDLE_TIMEOUT=3
|
||||||
|
|
||||||
# Seconds of audio kept after the last transmission ends. This is the only
|
# Seconds of audio kept past a CONTROL-CHANNEL-derived boundary — a talkgroup
|
||||||
# headroom protecting the final word of a transmission — usually the disposition
|
# change, or a close in the fallback mode above. Buffered audio lags the
|
||||||
# or the address. Raised 1.0 -> 3.0 after field measurement showed the
|
# control channel by ~1.5s (grant-to-speech offset measured 0.84-1.62s), so
|
||||||
# grant-to-speech offset is ~0.84-1.62s (typically ~1.5s): at 1.0s pad, short
|
# cutting at the exact control-channel timestamp clipped the last words of the
|
||||||
# calls had their recording window close before the voice even started,
|
# outgoing call. Does NOT apply to the normal end of a call any more; that
|
||||||
# clipping speech mid-word. Safe to be generous — trim_silence already strips
|
# boundary comes from the audio and needs no pad. Safe to be generous — the
|
||||||
# the extra back off long calls before upload, so only short transmissions
|
# extra is trimmed off again before upload.
|
||||||
# actually benefit from the larger window.
|
|
||||||
CALL_TAIL_PAD_SECONDS=3.0
|
CALL_TAIL_PAD_SECONDS=3.0
|
||||||
|
|
||||||
# Strip leading/trailing dead air before upload. ~63% of an untrimmed recording
|
# Strip leading/trailing dead air before upload. Recordings deliberately
|
||||||
# is silence, which costs Whisper spend and makes it hallucinate text that was
|
# over-capture at both ends, and silence costs Whisper spend and makes it
|
||||||
# never spoken. Only the head and tail are touched, with a guard margin so no
|
# hallucinate text that was never spoken. Trimming is a sample-offset slice of
|
||||||
# syllable is clipped. Set to false to upload raw audio.
|
# the buffered PCM (no re-encode) and only ever touches the head and tail, with
|
||||||
|
# a guard margin so no syllable is clipped. Set to false to upload raw audio.
|
||||||
TRIM_SILENCE=true
|
TRIM_SILENCE=true
|
||||||
# dBFS below which audio counts as silence for detection.
|
# dBFS (RMS) below which audio counts as silence when trimming the ends. Kept
|
||||||
|
# stricter than CALL_SILENCE_THRESHOLD_DB on purpose.
|
||||||
TRIM_SILENCE_THRESHOLD_DB=-40
|
TRIM_SILENCE_THRESHOLD_DB=-40
|
||||||
# Seconds of audio kept either side of detected speech.
|
# Seconds of audio kept either side of detected speech.
|
||||||
TRIM_SILENCE_GUARD_SECONDS=0.25
|
TRIM_SILENCE_GUARD_SECONDS=0.25
|
||||||
|
|||||||
@@ -15,5 +15,8 @@ RUN pip install uv && uv pip install --system --no-cache-dir -r requirements.txt
|
|||||||
|
|
||||||
COPY app/ ./app/
|
COPY app/ ./app/
|
||||||
COPY tests/ ./tests/
|
COPY tests/ ./tests/
|
||||||
|
# Without this the container runs pytest with asyncio_mode defaulting to strict,
|
||||||
|
# so unmarked async tests error out even though they pass locally.
|
||||||
|
COPY pytest.ini .
|
||||||
|
|
||||||
CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "80", "--reload"]
|
CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "80", "--reload"]
|
||||||
|
|||||||
+66
-35
@@ -34,49 +34,80 @@ class Settings(BaseSettings):
|
|||||||
# Bounded wait for the shared PulseAudio socket before launching FFmpeg.
|
# Bounded wait for the shared PulseAudio socket before launching FFmpeg.
|
||||||
pulse_wait_timeout: float = 30.0
|
pulse_wait_timeout: float = 30.0
|
||||||
|
|
||||||
# Call segmentation — seconds with no active transmission before the current
|
# ------------------------------------------------------------------
|
||||||
# recording is closed out. Consecutive grants on the SAME talkgroup inside this
|
# Call segmentation
|
||||||
# window are kept in one recording so back-and-forth traffic stays together.
|
|
||||||
#
|
#
|
||||||
# Do NOT tune this against measured *audio* silence: audio gaps also contain
|
# Boundaries come from the AUDIO, not the control channel. A recording
|
||||||
# the ~1.9 s P25 grant→speech delay, so they are always longer than the
|
# starts at voice onset and ends after call_silence_timeout seconds of
|
||||||
# control-channel idle this timer measures. metadata_watcher logs the real
|
# silence actually heard in the stream. See internal/metadata_watcher.py
|
||||||
# measured idle on every idle-timeout close — tune from that.
|
# for why the control channel is no longer trusted for either edge.
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
|
# Seconds of continuous silence IN THE AUDIO before the current recording is
|
||||||
|
# closed. This is the primary segmentation control. Consecutive
|
||||||
|
# transmissions on the SAME talkgroup separated by less than this stay in
|
||||||
|
# one recording, so back-and-forth traffic is one file.
|
||||||
|
#
|
||||||
|
# Defaults to 3.0 to match the behaviour of the control-channel idle timer
|
||||||
|
# it replaces, but it is NOT the same clock: this one measures real silence
|
||||||
|
# in the audio, with no grant->speech delay mixed in. metadata_watcher logs
|
||||||
|
# the measured trailing silence on every close — tune from that number.
|
||||||
|
call_silence_timeout: float = 3.0
|
||||||
|
|
||||||
|
# dBFS (RMS, measured over one ~46ms capture chunk) below which audio counts
|
||||||
|
# as silence for the purpose of ending a recording.
|
||||||
|
#
|
||||||
|
# This does NOT need field calibration against radio noise. Between
|
||||||
|
# transmissions the capture is the monitor of a PulseAudio *null sink*,
|
||||||
|
# which emits digital silence, not an analog noise floor: measured on a live
|
||||||
|
# node the gap sits at about -91 dBFS, i.e. one least-significant bit of a
|
||||||
|
# 16-bit sample. Speech on the same node averages about -18 dBFS. Anything
|
||||||
|
# between roughly -70 and -40 therefore behaves identically; -50 is chosen
|
||||||
|
# to sit far below even quiet speech while staying far above the floor.
|
||||||
|
call_silence_threshold_db: float = -50.0
|
||||||
|
|
||||||
|
# DEPRECATED as a primary control — used ONLY in console fallback mode, i.e.
|
||||||
|
# when PulseAudio capture is not producing audio and there is nothing to
|
||||||
|
# segment on. Then, and only then, the old control-channel state machine
|
||||||
|
# runs and closes a segment this many seconds after the last observed
|
||||||
|
# transmission. Those segments carry no audio; they exist so the node keeps
|
||||||
|
# reporting real radio activity to C2 while its audio path is broken.
|
||||||
|
#
|
||||||
|
# Do NOT tune this against measured *audio* silence — use
|
||||||
|
# call_silence_timeout for that.
|
||||||
call_idle_timeout: float = 3.0
|
call_idle_timeout: float = 3.0
|
||||||
|
|
||||||
# Audio kept after the observed end of the last transmission. The srcaddr
|
# Audio kept past a CONSOLE-DERIVED segment boundary, covering the fact that
|
||||||
# 1→0 edge can be up to one poll (0.5 s) late and the encoder adds its own
|
# buffered audio lags control-channel timestamps by ~1.5s (grant->speech
|
||||||
# latency, so this is the only headroom protecting the last word of a
|
# offset measured 0.84-1.62s across 7 field calls).
|
||||||
# transmission — which is usually the disposition or the address.
|
|
||||||
#
|
#
|
||||||
# Raised 1.0 -> 3.0 after field measurement showed the recording WINDOW
|
# Still needed, with a narrower job than before. It no longer pads the
|
||||||
# (anchored to OP25 control-channel timestamps) closing well before the
|
# normal end of a call — that boundary now comes from the audio itself and
|
||||||
# actual voice audio arrives: grant->speech offset measured 0.84-1.62s
|
# needs no pad at all. It applies to the three boundaries that are still
|
||||||
# across 7 calls (~1.5s typical). At the old 1.0s pad, a short
|
# control-channel timestamps:
|
||||||
# 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
|
# tgid_change close the outgoing call at the new grant + pad
|
||||||
# back to trim_silence_guard_seconds before upload, so a larger pad costs
|
# tgid_change_unlogged close at the observing poll + pad
|
||||||
# long calls nothing (the extra is trimmed away) while giving short
|
# idle_timeout console fallback mode only
|
||||||
# transmissions enough window to actually capture the voice. Over-capture
|
#
|
||||||
# is free; under-capture loses words permanently. Do not tune this back
|
# Safe to be generous: trim_silence strips trailing silence back to
|
||||||
# down without new field data showing the grant->speech offset has
|
# trim_silence_guard_seconds before upload, so a larger pad costs long calls
|
||||||
# shrunk — see DEFERRED.md for the call_idle_timeout coupling this value
|
# nothing. Over-capture is free; under-capture loses words permanently. If
|
||||||
# now sits at.
|
# the outgoing and incoming recordings overlap in the underlying audio
|
||||||
|
# because of this pad, that is correct — the audio contains both.
|
||||||
call_tail_pad_seconds: float = 3.0
|
call_tail_pad_seconds: float = 3.0
|
||||||
|
|
||||||
# Strip leading/trailing dead air before upload. ~63% of a typical recording
|
# Strip leading/trailing dead air before upload. A recording deliberately
|
||||||
# is silence (the grant→speech delay plus the tail pad), which inflates
|
# over-captures at both ends (pre-roll at the head, the whole measured
|
||||||
# Whisper cost and is a well-documented trigger for hallucinated transcript
|
# silence run at the tail), which inflates Whisper cost and is a
|
||||||
# text. Trimming is conservative — see internal/audio_trim.py.
|
# well-documented trigger for hallucinated transcript text. Trimming is a
|
||||||
|
# sample-offset slice of the buffered PCM — no re-encode — and only ever
|
||||||
|
# touches the head and tail. See internal/audio_trim.py.
|
||||||
trim_silence: bool = True
|
trim_silence: bool = True
|
||||||
# Anything quieter than this counts as silence for detection purposes.
|
# dBFS (RMS) below which audio counts as silence when trimming the ends.
|
||||||
|
# Kept above call_silence_threshold_db on purpose: the closer must not miss
|
||||||
|
# speech (permissive), the trimmer must not leave dead air (stricter), and
|
||||||
|
# trim_silence_guard_seconds protects the syllable either way.
|
||||||
trim_silence_threshold_db: float = -40.0
|
trim_silence_threshold_db: float = -40.0
|
||||||
# Guard margin kept around detected speech so no syllable is clipped.
|
# Guard margin kept around detected speech so no syllable is clipped.
|
||||||
trim_silence_guard_seconds: float = 0.25
|
trim_silence_guard_seconds: float = 0.25
|
||||||
|
|||||||
@@ -1,270 +1,212 @@
|
|||||||
"""
|
"""
|
||||||
Conservative leading/trailing silence removal for finished call recordings.
|
Leading/trailing silence removal, as a slice of raw PCM.
|
||||||
|
|
||||||
WHY: P25 grants the channel, radios tune, and only then does a human start
|
WHY: P25 grants the channel, radios tune, and only then does a human start
|
||||||
talking. Measured on six real recordings from a live node, that costs 1.71–2.45 s
|
talking; the recorder also deliberately over-captures at the tail (it closes a
|
||||||
of dead air at the head of every single file, and the tail pad adds its own
|
call only after N seconds of silence have actually been HEARD). Both ends
|
||||||
~0.3–1.0 s. Roughly 63% of every uploaded MP3 was silence. That is not just
|
therefore carry dead air. That is not just wasted Whisper spend: silence is a
|
||||||
wasted Whisper spend: silence is a well-documented trigger for Whisper
|
well-documented trigger for Whisper hallucinating text that was never spoken,
|
||||||
hallucinating text that was never spoken, and a hallucinated sentence poisons
|
and a hallucinated sentence poisons entity extraction and then incident
|
||||||
entity extraction and then incident correlation downstream.
|
correlation downstream.
|
||||||
|
|
||||||
WHY IT IS SAFE: only the head and tail are touched, never the middle, and a
|
WHY IT IS SAFE: only the head and tail are touched, never the middle, and a
|
||||||
guard margin is kept around the detected speech so no syllable can be clipped.
|
guard margin is kept around the detected speech so no syllable can be clipped.
|
||||||
If detection says the whole file is silent we do NOT emit a zero-length file —
|
If detection says the whole buffer is silent we do NOT emit a zero-length
|
||||||
the caller is told and decides (see call_recorder: it skips the upload and logs).
|
recording — the caller is told and decides (see call_recorder: it skips the
|
||||||
|
upload and logs).
|
||||||
|
|
||||||
TIMING: trimming changes the audio's duration relative to the call's wall-clock
|
TIMING: trimming changes the audio's duration relative to the call's wall-clock
|
||||||
start/end, so every trim reports exactly how much was removed from each end.
|
start/end, so every trim reports exactly how much was removed from each end.
|
||||||
Callers must carry those offsets forward — `started_at`/`ended_at` keep meaning
|
Callers must carry those offsets forward — `started_at`/`ended_at` keep meaning
|
||||||
the CALL's bounds, and the trimmed audio's own bounds are reported separately.
|
the CALL's bounds, and the trimmed audio's own bounds are reported separately.
|
||||||
|
|
||||||
Implementation is two FFmpeg passes (detect, then cut). FFmpeg is already a hard
|
HISTORY — THIS USED TO BE TWO FFMPEG PASSES. Detection was `silencedetect`
|
||||||
dependency of this container and is already running the capture, so this adds no
|
parsed out of FFmpeg's stderr, and the cut was a second FFmpeg re-encode. Both
|
||||||
new moving parts. `silenceremove` in one pass was rejected on purpose: it gives
|
are gone: the recorder now buffers PCM, so detection is arithmetic over the
|
||||||
no way to learn how much it removed, which would make the timing metadata above
|
samples and the cut is a byte-offset slice. Consequences worth keeping in mind:
|
||||||
impossible to produce.
|
|
||||||
|
* The recording is encoded to MP3 exactly ONCE, after this runs, instead of
|
||||||
|
being captured as MP3 and then re-encoded. One less generation of lossy
|
||||||
|
encoding on every upload, and one less subprocess per call.
|
||||||
|
* The threshold is now RMS over a short window (see pcm.rms_dbfs), where
|
||||||
|
FFmpeg's silencedetect compared |sample| per sample. Same units (dBFS),
|
||||||
|
slightly different meaning — do not port an old threshold across without
|
||||||
|
re-reading the field logs.
|
||||||
|
* There is no "is it worth re-encoding" minimum any more. A slice is free, so
|
||||||
|
even a 0.05 s trim is applied.
|
||||||
"""
|
"""
|
||||||
import asyncio
|
|
||||||
import re
|
|
||||||
from dataclasses import dataclass
|
from dataclasses import dataclass
|
||||||
from pathlib import Path
|
from typing import Optional, Tuple
|
||||||
from typing import List, Optional, Tuple
|
|
||||||
|
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
|
from app.internal import pcm
|
||||||
from app.internal.logger import logger
|
from app.internal.logger import logger
|
||||||
|
|
||||||
# Minimum run of quiet before FFmpeg calls it a silence region. Below ~0.3 s this
|
# Window the head/tail scan works in. 20 ms is short enough that the guard
|
||||||
# starts firing on the natural pauses between words, which is not what we want —
|
# margin below dwarfs the quantisation error, and long enough that RMS means
|
||||||
# we only care about the big block of dead air at each end.
|
# something.
|
||||||
MIN_SILENCE_SECONDS = 0.3
|
ANALYSIS_WINDOW_SECONDS = 0.02
|
||||||
|
|
||||||
# A silence region only counts as "leading" if it begins essentially at the file
|
# How far in from each end the scan is willing to look before giving up.
|
||||||
# head. One chunk of slop.
|
#
|
||||||
HEAD_EPSILON_SECONDS = 0.15
|
# Bounds the only unbounded cost in this module: the per-sample RMS loop. A
|
||||||
|
# normal recording resolves within a window or two at the head (the recorder
|
||||||
# ...and only as "trailing" if it reaches the end of the audio. Do NOT assume a
|
# starts on voice onset) and within the silence run at the tail, so this cap is
|
||||||
# missing `silence_end` marks that case: FFmpeg 6.x flushes a closing
|
# never reached in practice. If it IS reached, we leave the audio untrimmed and
|
||||||
# `silence_end` at EOF, so an all-silence file looks exactly like a file with one
|
# say so — shipping an untrimmed recording is always better than shipping none.
|
||||||
# closed silence region. Verified against ffmpeg 6.1.1 — the reported end lands
|
MAX_SCAN_SECONDS = 30.0
|
||||||
# ~0.03 s short of the (offset-corrected) duration, hence this epsilon. The
|
|
||||||
# residual risk is clipping <=0.1 s of audio that follows a >=0.3 s gap right at
|
|
||||||
# EOF, which the guard margin below more than covers.
|
|
||||||
TAIL_EPSILON_SECONDS = 0.10
|
|
||||||
|
|
||||||
# Don't bother re-encoding to reclaim less than this — a re-encode costs a CPU
|
|
||||||
# spike on a Pi and a generation of MP3 quality, which is a bad trade for
|
|
||||||
# a fraction of a second.
|
|
||||||
MIN_TRIM_SECONDS = 0.20
|
|
||||||
|
|
||||||
# Bounded so a wedged FFmpeg can never stall the upload path.
|
|
||||||
FFMPEG_TIMEOUT_SECONDS = 30.0
|
|
||||||
|
|
||||||
_SILENCE_START_RE = re.compile(r"silence_start:\s*(-?[0-9.]+)")
|
|
||||||
_SILENCE_END_RE = re.compile(r"silence_end:\s*(-?[0-9.]+)")
|
|
||||||
_DURATION_RE = re.compile(r"Duration:\s*(\d+):(\d\d):(\d\d\.\d+)")
|
|
||||||
_START_RE = re.compile(r"Duration:[^\n]*?start:\s*(-?[0-9.]+)")
|
|
||||||
|
|
||||||
|
|
||||||
@dataclass(frozen=True)
|
@dataclass(frozen=True)
|
||||||
class TrimResult:
|
class TrimResult:
|
||||||
"""Outcome of a trim attempt. `lead`/`tail` are seconds actually removed."""
|
"""Outcome of a trim attempt. `lead`/`tail` are seconds actually removed."""
|
||||||
|
|
||||||
path: Optional[Path]
|
|
||||||
lead: float = 0.0
|
lead: float = 0.0
|
||||||
tail: float = 0.0
|
tail: float = 0.0
|
||||||
duration_before: float = 0.0
|
duration_before: float = 0.0
|
||||||
duration_after: float = 0.0
|
duration_after: float = 0.0
|
||||||
all_silence: bool = False
|
all_silence: bool = False
|
||||||
applied: bool = False
|
applied: bool = False
|
||||||
|
# True when the scan hit MAX_SCAN_SECONDS without finding speech, so
|
||||||
|
# `all_silence` could not be determined and nothing was trimmed.
|
||||||
|
scan_truncated: bool = False
|
||||||
|
|
||||||
@property
|
@property
|
||||||
def trimmed_seconds(self) -> float:
|
def trimmed_seconds(self) -> float:
|
||||||
return self.lead + self.tail
|
return self.lead + self.tail
|
||||||
|
|
||||||
|
|
||||||
async def _run(cmd: List[str]) -> Tuple[int, str]:
|
def _window_bytes() -> int:
|
||||||
"""Run FFmpeg and return (returncode, stderr). FFmpeg reports on stderr."""
|
return max(pcm.FRAME_BYTES, pcm.byte_offset(ANALYSIS_WINDOW_SECONDS))
|
||||||
proc = await asyncio.create_subprocess_exec(
|
|
||||||
*cmd,
|
|
||||||
stdout=asyncio.subprocess.DEVNULL,
|
|
||||||
stderr=asyncio.subprocess.PIPE,
|
|
||||||
)
|
|
||||||
try:
|
|
||||||
_, stderr = await asyncio.wait_for(proc.communicate(), timeout=FFMPEG_TIMEOUT_SECONDS)
|
|
||||||
except asyncio.TimeoutError:
|
|
||||||
try:
|
|
||||||
proc.kill()
|
|
||||||
except Exception:
|
|
||||||
pass
|
|
||||||
raise
|
|
||||||
return proc.returncode or 0, stderr.decode(errors="replace")
|
|
||||||
|
|
||||||
|
|
||||||
def _parse_duration(stderr: str) -> Optional[float]:
|
def first_signal_offset(
|
||||||
|
audio: bytes,
|
||||||
|
threshold_db: float,
|
||||||
|
limit_seconds: float = MAX_SCAN_SECONDS,
|
||||||
|
) -> Optional[int]:
|
||||||
"""
|
"""
|
||||||
Length of the decodable audio, in silencedetect's coordinates.
|
Byte offset of the first window carrying signal, scanning forward.
|
||||||
|
|
||||||
MP3 carries encoder delay/padding, which FFmpeg reports as a container
|
None means "no signal found" — either the buffer really is all silence or
|
||||||
`start:` offset — the container duration is that much longer than the audio
|
the scan hit `limit_seconds` first; the caller distinguishes the two by
|
||||||
silencedetect actually timestamps. Subtracting it is what lets
|
comparing the scanned span against the buffer length.
|
||||||
TAIL_EPSILON_SECONDS stay tight enough to be safe.
|
|
||||||
"""
|
"""
|
||||||
match = _DURATION_RE.search(stderr)
|
window = _window_bytes()
|
||||||
if not match:
|
limit = min(len(audio), pcm.byte_offset(limit_seconds) or len(audio))
|
||||||
|
offset = 0
|
||||||
|
while offset < limit:
|
||||||
|
chunk = audio[offset:offset + window]
|
||||||
|
if not pcm.is_silent(chunk, threshold_db):
|
||||||
|
return offset
|
||||||
|
offset += window
|
||||||
return None
|
return None
|
||||||
hours, minutes, seconds = match.groups()
|
|
||||||
duration = int(hours) * 3600 + int(minutes) * 60 + float(seconds)
|
|
||||||
|
|
||||||
start = _START_RE.search(stderr)
|
|
||||||
if start:
|
|
||||||
offset = float(start.group(1))
|
|
||||||
if 0.0 <= offset < duration:
|
|
||||||
duration -= offset
|
|
||||||
return duration
|
|
||||||
|
|
||||||
|
|
||||||
def _parse_silences(stderr: str) -> List[Tuple[float, Optional[float]]]:
|
def last_signal_offset(
|
||||||
|
audio: bytes,
|
||||||
|
threshold_db: float,
|
||||||
|
limit_seconds: float = MAX_SCAN_SECONDS,
|
||||||
|
) -> Optional[int]:
|
||||||
"""
|
"""
|
||||||
Extract silence regions as (start, end) with end=None when it runs to EOF.
|
Byte offset of the END of the last window carrying signal, scanning back.
|
||||||
|
|
||||||
FFmpeg emits `silence_start:` and a later `silence_end:` per region, and
|
Returns the offset one past the last signal-bearing window, so it can be
|
||||||
simply never emits the closing line for a region that reaches EOF.
|
used directly as a slice bound.
|
||||||
"""
|
"""
|
||||||
regions: List[Tuple[float, Optional[float]]] = []
|
window = _window_bytes()
|
||||||
pending: Optional[float] = None
|
total = pcm.align(len(audio))
|
||||||
for line in stderr.splitlines():
|
floor = max(0, total - (pcm.byte_offset(limit_seconds) or total))
|
||||||
if "silencedetect" not in line:
|
offset = total
|
||||||
continue
|
while offset > floor:
|
||||||
start = _SILENCE_START_RE.search(line)
|
start = max(floor, offset - window)
|
||||||
if start:
|
if not pcm.is_silent(audio[start:offset], threshold_db):
|
||||||
pending = float(start.group(1))
|
return offset
|
||||||
continue
|
offset = start
|
||||||
end = _SILENCE_END_RE.search(line)
|
return None
|
||||||
if end and pending is not None:
|
|
||||||
regions.append((pending, float(end.group(1))))
|
|
||||||
pending = None
|
|
||||||
if pending is not None:
|
|
||||||
regions.append((pending, None))
|
|
||||||
return regions
|
|
||||||
|
|
||||||
|
|
||||||
def speech_bounds(
|
def keep_window(
|
||||||
regions: List[Tuple[float, Optional[float]]],
|
first_signal: Optional[int],
|
||||||
duration: float,
|
last_signal: Optional[int],
|
||||||
guard: float,
|
total_bytes: int,
|
||||||
) -> Tuple[float, float, bool]:
|
guard_bytes: int,
|
||||||
|
) -> Tuple[int, int]:
|
||||||
"""
|
"""
|
||||||
Turn detected silence regions into the [start, end] window to keep.
|
Turn detected signal bounds into the byte range to keep.
|
||||||
|
|
||||||
Pure and side-effect free so the decision logic is unit-testable without
|
Pure and side-effect free so the decision that can destroy a transmission
|
||||||
FFmpeg. Returns (start, end, all_silence).
|
stays unit-testable without any audio. Offsets are sample-aligned and
|
||||||
|
clamped to the buffer.
|
||||||
"""
|
"""
|
||||||
speech_start = 0.0
|
total = pcm.align(total_bytes)
|
||||||
speech_end = duration
|
start = 0 if first_signal is None else max(0, first_signal - guard_bytes)
|
||||||
|
end = total if last_signal is None else min(total, last_signal + guard_bytes)
|
||||||
if regions:
|
start = pcm.align(start)
|
||||||
head_start, head_end = regions[0]
|
end = pcm.align(end)
|
||||||
if head_start <= HEAD_EPSILON_SECONDS and head_end is not None:
|
if end <= start:
|
||||||
speech_start = head_end
|
return 0, total
|
||||||
|
return start, end
|
||||||
tail_start, tail_end = regions[-1]
|
|
||||||
# `None` = pre-6.x FFmpeg, which simply stopped reporting at EOF.
|
|
||||||
reaches_eof = tail_end is None or (duration - tail_end) <= TAIL_EPSILON_SECONDS
|
|
||||||
if reaches_eof:
|
|
||||||
speech_end = min(speech_end, tail_start)
|
|
||||||
|
|
||||||
if speech_end <= speech_start:
|
|
||||||
# Detection says there is no speech anywhere in the file.
|
|
||||||
return 0.0, duration, True
|
|
||||||
|
|
||||||
# Guard margin: never trim right up against the first/last syllable.
|
|
||||||
keep_start = max(0.0, speech_start - guard)
|
|
||||||
keep_end = min(duration, speech_end + guard)
|
|
||||||
return keep_start, keep_end, False
|
|
||||||
|
|
||||||
|
|
||||||
async def trim_silence(
|
def trim_pcm(
|
||||||
path: Path,
|
audio: bytes,
|
||||||
sample_rate: str,
|
|
||||||
bitrate: str,
|
|
||||||
threshold_db: Optional[float] = None,
|
threshold_db: Optional[float] = None,
|
||||||
guard: Optional[float] = None,
|
guard: Optional[float] = None,
|
||||||
) -> TrimResult:
|
) -> Tuple[bytes, TrimResult]:
|
||||||
"""
|
"""
|
||||||
Trim leading/trailing silence in place, preserving the original on failure.
|
Return (kept_audio, result). Never raises and never returns empty audio.
|
||||||
|
|
||||||
Never raises: any problem degrades to "leave the file exactly as it was",
|
An all-silence buffer is returned UNCHANGED with `all_silence=True`: the
|
||||||
because shipping an untrimmed recording is far better than shipping none.
|
caller decides what to do with a recording that contains no speech at all —
|
||||||
|
that is itself a signal (squelch misconfigured, wrong sink, dead audio
|
||||||
|
path), not something to silently truncate to nothing.
|
||||||
"""
|
"""
|
||||||
threshold = settings.trim_silence_threshold_db if threshold_db is None else threshold_db
|
threshold = settings.trim_silence_threshold_db if threshold_db is None else threshold_db
|
||||||
margin = settings.trim_silence_guard_seconds if guard is None else guard
|
margin = settings.trim_silence_guard_seconds if guard is None else guard
|
||||||
|
|
||||||
try:
|
total = pcm.align(len(audio))
|
||||||
_, stderr = await _run([
|
duration = pcm.seconds(total)
|
||||||
"ffmpeg", "-hide_banner", "-nostdin", "-nostats",
|
if total <= 0:
|
||||||
"-i", str(path),
|
return audio, TrimResult()
|
||||||
"-af", f"silencedetect=noise={threshold}dB:d={MIN_SILENCE_SECONDS}",
|
|
||||||
"-f", "null", "-",
|
|
||||||
])
|
|
||||||
except Exception as e:
|
|
||||||
logger.warning(f"Silence detection failed for {path.name} ({e}) — uploading untrimmed.")
|
|
||||||
return TrimResult(path=path)
|
|
||||||
|
|
||||||
duration = _parse_duration(stderr)
|
first = first_signal_offset(audio, threshold)
|
||||||
if duration is None or duration <= 0:
|
if first is None:
|
||||||
logger.warning(f"Could not determine duration of {path.name} — uploading untrimmed.")
|
scanned = min(total, pcm.byte_offset(MAX_SCAN_SECONDS) or total)
|
||||||
return TrimResult(path=path)
|
if scanned < total:
|
||||||
|
# Could not prove it is all silence; refuse to guess.
|
||||||
regions = _parse_silences(stderr)
|
|
||||||
keep_start, keep_end, all_silence = speech_bounds(regions, duration, margin)
|
|
||||||
|
|
||||||
if all_silence:
|
|
||||||
# Deliberately NOT trimmed to nothing. The caller decides what to do with
|
|
||||||
# a recording that contains no speech at all — that is itself a signal
|
|
||||||
# (squelch misconfigured, wrong sink, dead audio path).
|
|
||||||
logger.warning(
|
logger.warning(
|
||||||
f"{path.name} is entirely silence ({duration:.2f}s, threshold {threshold}dB) — "
|
f"Silence scan gave up after {MAX_SCAN_SECONDS:.0f}s without finding speech in a "
|
||||||
|
f"{duration:.1f}s recording — leaving it untrimmed."
|
||||||
|
)
|
||||||
|
return audio, TrimResult(
|
||||||
|
duration_before=duration, duration_after=duration, scan_truncated=True
|
||||||
|
)
|
||||||
|
logger.warning(
|
||||||
|
f"Recording is entirely silence ({duration:.2f}s, threshold {threshold:.1f}dBFS RMS) — "
|
||||||
"no speech detected."
|
"no speech detected."
|
||||||
)
|
)
|
||||||
return TrimResult(path=path, duration_before=duration, duration_after=duration, all_silence=True)
|
return audio, TrimResult(duration_before=duration, duration_after=duration, all_silence=True)
|
||||||
|
|
||||||
lead = keep_start
|
last = last_signal_offset(audio, threshold)
|
||||||
tail = duration - keep_end
|
guard_bytes = pcm.byte_offset(margin)
|
||||||
if (lead + tail) < MIN_TRIM_SECONDS:
|
keep_start, keep_end = keep_window(first, last, total, guard_bytes)
|
||||||
return TrimResult(path=path, duration_before=duration, duration_after=duration)
|
|
||||||
|
|
||||||
trimmed = path.with_name(f"{path.stem}_trimmed{path.suffix}")
|
lead = pcm.seconds(keep_start)
|
||||||
try:
|
tail = pcm.seconds(total - keep_end)
|
||||||
code, err = await _run([
|
if keep_start <= 0 and keep_end >= total:
|
||||||
"ffmpeg", "-hide_banner", "-nostdin", "-nostats",
|
return audio[:total], TrimResult(duration_before=duration, duration_after=duration)
|
||||||
"-loglevel", "warning", "-y",
|
|
||||||
"-ss", f"{keep_start:.3f}",
|
|
||||||
"-i", str(path),
|
|
||||||
"-t", f"{keep_end - keep_start:.3f}",
|
|
||||||
"-ac", "1", "-ar", sample_rate, "-b:a", bitrate,
|
|
||||||
"-f", "mp3", str(trimmed),
|
|
||||||
])
|
|
||||||
except Exception as e:
|
|
||||||
logger.warning(f"Silence trim failed for {path.name} ({e}) — uploading untrimmed.")
|
|
||||||
trimmed.unlink(missing_ok=True)
|
|
||||||
return TrimResult(path=path, duration_before=duration, duration_after=duration)
|
|
||||||
|
|
||||||
if code != 0 or not trimmed.exists() or trimmed.stat().st_size == 0:
|
kept = audio[keep_start:keep_end]
|
||||||
logger.warning(f"Silence trim produced no output for {path.name} ({err.strip()}) — uploading untrimmed.")
|
after = pcm.seconds(len(kept))
|
||||||
trimmed.unlink(missing_ok=True)
|
|
||||||
return TrimResult(path=path, duration_before=duration, duration_after=duration)
|
|
||||||
|
|
||||||
trimmed.replace(path)
|
|
||||||
logger.info(
|
logger.info(
|
||||||
f"Trimmed {path.name}: -{lead:.2f}s lead, -{tail:.2f}s tail "
|
f"Trimmed recording: -{lead:.2f}s lead, -{tail:.2f}s tail "
|
||||||
f"({duration:.2f}s → {keep_end - keep_start:.2f}s)"
|
f"({duration:.2f}s -> {after:.2f}s, threshold {threshold:.1f}dBFS RMS)"
|
||||||
)
|
)
|
||||||
return TrimResult(
|
return kept, TrimResult(
|
||||||
path=path,
|
|
||||||
lead=lead,
|
lead=lead,
|
||||||
tail=tail,
|
tail=tail,
|
||||||
duration_before=duration,
|
duration_before=duration,
|
||||||
duration_after=keep_end - keep_start,
|
duration_after=after,
|
||||||
applied=True,
|
applied=True,
|
||||||
)
|
)
|
||||||
|
|||||||
@@ -1,16 +1,26 @@
|
|||||||
"""
|
"""
|
||||||
Continuous PulseAudio capture: a ring buffer for PRE-ROLL, a per-call
|
Continuous PulseAudio capture: a ring buffer for PRE-ROLL, a per-call
|
||||||
accumulator for the call itself.
|
accumulator for the call itself, and the voice-activity signal that decides
|
||||||
|
where calls begin and end.
|
||||||
|
|
||||||
A persistent capture process runs for the lifetime of the node. Spawning FFmpeg
|
A persistent capture process runs for the lifetime of the node. Spawning FFmpeg
|
||||||
per call used to lose the first 1-2 s to process startup, which meant short
|
per call used to lose the first 1-2 s to process startup, which meant short
|
||||||
transmissions produced empty files, so capture never stops.
|
transmissions produced empty files, so capture never stops.
|
||||||
|
|
||||||
|
RAW PCM, NOT MP3 — this is the change everything else hangs off. FFmpeg is
|
||||||
|
asked for s16le/22050/mono on stdout instead of an MP3 stream, so:
|
||||||
|
|
||||||
|
* silence detection is integer arithmetic over each chunk as it arrives, with
|
||||||
|
no decode, which is what makes AUDIO-DRIVEN call boundaries possible;
|
||||||
|
* trimming is a byte-offset slice, not a second FFmpeg pass;
|
||||||
|
* MP3 encoding happens exactly ONCE, at save time, so uploads are no longer
|
||||||
|
double-encoded.
|
||||||
|
|
||||||
TWO BUFFERS, TWO JOBS — this split is load-bearing:
|
TWO BUFFERS, TWO JOBS — this split is load-bearing:
|
||||||
|
|
||||||
RING BUFFER holds the last RING_BUFFER_SECONDS of audio at all times. Its
|
RING BUFFER holds the last RING_BUFFER_SECONDS of audio at all times. Its
|
||||||
only job is PRE-ROLL: however late we notice a grant, we can
|
only job is PRE-ROLL: however late the segmenter notices voice
|
||||||
still seek back to OP25's exact timestamp. It is sized for
|
onset, we can still seek back before it. It is sized for
|
||||||
detection latency, nothing else.
|
detection latency, nothing else.
|
||||||
|
|
||||||
ACCUMULATOR opened by start_recording(), fed by every subsequent chunk, and
|
ACCUMULATOR opened by start_recording(), fed by every subsequent chunk, and
|
||||||
@@ -20,6 +30,14 @@ TWO BUFFERS, TWO JOBS — this split is load-bearing:
|
|||||||
which silently clamped the front of any call longer than
|
which silently clamped the front of any call longer than
|
||||||
RING_BUFFER_SECONDS.
|
RING_BUFFER_SECONDS.
|
||||||
|
|
||||||
|
VOICE ACTIVITY is tracked CONTINUOUSLY, not only while recording, because the
|
||||||
|
segmenter starts a call from audio onset. `_last_voice_epoch` and
|
||||||
|
`_voice_onset_epoch` are the whole interface: metadata_watcher polls them via
|
||||||
|
audio_activity() and owns every decision about segment boundaries. This module
|
||||||
|
deliberately does not open or close calls by itself — attribution (which
|
||||||
|
talkgroup this audio belongs to) lives in the watcher, and audio alone cannot
|
||||||
|
answer it.
|
||||||
|
|
||||||
Why not Icecast: it lags ~1 s at connect and drifts progressively to 100 s+, so
|
Why not Icecast: it lags ~1 s at connect and drifts progressively to 100 s+, so
|
||||||
slice timestamps and audio content diverge without bound. Icecast stays in the
|
slice timestamps and audio content diverge without bound. Icecast stays in the
|
||||||
stack for frontend/mobile live listening; it is not an accuracy path.
|
stack for frontend/mobile live listening; it is not an accuracy path.
|
||||||
@@ -31,6 +49,12 @@ the same clock and the pre-roll arithmetic below is a direct subtraction with no
|
|||||||
offset mapping. (A wall-clock STEP — e.g. a large NTP correction — would corrupt
|
offset mapping. (A wall-clock STEP — e.g. a large NTP correction — would corrupt
|
||||||
at most the calls in flight at that instant; the buffer self-heals within
|
at most the calls in flight at that instant; the buffer self-heals within
|
||||||
RING_BUFFER_SECONDS.)
|
RING_BUFFER_SECONDS.)
|
||||||
|
|
||||||
|
NOTE on what a chunk timestamp means: it is the ARRIVAL time of that audio at
|
||||||
|
this process, which lags the moment the words were spoken by the PulseAudio →
|
||||||
|
FFmpeg → pipe latency. Every timestamp this module produces is in that same
|
||||||
|
arrival clock, so differences between them are exact; only comparisons against
|
||||||
|
OP25's control-channel timestamps carry the lag, and those are padded for it.
|
||||||
"""
|
"""
|
||||||
import asyncio
|
import asyncio
|
||||||
import time
|
import time
|
||||||
@@ -42,57 +66,72 @@ from typing import List, Optional, Tuple
|
|||||||
|
|
||||||
import httpx
|
import httpx
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
from app.internal import audio_trim, credentials, pulse
|
from app.internal import audio_trim, credentials, pcm, pulse
|
||||||
from app.internal.logger import logger
|
from app.internal.logger import logger
|
||||||
|
|
||||||
# Safety cap on a single recording; mirrors MAX_SEGMENT_SECONDS in metadata_watcher.
|
# Safety cap on a single recording; mirrors MAX_SEGMENT_SECONDS in metadata_watcher.
|
||||||
MAX_RECORDING_SECONDS = 600
|
MAX_RECORDING_SECONDS = 600
|
||||||
|
|
||||||
# Audio included ahead of OP25's call_log timestamp. The grant is logged when the
|
# Audio included ahead of the detected voice onset.
|
||||||
# channel is granted, so the first syllable can land marginally before it.
|
|
||||||
#
|
#
|
||||||
# Kept small on purpose: measurement on a live node shows 1.71–2.45 s of real
|
# Under audio-driven segmentation this is no longer covering a variable
|
||||||
# grant→speech delay on every call, so there is no clipping risk at the head and
|
# control-channel offset — it covers exactly two things: the analysis chunk
|
||||||
# a larger pre-roll would only add dead air.
|
# quantisation (~46 ms) and the possibility that the first syllable ramps up
|
||||||
|
# through the silence threshold rather than crossing it instantly. 0.25 s is
|
||||||
|
# generous for both, and anything it drags in that is genuinely silence gets
|
||||||
|
# trimmed off again before upload.
|
||||||
PRE_ROLL_SECONDS = 0.25
|
PRE_ROLL_SECONDS = 0.25
|
||||||
|
|
||||||
# Rolling history kept for PRE-ROLL ONLY. Budget for the worst realistic
|
# Rolling history kept for PRE-ROLL ONLY. Budget for the worst realistic
|
||||||
# detection latency: 0.5 s poll interval + ~0.2 s http_server blocking floor +
|
# detection latency: the segmenter polls every 0.5 s and can stall for up to a
|
||||||
# up to 3 s httpx timeout on a stalled poll + callback work ≈ 4 s from grant to
|
# 3 s httpx timeout on a bad OP25 poll, so ~4 s from onset to start_recording().
|
||||||
# start_recording(). 30 s is ~7x that margin, and at 16 kbps costs only ~60 KB of
|
# 30 s is ~7x that margin. At 44.1 KB/s of PCM it costs ~1.3 MB of RAM. This
|
||||||
# RAM. This value does NOT bound call length — the accumulator does.
|
# value does NOT bound call length — the accumulator does.
|
||||||
RING_BUFFER_SECONDS = 30
|
RING_BUFFER_SECONDS = 30
|
||||||
|
|
||||||
# ~128 ms of audio per chunk at 16 kbps. Chunk size IS the timestamp resolution of
|
# ~46 ms of audio per chunk. Chunk size is BOTH the timestamp resolution of the
|
||||||
# the ring buffer, so it must stay well under PRE_ROLL_SECONDS — the old 4096-byte
|
# ring buffer AND the window silence detection runs over, so it has to stay well
|
||||||
# reads were ~2 s per chunk, which made sub-second slicing meaningless.
|
# under PRE_ROLL_SECONDS and well under the shortest utterance we care about.
|
||||||
READ_CHUNK_BYTES = 256
|
READ_CHUNK_BYTES = 2048
|
||||||
|
|
||||||
# Encoder settings, matched on purpose to what Liquidsoap already pushes to
|
# Encoder settings for the single encode at save time, matched on purpose to
|
||||||
# Icecast — %mp3(bitrate=16, samplerate=22050, stereo=false) — so the C2 /upload
|
# what Liquidsoap already pushes to Icecast — %mp3(bitrate=16, samplerate=22050,
|
||||||
# endpoint keeps receiving exactly the kind of MP3 it has always received
|
# stereo=false) — so the C2 /upload endpoint keeps receiving exactly the kind of
|
||||||
# (multipart "audio/mpeg", stored to GCS as .mp3, then fed to Whisper).
|
# MP3 it has always received (multipart "audio/mpeg", stored to GCS as .mp3,
|
||||||
# Change both of these together if you ever want higher-fidelity uploads.
|
# then fed to Whisper). MP3_SAMPLE_RATE MUST equal pcm.SAMPLE_RATE: the encode
|
||||||
|
# is a straight pass with no resampling.
|
||||||
MP3_BITRATE = "16k"
|
MP3_BITRATE = "16k"
|
||||||
MP3_SAMPLE_RATE = "22050"
|
MP3_SAMPLE_RATE = str(pcm.SAMPLE_RATE)
|
||||||
|
|
||||||
# Hard memory ceiling for one call's accumulator. 16 kbps is 2 KB/s, so 600 s of
|
# Bounded so a wedged encoder can never stall the upload path.
|
||||||
# call is ~1.2 MB; 4x that is the ceiling, which both leaves room for encoder
|
ENCODE_TIMEOUT_SECONDS = 60.0
|
||||||
# overshoot and guarantees a runaway call can never eat a Pi's RAM.
|
|
||||||
_MP3_BYTES_PER_SECOND = 16_000 // 8
|
# Hard memory ceiling for one call's accumulator.
|
||||||
MAX_RECORDING_BYTES = MAX_RECORDING_SECONDS * _MP3_BYTES_PER_SECOND * 4
|
#
|
||||||
|
# PCM costs 44.1 KB/s where the old MP3 buffer cost 2 KB/s, so this had to be
|
||||||
|
# re-derived rather than carried over. 600 s (the time cap) of PCM is 26.5 MB;
|
||||||
|
# 32 MiB is ~761 s, which guarantees the TIME cap always bites first and a legal
|
||||||
|
# call is never truncated by the byte cap. Peak resident audio is therefore
|
||||||
|
# ~33.5 MB for the accumulator plus ~1.3 MB for the ring buffer.
|
||||||
|
#
|
||||||
|
# Rejected alternatives, for the record: spilling to disk (SD-card wear on a Pi,
|
||||||
|
# and I/O in the close path); encoding incrementally into MP3 as chunks arrive
|
||||||
|
# (puts a subprocess back in the hot path and makes the sample-accurate post-hoc
|
||||||
|
# trim impossible); a lower capture sample rate (changes what Whisper receives).
|
||||||
|
MAX_RECORDING_BYTES = 32 * 1024 * 1024
|
||||||
|
|
||||||
# How long stop_recording() will wait for captured audio to actually reach the
|
# How long stop_recording() will wait for captured audio to actually reach the
|
||||||
# call's end timestamp. PulseAudio → FFmpeg → MP3 encoder → muxer → our pipe read
|
# call's end timestamp. PulseAudio → FFmpeg → our pipe read is a pipeline with
|
||||||
# is a pipeline with latency, so at the instant a call ends the newest buffered
|
# latency, so at the instant a CONTROL-CHANNEL derived end is computed the
|
||||||
# chunk is typically a few hundred ms OLDER than the end epoch. Slicing
|
# newest buffered chunk is typically a few hundred ms OLDER than that epoch.
|
||||||
# immediately therefore cuts the tail short — which costs the last word of the
|
# Slicing immediately therefore cuts the tail short — which costs the last word
|
||||||
# transmission, usually the disposition or the address. Bounded so a dead capture
|
# of the transmission, usually the disposition or the address.
|
||||||
# can never hang the upload path.
|
|
||||||
#
|
#
|
||||||
# Must exceed settings.call_tail_pad_seconds (default 3.0), otherwise a
|
# An audio-driven close never needs this (its end epoch is derived from audio
|
||||||
# tgid_change close — which pads past a timestamp that is still ~now — gives up
|
# that is already buffered, by construction), but a tgid_change close still
|
||||||
# before the padded audio has been captured and warns on every talkgroup switch.
|
# pads past a control-channel timestamp that is ~now, so the wait must exceed
|
||||||
|
# settings.call_tail_pad_seconds (default 3.0) or it would warn on every
|
||||||
|
# talkgroup switch. Bounded so a dead capture can never hang the upload path.
|
||||||
TAIL_WAIT_TIMEOUT_SECONDS = 4.0
|
TAIL_WAIT_TIMEOUT_SECONDS = 4.0
|
||||||
TAIL_WAIT_POLL_SECONDS = 0.05
|
TAIL_WAIT_POLL_SECONDS = 0.05
|
||||||
|
|
||||||
@@ -114,12 +153,38 @@ _SOURCE_MISSING_MARKERS = ("no such process", "no such device")
|
|||||||
_NO_DAEMON_MARKERS = ("connection refused", "connection failure")
|
_NO_DAEMON_MARKERS = ("connection refused", "connection failure")
|
||||||
|
|
||||||
|
|
||||||
|
@dataclass(frozen=True)
|
||||||
|
class AudioActivity:
|
||||||
|
"""
|
||||||
|
What the capture stream is doing right now, as raw facts.
|
||||||
|
|
||||||
|
Deliberately carries no decision — no "should a call be open" boolean —
|
||||||
|
because every threshold comparison belongs to metadata_watcher, which owns
|
||||||
|
the segment state machine and (in tests) an injectable clock. This is a
|
||||||
|
snapshot of observations, nothing more.
|
||||||
|
|
||||||
|
`voice_onset_epoch` is the arrival timestamp of the first chunk of the most
|
||||||
|
recent run of voice. It is NOT cleared when that run ends, so a caller must
|
||||||
|
check `last_voice_epoch` against its own clock before treating the run as
|
||||||
|
live. That is intentional: the segmenter needs the onset of the run it just
|
||||||
|
finished recording in order to avoid re-opening on the same run.
|
||||||
|
"""
|
||||||
|
|
||||||
|
capturing: bool
|
||||||
|
recording: bool
|
||||||
|
last_voice_epoch: Optional[float] = None
|
||||||
|
voice_onset_epoch: Optional[float] = None
|
||||||
|
# Convenience for /api/status only; the segmenter recomputes this against
|
||||||
|
# its own clock.
|
||||||
|
silence_seconds: float = 0.0
|
||||||
|
|
||||||
|
|
||||||
@dataclass
|
@dataclass
|
||||||
class _ActiveRecording:
|
class _ActiveRecording:
|
||||||
"""Audio accumulating for the call currently being recorded."""
|
"""Audio accumulating for the call currently being recorded."""
|
||||||
|
|
||||||
call_id: str
|
call_id: str
|
||||||
call_start: float # OP25 grant epoch
|
call_start: float # detected voice onset (or a caller-supplied epoch)
|
||||||
slice_start: float # call_start - PRE_ROLL_SECONDS
|
slice_start: float # call_start - PRE_ROLL_SECONDS
|
||||||
chunks: List[Tuple[float, bytes]] = field(default_factory=list)
|
chunks: List[Tuple[float, bytes]] = field(default_factory=list)
|
||||||
total_bytes: int = 0
|
total_bytes: int = 0
|
||||||
@@ -140,7 +205,7 @@ class Recording:
|
|||||||
|
|
||||||
wall_clock_of(audio_offset_t) == audio_start_epoch + t
|
wall_clock_of(audio_offset_t) == audio_start_epoch + t
|
||||||
|
|
||||||
Bounds are accurate to ±one capture chunk (~128 ms).
|
Bounds are accurate to ±one capture chunk (~46 ms).
|
||||||
"""
|
"""
|
||||||
|
|
||||||
call_id: str
|
call_id: str
|
||||||
@@ -153,13 +218,66 @@ class Recording:
|
|||||||
all_silence: bool = False
|
all_silence: bool = False
|
||||||
|
|
||||||
|
|
||||||
|
async def encode_mp3(audio: bytes, path: Path) -> bool:
|
||||||
|
"""
|
||||||
|
The one and only encode in the pipeline: raw PCM in, MP3 file out.
|
||||||
|
|
||||||
|
Module-level rather than a method so tests can substitute it without
|
||||||
|
needing FFmpeg, and so the "exactly one encode per call" property is
|
||||||
|
trivially observable.
|
||||||
|
"""
|
||||||
|
if not audio:
|
||||||
|
return False
|
||||||
|
cmd = [
|
||||||
|
"ffmpeg",
|
||||||
|
"-hide_banner", "-nostdin", "-nostats",
|
||||||
|
"-loglevel", "warning", "-y",
|
||||||
|
"-f", "s16le",
|
||||||
|
"-ar", MP3_SAMPLE_RATE,
|
||||||
|
"-ac", str(pcm.CHANNELS),
|
||||||
|
"-i", "pipe:0",
|
||||||
|
"-ar", MP3_SAMPLE_RATE,
|
||||||
|
"-ac", str(pcm.CHANNELS),
|
||||||
|
"-b:a", MP3_BITRATE,
|
||||||
|
"-f", "mp3", str(path),
|
||||||
|
]
|
||||||
|
try:
|
||||||
|
proc = await asyncio.create_subprocess_exec(
|
||||||
|
*cmd,
|
||||||
|
stdin=asyncio.subprocess.PIPE,
|
||||||
|
stdout=asyncio.subprocess.DEVNULL,
|
||||||
|
stderr=asyncio.subprocess.PIPE,
|
||||||
|
)
|
||||||
|
except Exception as e:
|
||||||
|
logger.error(f"Could not launch the MP3 encoder ({e}) — recording not saved.")
|
||||||
|
return False
|
||||||
|
|
||||||
|
try:
|
||||||
|
_, stderr = await asyncio.wait_for(proc.communicate(audio), timeout=ENCODE_TIMEOUT_SECONDS)
|
||||||
|
except asyncio.TimeoutError:
|
||||||
|
try:
|
||||||
|
proc.kill()
|
||||||
|
except Exception:
|
||||||
|
pass
|
||||||
|
logger.error(f"MP3 encode timed out after {ENCODE_TIMEOUT_SECONDS:.0f}s — recording not saved.")
|
||||||
|
return False
|
||||||
|
except Exception as e:
|
||||||
|
logger.error(f"MP3 encode failed ({e}) — recording not saved.")
|
||||||
|
return False
|
||||||
|
|
||||||
|
if proc.returncode != 0:
|
||||||
|
logger.error(f"MP3 encode exited {proc.returncode}: {stderr.decode(errors='replace').strip()}")
|
||||||
|
return False
|
||||||
|
return True
|
||||||
|
|
||||||
|
|
||||||
class CallRecorder:
|
class CallRecorder:
|
||||||
"""Continuous PulseAudio capture: ring buffer for pre-roll, accumulator per call."""
|
"""Continuous PulseAudio capture: ring buffer for pre-roll, accumulator per call."""
|
||||||
|
|
||||||
def __init__(self):
|
def __init__(self):
|
||||||
self._recordings_dir = Path(settings.recordings_path)
|
self._recordings_dir = Path(settings.recordings_path)
|
||||||
|
|
||||||
# Ring buffer: deque of (wall_clock_epoch_at_arrival, mp3_bytes).
|
# Ring buffer: deque of (wall_clock_epoch_at_arrival, pcm_bytes).
|
||||||
# Pre-roll only — see the module docstring.
|
# Pre-roll only — see the module docstring.
|
||||||
self._buffer: deque[Tuple[float, bytes]] = deque()
|
self._buffer: deque[Tuple[float, bytes]] = deque()
|
||||||
self._buffer_bytes: int = 0
|
self._buffer_bytes: int = 0
|
||||||
@@ -168,6 +286,10 @@ class CallRecorder:
|
|||||||
self._proc: Optional[asyncio.subprocess.Process] = None
|
self._proc: Optional[asyncio.subprocess.Process] = None
|
||||||
self._capturing: bool = False
|
self._capturing: bool = False
|
||||||
|
|
||||||
|
# Voice activity, tracked continuously — not only while recording.
|
||||||
|
self._last_voice_epoch: Optional[float] = None
|
||||||
|
self._voice_onset_epoch: Optional[float] = None
|
||||||
|
|
||||||
# Active recording state (None when idle)
|
# Active recording state (None when idle)
|
||||||
self._active: Optional[_ActiveRecording] = None
|
self._active: Optional[_ActiveRecording] = None
|
||||||
|
|
||||||
@@ -204,14 +326,12 @@ class CallRecorder:
|
|||||||
"-hide_banner", "-nostdin", "-nostats",
|
"-hide_banner", "-nostdin", "-nostats",
|
||||||
"-loglevel", "warning",
|
"-loglevel", "warning",
|
||||||
"-f", "pulse", "-i", settings.pulse_source,
|
"-f", "pulse", "-i", settings.pulse_source,
|
||||||
"-ac", "1",
|
"-ac", str(pcm.CHANNELS),
|
||||||
"-ar", MP3_SAMPLE_RATE,
|
"-ar", MP3_SAMPLE_RATE,
|
||||||
"-b:a", MP3_BITRATE,
|
# Raw PCM on stdout. No muxer, so no -flush_packets games: s16le is
|
||||||
# Without this, the MP3 muxer fills its 32 KB AVIO buffer before
|
# a bare byte stream and every byte FFmpeg produces is immediately
|
||||||
# writing anything — 16 s of audio per burst at 16 kbps, which would
|
# readable, which is what keeps arrival timestamps honest.
|
||||||
# destroy the arrival timestamps the slicing depends on.
|
"-f", "s16le", "-",
|
||||||
"-flush_packets", "1",
|
|
||||||
"-f", "mp3", "-",
|
|
||||||
]
|
]
|
||||||
|
|
||||||
async def _capture_loop(self) -> None:
|
async def _capture_loop(self) -> None:
|
||||||
@@ -240,7 +360,7 @@ class CallRecorder:
|
|||||||
|
|
||||||
async def _run_capture(self) -> None:
|
async def _run_capture(self) -> None:
|
||||||
cmd = self._ffmpeg_command()
|
cmd = self._ffmpeg_command()
|
||||||
logger.info(f"Starting capture: ffmpeg -f pulse -i {settings.pulse_source}")
|
logger.info(f"Starting capture: ffmpeg -f pulse -i {settings.pulse_source} (s16le/{MP3_SAMPLE_RATE}/mono)")
|
||||||
self._last_stderr_lines.clear()
|
self._last_stderr_lines.clear()
|
||||||
proc = await asyncio.create_subprocess_exec(
|
proc = await asyncio.create_subprocess_exec(
|
||||||
*cmd,
|
*cmd,
|
||||||
@@ -252,8 +372,14 @@ class CallRecorder:
|
|||||||
try:
|
try:
|
||||||
assert proc.stdout is not None
|
assert proc.stdout is not None
|
||||||
while True:
|
while True:
|
||||||
chunk = await proc.stdout.read(READ_CHUNK_BYTES)
|
# readexactly, not read: a fixed chunk keeps every analysis
|
||||||
if not chunk:
|
# window the same length AND guarantees sample alignment, so a
|
||||||
|
# short read can never split a 16-bit sample across chunks.
|
||||||
|
try:
|
||||||
|
chunk = await proc.stdout.readexactly(READ_CHUNK_BYTES)
|
||||||
|
except asyncio.IncompleteReadError as partial:
|
||||||
|
if partial.partial:
|
||||||
|
self._ingest(partial.partial)
|
||||||
break # EOF — FFmpeg died or the source went away
|
break # EOF — FFmpeg died or the source went away
|
||||||
if not self._capturing:
|
if not self._capturing:
|
||||||
self._capturing = True
|
self._capturing = True
|
||||||
@@ -339,9 +465,44 @@ class CallRecorder:
|
|||||||
except Exception:
|
except Exception:
|
||||||
pass
|
pass
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# Voice activity
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
|
def _note_voice(self, chunk: bytes, now: float) -> None:
|
||||||
|
"""
|
||||||
|
Update the continuous voice-activity marks from one arriving chunk.
|
||||||
|
|
||||||
|
A chunk carrying signal starts a NEW run whenever the gap since the last
|
||||||
|
one is at least the configured silence timeout — i.e. runs are separated
|
||||||
|
by exactly the same threshold that ends a recording, so the segmenter's
|
||||||
|
"did a new run begin" and "did the recording end" questions can never
|
||||||
|
disagree with each other.
|
||||||
|
"""
|
||||||
|
if pcm.is_silent(chunk, settings.call_silence_threshold_db):
|
||||||
|
return
|
||||||
|
gap = settings.call_silence_timeout
|
||||||
|
if self._last_voice_epoch is None or (now - self._last_voice_epoch) >= gap:
|
||||||
|
self._voice_onset_epoch = now
|
||||||
|
self._last_voice_epoch = now
|
||||||
|
|
||||||
|
def audio_activity(self) -> AudioActivity:
|
||||||
|
"""Snapshot of the capture stream for metadata_watcher (and /api/status)."""
|
||||||
|
last = self._last_voice_epoch
|
||||||
|
silence = (time.time() - last) if last is not None else 0.0
|
||||||
|
return AudioActivity(
|
||||||
|
capturing=self._capturing,
|
||||||
|
recording=self._active is not None,
|
||||||
|
last_voice_epoch=last,
|
||||||
|
voice_onset_epoch=self._voice_onset_epoch,
|
||||||
|
silence_seconds=max(0.0, silence),
|
||||||
|
)
|
||||||
|
|
||||||
def _ingest(self, chunk: bytes) -> None:
|
def _ingest(self, chunk: bytes) -> None:
|
||||||
"""Append a chunk to the ring buffer and, if recording, the accumulator."""
|
"""Append a chunk to the ring buffer and, if recording, the accumulator."""
|
||||||
now = time.time()
|
now = time.time()
|
||||||
|
self._note_voice(chunk, now)
|
||||||
|
|
||||||
self._buffer.append((now, chunk))
|
self._buffer.append((now, chunk))
|
||||||
self._buffer_bytes += len(chunk)
|
self._buffer_bytes += len(chunk)
|
||||||
|
|
||||||
@@ -375,9 +536,10 @@ class CallRecorder:
|
|||||||
|
|
||||||
async def start_recording(self, call_id: str, start_epoch: Optional[float] = None) -> bool:
|
async def start_recording(self, call_id: str, start_epoch: Optional[float] = None) -> bool:
|
||||||
"""
|
"""
|
||||||
Open a recording. `start_epoch` is OP25's call_log timestamp (host wall
|
Open a recording. `start_epoch` is the detected voice onset (host wall
|
||||||
clock); the slice begins PRE_ROLL_SECONDS before it. Omit it only when no
|
clock, same clock as the chunk stamps); the slice begins
|
||||||
OP25 timestamp is available — then we fall back to "now", losing precision.
|
PRE_ROLL_SECONDS before it. Omit it only when no onset is available —
|
||||||
|
then we fall back to "now", losing the pre-roll's precision.
|
||||||
"""
|
"""
|
||||||
if self._active is not None:
|
if self._active is not None:
|
||||||
logger.warning(f"Recording already active ({self._active.call_id}) — ignoring start for {call_id}.")
|
logger.warning(f"Recording already active ({self._active.call_id}) — ignoring start for {call_id}.")
|
||||||
@@ -396,8 +558,8 @@ class CallRecorder:
|
|||||||
oldest = self._buffer[0][0] if self._buffer else None
|
oldest = self._buffer[0][0] if self._buffer else None
|
||||||
if oldest is not None and slice_start < oldest:
|
if oldest is not None and slice_start < oldest:
|
||||||
# Pre-roll predates the buffer: node just started, capture restarted,
|
# Pre-roll predates the buffer: node just started, capture restarted,
|
||||||
# or OP25's timestamp is far in the past. Clamp and say so LOUDLY —
|
# or the onset is far in the past. Clamp and say so LOUDLY — this is
|
||||||
# this is silent audio loss otherwise.
|
# silent audio loss otherwise.
|
||||||
clamped = oldest - slice_start
|
clamped = oldest - slice_start
|
||||||
logger.warning(
|
logger.warning(
|
||||||
f"BUFFER CLAMP: pre-roll for call {call_id} predates buffered audio by "
|
f"BUFFER CLAMP: pre-roll for call {call_id} predates buffered audio by "
|
||||||
@@ -417,13 +579,28 @@ class CallRecorder:
|
|||||||
logger.info(f"Recording started: {call_id} (slice from {slice_start:.3f})")
|
logger.info(f"Recording started: {call_id} (slice from {slice_start:.3f})")
|
||||||
return True
|
return True
|
||||||
|
|
||||||
|
async def discard_recording(self) -> None:
|
||||||
|
"""
|
||||||
|
Drop the open recording without writing anything.
|
||||||
|
|
||||||
|
Used when the segmenter decides the audio must not be kept — today only
|
||||||
|
the unattributed/orphan-audio path, where uploading would inject a call
|
||||||
|
with no talkgroup into correlation.
|
||||||
|
"""
|
||||||
|
active, self._active = self._active, None
|
||||||
|
if active is not None:
|
||||||
|
logger.info(f"Discarded buffered audio for {active.call_id} ({active.total_bytes} bytes).")
|
||||||
|
|
||||||
async def stop_recording(self, end_epoch: Optional[float] = None) -> Optional[Recording]:
|
async def stop_recording(self, end_epoch: Optional[float] = None) -> Optional[Recording]:
|
||||||
"""
|
"""
|
||||||
Close the recording and write the file. `end_epoch` is host wall clock.
|
Close the recording, trim it, encode it once and write the file.
|
||||||
|
`end_epoch` is host wall clock.
|
||||||
|
|
||||||
Waits (bounded) for captured audio to actually cover `end_epoch` before
|
Waits (bounded) for captured audio to actually cover `end_epoch` before
|
||||||
slicing — see TAIL_WAIT_TIMEOUT_SECONDS. Returns None only when there was
|
slicing — see TAIL_WAIT_TIMEOUT_SECONDS. An audio-driven close never
|
||||||
no recording open or no audio at all.
|
needs that wait, because its end epoch is derived from audio that is
|
||||||
|
already buffered; a control-channel-derived close (tgid_change) does.
|
||||||
|
Returns None only when there was no recording open or no audio at all.
|
||||||
"""
|
"""
|
||||||
active = self._active
|
active = self._active
|
||||||
if active is None:
|
if active is None:
|
||||||
@@ -439,19 +616,21 @@ class CallRecorder:
|
|||||||
await self._await_tail(end, call_id)
|
await self._await_tail(end, call_id)
|
||||||
self._active = None
|
self._active = None
|
||||||
|
|
||||||
chunks: List[bytes] = []
|
parts: List[bytes] = []
|
||||||
|
total = 0
|
||||||
last_ts = slice_start
|
last_ts = slice_start
|
||||||
for ts, chunk in active.chunks:
|
for ts, chunk in active.chunks:
|
||||||
if ts < slice_start:
|
if ts < slice_start:
|
||||||
continue
|
continue
|
||||||
chunks.append(chunk)
|
parts.append(chunk)
|
||||||
|
total += len(chunk)
|
||||||
last_ts = ts
|
last_ts = ts
|
||||||
if ts >= end:
|
if ts >= end:
|
||||||
# Include the chunk straddling `end` so the tail is never clipped,
|
# Include the chunk straddling `end` so the tail is never clipped,
|
||||||
# then stop.
|
# then stop.
|
||||||
break
|
break
|
||||||
|
|
||||||
if not chunks:
|
if not parts:
|
||||||
logger.warning(
|
logger.warning(
|
||||||
f"No buffered audio for call {call_id} "
|
f"No buffered audio for call {call_id} "
|
||||||
f"(window {slice_start:.3f}–{end:.3f}) — PulseAudio capture may be down."
|
f"(window {slice_start:.3f}–{end:.3f}) — PulseAudio capture may be down."
|
||||||
@@ -464,29 +643,55 @@ class CallRecorder:
|
|||||||
"audio — the tail is short. Capture may be stalled or restarting."
|
"audio — the tail is short. Capture may be stalled or restarting."
|
||||||
)
|
)
|
||||||
|
|
||||||
self._recordings_dir.mkdir(parents=True, exist_ok=True)
|
raw = b"".join(parts)
|
||||||
ts_str = datetime.now(timezone.utc).strftime("%Y%m%d_%H%M%S")
|
|
||||||
output_path = self._recordings_dir / f"{ts_str}_{call_id}.mp3"
|
|
||||||
|
|
||||||
output_path.write_bytes(b"".join(chunks))
|
|
||||||
|
|
||||||
size = output_path.stat().st_size
|
|
||||||
if size <= 0:
|
|
||||||
output_path.unlink(missing_ok=True)
|
|
||||||
logger.warning(f"Recording for call {call_id} produced an empty file.")
|
|
||||||
return None
|
|
||||||
|
|
||||||
audio_end = min(end, last_ts)
|
|
||||||
logger.info(f"Recording saved: {output_path.name} ({size} bytes, {audio_end - slice_start:.2f}s window)")
|
|
||||||
|
|
||||||
recording = Recording(
|
recording = Recording(
|
||||||
call_id=call_id,
|
call_id=call_id,
|
||||||
path=output_path,
|
path=None,
|
||||||
audio_start_epoch=slice_start,
|
audio_start_epoch=slice_start,
|
||||||
audio_end_epoch=audio_end,
|
audio_end_epoch=slice_start + pcm.seconds(len(raw)),
|
||||||
clamped_seconds=active.clamped_seconds,
|
clamped_seconds=active.clamped_seconds,
|
||||||
)
|
)
|
||||||
return await self._apply_trim(recording)
|
return await self._finish(recording, raw)
|
||||||
|
|
||||||
|
async def _finish(self, recording: Recording, raw: bytes) -> Optional[Recording]:
|
||||||
|
"""Trim, encode exactly once, and write the MP3."""
|
||||||
|
audio = raw
|
||||||
|
if settings.trim_silence:
|
||||||
|
audio, result = audio_trim.trim_pcm(audio)
|
||||||
|
if result.all_silence:
|
||||||
|
logger.warning(
|
||||||
|
f"Call {recording.call_id} contains no speech at all — skipping upload. "
|
||||||
|
"Check squelch, the Liquidsoap output and the drb_sink monitor."
|
||||||
|
)
|
||||||
|
recording.all_silence = True
|
||||||
|
return recording
|
||||||
|
if result.applied:
|
||||||
|
recording.lead_trimmed = result.lead
|
||||||
|
recording.tail_trimmed = result.tail
|
||||||
|
# Wall clock of the trimmed audio's first and last sample.
|
||||||
|
recording.audio_start_epoch += result.lead
|
||||||
|
recording.audio_end_epoch -= result.tail
|
||||||
|
|
||||||
|
self._recordings_dir.mkdir(parents=True, exist_ok=True)
|
||||||
|
ts_str = datetime.now(timezone.utc).strftime("%Y%m%d_%H%M%S")
|
||||||
|
output_path = self._recordings_dir / f"{ts_str}_{recording.call_id}.mp3"
|
||||||
|
|
||||||
|
if not await encode_mp3(audio, output_path):
|
||||||
|
output_path.unlink(missing_ok=True)
|
||||||
|
return None
|
||||||
|
|
||||||
|
size = output_path.stat().st_size if output_path.exists() else 0
|
||||||
|
if size <= 0:
|
||||||
|
output_path.unlink(missing_ok=True)
|
||||||
|
logger.warning(f"Recording for call {recording.call_id} produced an empty file.")
|
||||||
|
return None
|
||||||
|
|
||||||
|
recording.path = output_path
|
||||||
|
logger.info(
|
||||||
|
f"Recording saved: {output_path.name} ({size} bytes, "
|
||||||
|
f"{pcm.seconds(len(audio)):.2f}s audio)"
|
||||||
|
)
|
||||||
|
return recording
|
||||||
|
|
||||||
async def _await_tail(self, end: float, call_id: str) -> float:
|
async def _await_tail(self, end: float, call_id: str) -> float:
|
||||||
"""
|
"""
|
||||||
@@ -519,41 +724,6 @@ class CallRecorder:
|
|||||||
)
|
)
|
||||||
return waited
|
return waited
|
||||||
|
|
||||||
async def _apply_trim(self, recording: Recording) -> Recording:
|
|
||||||
"""
|
|
||||||
Strip leading/trailing dead air and keep the timing metadata honest.
|
|
||||||
|
|
||||||
An all-silence recording is NOT uploaded: it carries no information and
|
|
||||||
silence is exactly what makes Whisper hallucinate. It is logged instead,
|
|
||||||
because it also means something is wrong with the audio path.
|
|
||||||
"""
|
|
||||||
if not settings.trim_silence or recording.path is None:
|
|
||||||
return recording
|
|
||||||
|
|
||||||
result = await audio_trim.trim_silence(
|
|
||||||
recording.path,
|
|
||||||
sample_rate=MP3_SAMPLE_RATE,
|
|
||||||
bitrate=MP3_BITRATE,
|
|
||||||
)
|
|
||||||
|
|
||||||
if result.all_silence:
|
|
||||||
logger.warning(
|
|
||||||
f"Call {recording.call_id} contains no speech at all — skipping upload. "
|
|
||||||
"Check squelch, the Liquidsoap output and the drb_sink monitor."
|
|
||||||
)
|
|
||||||
recording.path.unlink(missing_ok=True)
|
|
||||||
recording.path = None
|
|
||||||
recording.all_silence = True
|
|
||||||
return recording
|
|
||||||
|
|
||||||
if result.applied:
|
|
||||||
recording.lead_trimmed = result.lead
|
|
||||||
recording.tail_trimmed = result.tail
|
|
||||||
# Wall clock of the trimmed audio's first and last sample.
|
|
||||||
recording.audio_start_epoch += result.lead
|
|
||||||
recording.audio_end_epoch -= result.tail
|
|
||||||
return recording
|
|
||||||
|
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
# Upload (unchanged interface)
|
# Upload (unchanged interface)
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
|
|||||||
@@ -1,81 +1,160 @@
|
|||||||
"""
|
"""
|
||||||
Event-driven call state machine.
|
Call segmentation: AUDIO decides the boundaries, the CONSOLE decides the label.
|
||||||
|
|
||||||
Replaces the old hang-counter inference (which derived call start from "a tgid
|
START first chunk of audio above the silence threshold (voice onset).
|
||||||
appeared in channel_update" and call end from N polls of silence) with the two
|
STOP settings.call_silence_timeout seconds of continuous silence HEARD in
|
||||||
authoritative signals OP25 actually exposes:
|
that audio.
|
||||||
|
LABEL talkgroup / alias / rid, resolved from OP25 console observations that
|
||||||
|
fall inside the recording's window, resolved AT CLOSE TIME.
|
||||||
|
SPLIT a console talkgroup change still forces a cut, even mid-audio.
|
||||||
|
|
||||||
START — a `call_log` entry. OP25 appends one at channel-grant time stamped with
|
WHY THE CONTROL CHANNEL NO LONGER DECIDES BOUNDARIES. The previous design
|
||||||
its own time.time(). This is an exact start timestamp, not the moment
|
started a segment on an OP25 `call_log` grant and ended it by inferring from the
|
||||||
our poll happened to notice, so recordings can be sliced back to it.
|
control channel: the `srcaddr != 0 -> 0` edge started an idle timer and the
|
||||||
|
segment closed call_idle_timeout seconds later. Both halves were measured wrong
|
||||||
|
in the field:
|
||||||
|
|
||||||
END — the `srcaddr` != 0 → `srcaddr` == 0 transition in `channel_update`.
|
* The grant fires 0.84-1.62 s (variable) before anyone speaks, so a
|
||||||
OP25 never reports call termination externally: internally it ends a
|
grant-anchored window is always guessing at the offset.
|
||||||
call on the P25 Terminator Data Unit (duid15) or 3 voice-framing
|
* `srcaddr` can drop to 0 WHILE SOMEONE IS STILL TALKING. Measured across six
|
||||||
timeouts, but neither becomes a log entry. What *is* observable is that
|
recordings, five had healthy trailing silence trimmed (-0.53 s to -2.48 s)
|
||||||
`srcaddr`/`svcopts` reset to 0/false the instant the call ends, while
|
but one reported "-1.61s lead, -0.00s tail" — the trim found nothing to
|
||||||
`tgid`/`hold_tgid` keep showing the just-ended talkgroup for
|
remove because the capture window had closed on top of live speech. The
|
||||||
TGID_HOLD_TIME (2 s). So the srcaddr edge is a real state change, not a
|
recording ends on an unfinished word. Working backwards from its lead trim,
|
||||||
timeout heuristic.
|
the audio pipeline lag was at most 1.36 s, so the window should have held
|
||||||
|
~1.6 s more; the only consistent explanation is a false early `srcaddr -> 0`.
|
||||||
|
|
||||||
|
Audio is the ground truth for WHEN. It cannot answer WHO, so the console is
|
||||||
|
still the only source of talkgroup, alias and radio id.
|
||||||
|
|
||||||
|
WHY ATTRIBUTION HAPPENS AT CLOSE, NOT AT OPEN. There is no guaranteed ordering
|
||||||
|
between a grant and the audio it belongs to: the console is polled every 500 ms
|
||||||
|
and the audio pipeline lag is variable, so the grant can land after voice onset
|
||||||
|
just as easily as before it. A segment may therefore open unattributed and
|
||||||
|
acquire its talkgroup part-way through, which is expected and fine. At close we
|
||||||
|
have seen the whole window and ask the rolling console history "what was active
|
||||||
|
during this audio, give or take a few seconds" — see _attribute and the
|
||||||
|
ATTRIBUTION_* constants.
|
||||||
|
|
||||||
|
ORPHAN AUDIO. If nothing in the console history overlaps the window, the audio
|
||||||
|
is unattributed: Liquidsoap fallback, a test tone, stray noise, or a dropped
|
||||||
|
`call_log`. Policy is DISCARD AND SHOUT — the recording is not uploaded and no
|
||||||
|
call_start/call_end is published, because a call with no talkgroup silently
|
||||||
|
poisons incident correlation downstream, and that is worse than losing the
|
||||||
|
audio. It is logged at ERROR with the window and everything nearby that was
|
||||||
|
considered, and counted on /api/status so it cannot pass unnoticed.
|
||||||
|
|
||||||
|
FALLBACK MODE. When PulseAudio capture is NOT producing audio there is nothing
|
||||||
|
to segment on, so the old console state machine still runs (grant opens,
|
||||||
|
srcaddr edge + call_idle_timeout closes). It produces no audio — capture is
|
||||||
|
down — but it keeps the node reporting real radio activity to C2 while the
|
||||||
|
audio path is broken. This is the only remaining consumer of
|
||||||
|
settings.call_idle_timeout.
|
||||||
|
|
||||||
SEGMENTS: one emitted call (= one recording, one Firestore doc) spans a whole
|
SEGMENTS: one emitted call (= one recording, one Firestore doc) spans a whole
|
||||||
conversation, not a single transmission. It stays open across repeated grants on
|
conversation, not a single transmission. It stays open across repeated grants on
|
||||||
the same talkgroup and closes when the talkgroup changes or the radio goes quiet
|
the same talkgroup and closes when the talkgroup changes or the AUDIO goes quiet
|
||||||
for settings.call_idle_timeout seconds.
|
for settings.call_silence_timeout seconds.
|
||||||
|
|
||||||
CLOCKS: `call_log["time"]` is time.time() inside the op25 container. All three
|
CLOCKS: `call_log["time"]` is time.time() inside the op25 container. All three
|
||||||
client containers run network_mode: host and share the host kernel clock, so that
|
client containers run network_mode: host and share the host kernel clock, so that
|
||||||
value is directly comparable to time.time() here — no offset mapping needed. The
|
value is directly comparable to time.time() here — no offset mapping needed. The
|
||||||
call recorder's ring buffer is stamped with the same clock for the same reason.
|
call recorder's chunk timestamps are the same clock, with the caveat that they
|
||||||
|
are ARRIVAL times and therefore lag the moment of speech by the pipeline
|
||||||
|
latency. Comparisons between two audio timestamps are exact; comparisons between
|
||||||
|
audio and console timestamps carry that lag, which is what _tail_pad() covers.
|
||||||
"""
|
"""
|
||||||
import asyncio
|
import asyncio
|
||||||
import time
|
import time
|
||||||
import uuid
|
import uuid
|
||||||
|
from collections import deque
|
||||||
|
from dataclasses import dataclass, field
|
||||||
from datetime import datetime, timezone
|
from datetime import datetime, timezone
|
||||||
from typing import Optional, Callable, Awaitable, Any, List, Dict
|
from typing import Optional, Callable, Awaitable, Any, List, Dict
|
||||||
|
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
|
from app.internal.call_recorder import AudioActivity
|
||||||
from app.internal.op25_client import op25_client
|
from app.internal.op25_client import op25_client
|
||||||
from app.internal.logger import logger
|
from app.internal.logger import logger
|
||||||
|
|
||||||
CallbackFn = Callable[[dict], Awaitable[None]]
|
CallbackFn = Callable[[dict], Awaitable[None]]
|
||||||
|
ActivityFn = Callable[[], AudioActivity]
|
||||||
|
|
||||||
# 500 ms. Do NOT lower: start precision already comes from OP25's own timestamp,
|
# 500 ms. Do NOT lower: audio boundaries come from the recorder's own chunk
|
||||||
# and http_server.py's request handler has a ~200 ms blocking floor anyway.
|
# timestamps (~46 ms resolution), not from when this loop happens to notice
|
||||||
|
# them, and http_server.py's request handler has a ~200 ms blocking floor anyway.
|
||||||
POLL_INTERVAL = 0.5
|
POLL_INTERVAL = 0.5
|
||||||
|
|
||||||
# Seconds of unreachable OP25 before an open segment is force-closed.
|
# Seconds of unreachable OP25 before an open segment is force-closed. Applies in
|
||||||
|
# both modes: without the console there is no attribution, and unattributed
|
||||||
|
# audio is discarded anyway.
|
||||||
OP25_OFFLINE_GRACE = 3.0
|
OP25_OFFLINE_GRACE = 3.0
|
||||||
|
|
||||||
# Hard ceiling on a single segment; mirrors MAX_RECORDING_SECONDS in call_recorder
|
# Hard ceiling on a single segment; mirrors MAX_RECORDING_SECONDS in call_recorder
|
||||||
# so a talkgroup that never goes quiet cannot produce an unbounded recording.
|
# so a talkgroup that never goes quiet cannot produce an unbounded recording. In
|
||||||
|
# audio mode a new segment is opened immediately afterwards if voice is still
|
||||||
|
# present, so a genuinely long transmission is split rather than truncated.
|
||||||
MAX_SEGMENT_SECONDS = 600
|
MAX_SEGMENT_SECONDS = 600
|
||||||
|
|
||||||
|
# How far either side of the AUDIO window console observations are still
|
||||||
|
# accepted as attribution evidence. "Plus or minus some seconds", made explicit:
|
||||||
|
#
|
||||||
|
# LOOKBACK the grant normally PRECEDES the audio — 0.84-1.62 s of
|
||||||
|
# grant-to-speech delay, plus up to ~1.4 s of audio pipeline lag,
|
||||||
|
# plus one 0.5 s poll of detection slack. 4.0 s covers the worst
|
||||||
|
# case measured with margin.
|
||||||
|
# LOOKAHEAD the grant can also FOLLOW voice onset, because the console is only
|
||||||
|
# polled every 500 ms and OP25 logs the grant on its own schedule.
|
||||||
|
# 2.0 s is four poll intervals.
|
||||||
|
#
|
||||||
|
# Both are deliberately asymmetric: the "grant first" direction is the common
|
||||||
|
# one and has the larger physical spread.
|
||||||
|
ATTRIBUTION_LOOKBACK_SECONDS = 4.0
|
||||||
|
ATTRIBUTION_LOOKAHEAD_SECONDS = 2.0
|
||||||
|
|
||||||
|
# Rolling console history. Bounded twice — by age and by entry count — so a busy
|
||||||
|
# system cannot grow it without limit. At ~2 observations per poll this is a few
|
||||||
|
# minutes of history for a few tens of KB.
|
||||||
|
CONSOLE_HISTORY_SECONDS = 180.0
|
||||||
|
CONSOLE_HISTORY_MAX = 1200
|
||||||
|
|
||||||
|
# How far back to look for a duplicate before appending a grant. OP25's call_log
|
||||||
|
# deque drains on read so repeats should not happen, but a re-delivered entry
|
||||||
|
# would otherwise inflate the transmission count and the attribution score.
|
||||||
|
_GRANT_DEDUPE_DEPTH = 24
|
||||||
|
|
||||||
|
# Close reasons where the console explicitly told us the talkgroup changed, so
|
||||||
|
# the segment's label is already known first-hand and close-time attribution
|
||||||
|
# would only be able to make it worse (the window extends past the split).
|
||||||
|
_SPLIT_REASONS = ("tgid_change", "tgid_change_unlogged")
|
||||||
|
|
||||||
|
|
||||||
def _tail_pad() -> float:
|
def _tail_pad() -> float:
|
||||||
"""
|
"""
|
||||||
Audio kept after the observed end of the last transmission, so the srcaddr
|
Audio kept past a CONSOLE-DERIVED segment boundary, to cover the fact that
|
||||||
edge (up to one poll late) plus encoder latency never clips the tail.
|
buffered audio lags control-channel timestamps.
|
||||||
|
|
||||||
Read live from settings (env CALL_TAIL_PAD_SECONDS) rather than frozen into a
|
Under audio-driven segmentation this no longer applies to the normal end of
|
||||||
module constant, so it is tunable per node. See the setting in config.py for
|
a call — that boundary now comes from the audio itself and needs no pad. It
|
||||||
why the default moved 1.0 → 3.0 (short calls' recording window was closing
|
still applies wherever a boundary is a control-channel timestamp:
|
||||||
before the ~1.5s grant→speech offset let voice audio even start).
|
|
||||||
|
|
||||||
All three close paths use this pad: idle_timeout, tgid_change, and
|
tgid_change close at the new grant's timestamp + pad
|
||||||
tgid_change_unlogged. An earlier version of this docstring claimed the
|
tgid_change_unlogged close at the observing poll's timestamp + pad
|
||||||
latter two close at "an exact, already-known boundary" (the new grant's
|
idle_timeout console fallback mode only
|
||||||
timestamp, or the same poll tick) and so intentionally added no pad — THAT
|
|
||||||
|
Read live from settings (env CALL_TAIL_PAD_SECONDS) rather than frozen into
|
||||||
|
a module constant, so it is tunable per node.
|
||||||
|
|
||||||
|
An earlier version of this docstring claimed the tgid_change paths close at
|
||||||
|
"an exact, already-known boundary" and so intentionally added no pad — THAT
|
||||||
REASONING WAS WRONG and produced real truncated recordings. The boundary is
|
REASONING WAS WRONG and produced real truncated recordings. The boundary is
|
||||||
exact only in CONTROL-CHANNEL time; the buffered AUDIO lags control-channel
|
exact only in CONTROL-CHANNEL time; the buffered AUDIO lags control-channel
|
||||||
timestamps by ~1.5 s (measured: 0.84-1.62 s of lead trimmed across 7 field
|
timestamps by ~1.5 s (measured: 0.84-1.62 s of lead trimmed across 7 field
|
||||||
calls), so slicing the outgoing call at the new grant's exact timestamp cut
|
calls), so slicing the outgoing call at the new grant's exact timestamp cut
|
||||||
roughly the last 1.5s of its real speech — calls ending mid-word with ~0s
|
roughly the last 1.5 s of its real speech. Do not reintroduce a zero-pad
|
||||||
trailing silence. Do not reintroduce a zero-pad close for tgid_change or
|
close for tgid_change or tgid_change_unlogged; if the outgoing and incoming
|
||||||
tgid_change_unlogged; if the outgoing and incoming recordings end up
|
recordings end up overlapping in the underlying audio because of this pad,
|
||||||
overlapping in the underlying audio because of this pad, that is correct —
|
that is correct — the audio genuinely contains both.
|
||||||
the audio genuinely contains both. See _handle_call_log and
|
|
||||||
_handle_channels for how each path sources the timestamp this gets added to.
|
|
||||||
"""
|
"""
|
||||||
return settings.call_tail_pad_seconds
|
return settings.call_tail_pad_seconds
|
||||||
|
|
||||||
@@ -104,6 +183,35 @@ def _iso(epoch: Optional[float]) -> Optional[str]:
|
|||||||
return datetime.fromtimestamp(epoch, timezone.utc).isoformat()
|
return datetime.fromtimestamp(epoch, timezone.utc).isoformat()
|
||||||
|
|
||||||
|
|
||||||
|
@dataclass(frozen=True)
|
||||||
|
class ConsoleEvent:
|
||||||
|
"""One thing the OP25 console said, kept so a closing segment can ask about it."""
|
||||||
|
|
||||||
|
epoch: float
|
||||||
|
tgid: int
|
||||||
|
name: str = ""
|
||||||
|
freq: Any = None
|
||||||
|
rid: Optional[int] = None
|
||||||
|
# True for a `call_log` grant, False for an active `channel_update` row.
|
||||||
|
is_grant: bool = False
|
||||||
|
|
||||||
|
|
||||||
|
@dataclass
|
||||||
|
class Attribution:
|
||||||
|
"""Who a stretch of audio belonged to, and how confident we are."""
|
||||||
|
|
||||||
|
tgid: int
|
||||||
|
name: str = ""
|
||||||
|
freq: Any = None
|
||||||
|
rid: Optional[int] = None
|
||||||
|
grants: int = 0
|
||||||
|
# Observations that fall strictly inside the audio window (vs only inside
|
||||||
|
# the tolerance band around it).
|
||||||
|
overlap: int = 0
|
||||||
|
nearby: int = 0
|
||||||
|
competing: List[int] = field(default_factory=list)
|
||||||
|
|
||||||
|
|
||||||
class MetadataWatcher:
|
class MetadataWatcher:
|
||||||
def __init__(self):
|
def __init__(self):
|
||||||
self._running = False
|
self._running = False
|
||||||
@@ -114,21 +222,38 @@ class MetadataWatcher:
|
|||||||
self._current_tgid_name: Optional[str] = None
|
self._current_tgid_name: Optional[str] = None
|
||||||
self._current_freq: Any = None
|
self._current_freq: Any = None
|
||||||
self._current_srcaddr: Optional[int] = None
|
self._current_srcaddr: Optional[int] = None
|
||||||
self._started_at: Optional[float] = None # OP25 epoch of the first grant
|
self._started_at: Optional[float] = None # audio onset, or grant epoch in fallback mode
|
||||||
self._transmissions: int = 0
|
self._transmissions: int = 0
|
||||||
|
# True when the open segment is governed by audio, False for the
|
||||||
|
# console fallback. Fixed at open so capture flapping cannot switch the
|
||||||
|
# rules underneath a live segment.
|
||||||
|
self._audio_driven: bool = False
|
||||||
|
|
||||||
# Transmission tracking within the open segment
|
# Transmission tracking within the open segment (console fallback mode)
|
||||||
self._tx_active: bool = False # last poll saw srcaddr != 0
|
self._tx_active: bool = False # last poll saw srcaddr != 0
|
||||||
self._last_activity: float = 0.0 # epoch of last evidence of traffic
|
self._last_activity: float = 0.0 # epoch of last evidence of traffic
|
||||||
self._last_tx_end: Optional[float] = None # epoch of the srcaddr 1→0 edge
|
self._last_tx_end: Optional[float] = None # epoch of the srcaddr 1→0 edge
|
||||||
self._last_ok_poll: float = 0.0
|
self._last_ok_poll: float = 0.0
|
||||||
|
|
||||||
|
# Rolling console history for close-time attribution.
|
||||||
|
self._console: deque[ConsoleEvent] = deque(maxlen=CONSOLE_HISTORY_MAX)
|
||||||
|
|
||||||
|
# Onset of the voice run the last audio-driven segment covered, so the
|
||||||
|
# same run cannot immediately re-open a second segment.
|
||||||
|
self._consumed_onset: Optional[float] = None
|
||||||
|
|
||||||
|
# Field-visible counter of discarded orphan audio.
|
||||||
|
self._unattributed_segments: int = 0
|
||||||
|
|
||||||
# Injectable for tests; production is always the host wall clock.
|
# Injectable for tests; production is always the host wall clock.
|
||||||
self._clock: Callable[[], float] = time.time
|
self._clock: Callable[[], float] = time.time
|
||||||
|
|
||||||
# Set these before calling start()
|
# Set these before calling start()
|
||||||
self.on_call_start: Optional[CallbackFn] = None
|
self.on_call_start: Optional[CallbackFn] = None
|
||||||
self.on_call_end: Optional[CallbackFn] = None
|
self.on_call_end: Optional[CallbackFn] = None
|
||||||
|
# Supplies the audio-activity snapshot. None (or a snapshot reporting
|
||||||
|
# capturing=False) puts the watcher in console fallback mode.
|
||||||
|
self.audio_activity: Optional[ActivityFn] = None
|
||||||
|
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
# Lifecycle
|
# Lifecycle
|
||||||
@@ -138,7 +263,7 @@ class MetadataWatcher:
|
|||||||
self._running = True
|
self._running = True
|
||||||
self._last_ok_poll = self._clock()
|
self._last_ok_poll = self._clock()
|
||||||
asyncio.create_task(self._poll_loop())
|
asyncio.create_task(self._poll_loop())
|
||||||
logger.info("Metadata watcher started (call_log driven).")
|
logger.info("Metadata watcher started (audio-driven segmentation, console attribution).")
|
||||||
|
|
||||||
async def stop(self):
|
async def stop(self):
|
||||||
self._running = False
|
self._running = False
|
||||||
@@ -168,6 +293,307 @@ class MetadataWatcher:
|
|||||||
return
|
return
|
||||||
|
|
||||||
self._last_ok_poll = now
|
self._last_ok_poll = now
|
||||||
|
self._record_console(update, now)
|
||||||
|
|
||||||
|
activity = self._snapshot()
|
||||||
|
if activity is None or not activity.capturing:
|
||||||
|
await self._console_tick(update, now)
|
||||||
|
return
|
||||||
|
|
||||||
|
await self._audio_tick(update, activity, now)
|
||||||
|
|
||||||
|
def _snapshot(self) -> Optional[AudioActivity]:
|
||||||
|
if self.audio_activity is None:
|
||||||
|
return None
|
||||||
|
try:
|
||||||
|
return self.audio_activity()
|
||||||
|
except Exception as e:
|
||||||
|
logger.warning(f"Audio activity unavailable ({e}) — falling back to console segmentation.")
|
||||||
|
return None
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# Console history (feeds close-time attribution)
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
|
def _record_console(self, update: Any, now: float) -> None:
|
||||||
|
for entry in update.call_log:
|
||||||
|
tgid = _as_int(entry.get("tgid"))
|
||||||
|
if tgid is None:
|
||||||
|
continue
|
||||||
|
epoch = _as_float(entry.get("time"))
|
||||||
|
event = ConsoleEvent(
|
||||||
|
epoch=now if epoch is None else epoch,
|
||||||
|
tgid=tgid,
|
||||||
|
name=entry.get("tgtag") or "",
|
||||||
|
freq=entry.get("freq"),
|
||||||
|
rid=_as_int(entry.get("rid")),
|
||||||
|
is_grant=True,
|
||||||
|
)
|
||||||
|
if not self._is_duplicate_grant(event):
|
||||||
|
self._console.append(event)
|
||||||
|
|
||||||
|
for channel in update.channels:
|
||||||
|
tgid = _as_int(channel.get("tgid"))
|
||||||
|
srcaddr = _as_int(channel.get("srcaddr"))
|
||||||
|
if tgid is None or srcaddr is None:
|
||||||
|
continue # idle channel says nothing about who is talking
|
||||||
|
self._console.append(ConsoleEvent(
|
||||||
|
epoch=now,
|
||||||
|
tgid=tgid,
|
||||||
|
name=channel.get("tag") or "",
|
||||||
|
freq=channel.get("freq"),
|
||||||
|
rid=srcaddr,
|
||||||
|
is_grant=False,
|
||||||
|
))
|
||||||
|
|
||||||
|
cutoff = now - CONSOLE_HISTORY_SECONDS
|
||||||
|
while self._console and self._console[0].epoch < cutoff:
|
||||||
|
self._console.popleft()
|
||||||
|
|
||||||
|
def _is_duplicate_grant(self, event: ConsoleEvent) -> bool:
|
||||||
|
for index in range(len(self._console) - 1, -1, -1):
|
||||||
|
if len(self._console) - index > _GRANT_DEDUPE_DEPTH:
|
||||||
|
return False
|
||||||
|
known = self._console[index]
|
||||||
|
if known.is_grant and known.tgid == event.tgid and known.epoch == event.epoch:
|
||||||
|
return True
|
||||||
|
return False
|
||||||
|
|
||||||
|
def _attribute(self, start: float, end: float) -> Optional[Attribution]:
|
||||||
|
"""
|
||||||
|
Resolve which talkgroup a stretch of audio belongs to.
|
||||||
|
|
||||||
|
Scores every talkgroup seen in [start - LOOKBACK, end + LOOKAHEAD] by
|
||||||
|
how well its console activity overlaps the audio itself, preferring
|
||||||
|
real overlap over merely being nearby, and grants over channel rows.
|
||||||
|
Returns None only when NOTHING was observed in that band at all — the
|
||||||
|
orphan-audio case.
|
||||||
|
"""
|
||||||
|
low = start - ATTRIBUTION_LOOKBACK_SECONDS
|
||||||
|
high = end + ATTRIBUTION_LOOKAHEAD_SECONDS
|
||||||
|
candidates: Dict[int, Attribution] = {}
|
||||||
|
firsts: Dict[int, float] = {}
|
||||||
|
|
||||||
|
for event in self._console:
|
||||||
|
if event.epoch < low or event.epoch > high:
|
||||||
|
continue
|
||||||
|
found = candidates.get(event.tgid)
|
||||||
|
if found is None:
|
||||||
|
found = Attribution(tgid=event.tgid)
|
||||||
|
candidates[event.tgid] = found
|
||||||
|
firsts[event.tgid] = event.epoch
|
||||||
|
found.nearby += 1
|
||||||
|
if start <= event.epoch <= end:
|
||||||
|
found.overlap += 1
|
||||||
|
if event.is_grant:
|
||||||
|
found.grants += 1
|
||||||
|
if event.name and not found.name:
|
||||||
|
found.name = event.name
|
||||||
|
if event.freq and found.freq is None:
|
||||||
|
found.freq = event.freq
|
||||||
|
if event.rid is not None:
|
||||||
|
found.rid = event.rid # most recent wins
|
||||||
|
|
||||||
|
if not candidates:
|
||||||
|
return None
|
||||||
|
|
||||||
|
best = max(
|
||||||
|
candidates.values(),
|
||||||
|
key=lambda a: (a.overlap, a.grants, a.nearby, -firsts[a.tgid]),
|
||||||
|
)
|
||||||
|
best.competing = sorted(
|
||||||
|
tgid for tgid, a in candidates.items() if tgid != best.tgid and a.overlap > 0
|
||||||
|
)
|
||||||
|
return best
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# Audio-driven segmentation
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
|
async def _audio_tick(self, update: Any, activity: AudioActivity, now: float) -> None:
|
||||||
|
if self._active_call_id is not None and not self._audio_driven:
|
||||||
|
# A segment that opened while capture was down finishes under the
|
||||||
|
# rules it started with rather than switching mid-flight.
|
||||||
|
await self._console_tick(update, now)
|
||||||
|
return
|
||||||
|
|
||||||
|
# 1. Console first: a talkgroup change must still force a split even
|
||||||
|
# when the audio never went quiet, and a grant may be the thing that
|
||||||
|
# finally attributes an already-open segment.
|
||||||
|
for entry in sorted(update.call_log, key=lambda e: _as_float(e.get("time")) or 0.0):
|
||||||
|
await self._handle_grant(entry, now)
|
||||||
|
await self._scan_channels(update.channels, now)
|
||||||
|
|
||||||
|
# 2. Then the audio decides the boundaries.
|
||||||
|
last_voice = activity.last_voice_epoch
|
||||||
|
voice_active = last_voice is not None and (now - last_voice) < settings.call_silence_timeout
|
||||||
|
|
||||||
|
if self._active_call_id is None:
|
||||||
|
onset = activity.voice_onset_epoch
|
||||||
|
if voice_active and onset is not None and (
|
||||||
|
self._consumed_onset is None or onset > self._consumed_onset
|
||||||
|
):
|
||||||
|
await self._open_from_audio(onset, now)
|
||||||
|
return
|
||||||
|
|
||||||
|
if not voice_active:
|
||||||
|
silence = (now - last_voice) if last_voice is not None else settings.call_silence_timeout
|
||||||
|
# The measured trailing silence, in the AUDIO's own clock. This is
|
||||||
|
# the number to tune settings.call_silence_timeout from — unlike the
|
||||||
|
# old control-channel idle it contains no grant-to-speech delay, so
|
||||||
|
# it means exactly what it says.
|
||||||
|
logger.info(
|
||||||
|
f"Audio silence close for tgid {self._current_tgid}: measured trailing silence "
|
||||||
|
f"{silence:.2f}s (threshold {settings.call_silence_timeout:.2f}s at "
|
||||||
|
f"{settings.call_silence_threshold_db:.1f}dBFS)."
|
||||||
|
)
|
||||||
|
self._consumed_onset = activity.voice_onset_epoch
|
||||||
|
end = (last_voice + settings.call_silence_timeout) if last_voice is not None else now
|
||||||
|
await self._close_segment(min(end, now), reason="audio_silence")
|
||||||
|
return
|
||||||
|
|
||||||
|
if self._started_at is not None and (now - self._started_at) >= MAX_SEGMENT_SECONDS:
|
||||||
|
logger.warning(
|
||||||
|
f"Segment for tgid {self._current_tgid} hit the {MAX_SEGMENT_SECONDS}s cap while audio "
|
||||||
|
"was still live — closing and immediately reopening so nothing is dropped. If this "
|
||||||
|
"repeats, the silence threshold may be low enough that noise reads as voice."
|
||||||
|
)
|
||||||
|
await self._close_segment(now, reason="max_length")
|
||||||
|
await self._open_from_audio(now, now)
|
||||||
|
|
||||||
|
async def _open_from_audio(self, onset: float, now: float) -> None:
|
||||||
|
"""Open a segment at a detected voice onset, attributing it if we can."""
|
||||||
|
found = self._attribute(onset, now)
|
||||||
|
await self._open_segment(
|
||||||
|
started_at=onset,
|
||||||
|
now=now,
|
||||||
|
tgid=found.tgid if found else None,
|
||||||
|
tgid_name=found.name if found else "",
|
||||||
|
freq=found.freq if found else None,
|
||||||
|
srcaddr=found.rid if found else None,
|
||||||
|
audio_driven=True,
|
||||||
|
transmissions=found.grants if found else 0,
|
||||||
|
)
|
||||||
|
|
||||||
|
async def _handle_grant(self, entry: Dict[str, Any], now: float) -> None:
|
||||||
|
"""A `call_log` grant, interpreted in audio mode: label or split, never start."""
|
||||||
|
tgid = _as_int(entry.get("tgid"))
|
||||||
|
if tgid is None:
|
||||||
|
return # a grant with no talkgroup is nothing we can label with
|
||||||
|
|
||||||
|
started_at = _as_float(entry.get("time"))
|
||||||
|
if started_at is None:
|
||||||
|
logger.warning(f"call_log entry for tgid={tgid} has no usable time — using local clock.")
|
||||||
|
started_at = now
|
||||||
|
|
||||||
|
if self._active_call_id is None:
|
||||||
|
# Audio starts recordings, not grants. The grant is already in the
|
||||||
|
# console history and will attribute the segment when audio arrives.
|
||||||
|
return
|
||||||
|
|
||||||
|
if self._current_tgid is None:
|
||||||
|
self._current_tgid = tgid
|
||||||
|
self._current_tgid_name = entry.get("tgtag") or ""
|
||||||
|
self._current_freq = entry.get("freq")
|
||||||
|
self._current_srcaddr = _as_int(entry.get("rid"))
|
||||||
|
self._transmissions += 1
|
||||||
|
logger.info(
|
||||||
|
f"Late attribution: segment {self._active_call_id} adopted tgid {tgid} from a grant "
|
||||||
|
f"logged {started_at - (self._started_at or started_at):+.2f}s from audio onset."
|
||||||
|
)
|
||||||
|
return
|
||||||
|
|
||||||
|
if tgid == self._current_tgid:
|
||||||
|
# CONTINUE: same talkgroup, keep one recording so the back-and-forth
|
||||||
|
# of a single conversation lands in one file.
|
||||||
|
self._transmissions += 1
|
||||||
|
self._refresh_meta_from_log(entry)
|
||||||
|
return
|
||||||
|
|
||||||
|
# FORCED SPLIT. Two talkgroups can be back to back with no silence
|
||||||
|
# between them; pure audio segmentation would merge them into one file
|
||||||
|
# under one label, which is exactly the kind of wrong that corrupts
|
||||||
|
# incident correlation. The console change is authoritative here.
|
||||||
|
await self._close_segment(started_at + _tail_pad(), reason="tgid_change")
|
||||||
|
await self._open_segment(
|
||||||
|
started_at=started_at,
|
||||||
|
now=now,
|
||||||
|
tgid=tgid,
|
||||||
|
tgid_name=entry.get("tgtag") or "",
|
||||||
|
freq=entry.get("freq"),
|
||||||
|
srcaddr=_as_int(entry.get("rid")),
|
||||||
|
audio_driven=True,
|
||||||
|
transmissions=1,
|
||||||
|
)
|
||||||
|
|
||||||
|
async def _scan_channels(self, channels: List[Dict[str, Any]], now: float) -> None:
|
||||||
|
"""Channel rows in audio mode: refresh metadata, catch an unlogged split."""
|
||||||
|
if self._active_call_id is None:
|
||||||
|
return
|
||||||
|
|
||||||
|
active: List[Dict[str, Any]] = []
|
||||||
|
ours = False
|
||||||
|
for channel in channels:
|
||||||
|
tgid = _as_int(channel.get("tgid"))
|
||||||
|
srcaddr = _as_int(channel.get("srcaddr"))
|
||||||
|
if tgid is None or srcaddr is None:
|
||||||
|
continue
|
||||||
|
active.append(channel)
|
||||||
|
if tgid == self._current_tgid:
|
||||||
|
ours = True
|
||||||
|
self._current_srcaddr = srcaddr
|
||||||
|
self._last_activity = now
|
||||||
|
self._refresh_meta_from_channel(channel)
|
||||||
|
|
||||||
|
if self._current_tgid is None:
|
||||||
|
# Late attribution from a channel row — this is the path that saves
|
||||||
|
# us when the grant itself was dropped from OP25's capped deque.
|
||||||
|
if len(active) == 1:
|
||||||
|
tgid = _as_int(active[0].get("tgid"))
|
||||||
|
self._current_tgid = tgid
|
||||||
|
self._current_tgid_name = active[0].get("tag") or ""
|
||||||
|
self._current_freq = active[0].get("freq")
|
||||||
|
self._current_srcaddr = _as_int(active[0].get("srcaddr"))
|
||||||
|
logger.info(f"Late attribution: segment {self._active_call_id} adopted tgid {tgid} from channel state.")
|
||||||
|
return
|
||||||
|
|
||||||
|
if ours or not active or len(channels) != 1:
|
||||||
|
# Restricted to single-receiver setups on purpose: with several
|
||||||
|
# receivers, another channel being busy says nothing about ours.
|
||||||
|
return
|
||||||
|
|
||||||
|
foreign = _as_int(active[0].get("tgid"))
|
||||||
|
if foreign is None or foreign == self._current_tgid:
|
||||||
|
return
|
||||||
|
|
||||||
|
logger.warning(
|
||||||
|
f"tgid {foreign} active without a call_log entry — splitting segment for tgid "
|
||||||
|
f"{self._current_tgid} (call_log event likely dropped)."
|
||||||
|
)
|
||||||
|
await self._close_segment(now + _tail_pad(), reason="tgid_change_unlogged")
|
||||||
|
await self._open_segment(
|
||||||
|
started_at=now,
|
||||||
|
now=now,
|
||||||
|
tgid=foreign,
|
||||||
|
tgid_name=active[0].get("tag") or "",
|
||||||
|
freq=active[0].get("freq"),
|
||||||
|
srcaddr=_as_int(active[0].get("srcaddr")),
|
||||||
|
audio_driven=True,
|
||||||
|
transmissions=1,
|
||||||
|
)
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# Console fallback segmentation (capture down)
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
|
async def _console_tick(self, update: Any, now: float) -> None:
|
||||||
|
if self._active_call_id is not None and self._audio_driven:
|
||||||
|
logger.warning(
|
||||||
|
f"PulseAudio capture stopped while recording {self._active_call_id} — closing the "
|
||||||
|
"segment at the last captured audio; segmentation falls back to the control channel."
|
||||||
|
)
|
||||||
|
await self._close_segment(now, reason="capture_lost")
|
||||||
|
return
|
||||||
|
|
||||||
# 1. call_log first — these are the authoritative starts, and processing
|
# 1. call_log first — these are the authoritative starts, and processing
|
||||||
# them before the channel scan means a same-poll grant+state pair is
|
# them before the channel scan means a same-poll grant+state pair is
|
||||||
@@ -176,27 +602,24 @@ class MetadataWatcher:
|
|||||||
for entry in sorted(update.call_log, key=lambda e: _as_float(e.get("time")) or 0.0):
|
for entry in sorted(update.call_log, key=lambda e: _as_float(e.get("time")) or 0.0):
|
||||||
await self._handle_call_log(entry, now)
|
await self._handle_call_log(entry, now)
|
||||||
|
|
||||||
# 2. channel_update — the only external end signal.
|
# 2. channel_update — the only external end signal available here.
|
||||||
await self._handle_channels(update.channels, now)
|
await self._handle_channels(update.channels, now)
|
||||||
|
|
||||||
async def _handle_call_log(self, entry: Dict[str, Any], now: float) -> None:
|
async def _handle_call_log(self, entry: Dict[str, Any], now: float) -> None:
|
||||||
tgid = _as_int(entry.get("tgid"))
|
tgid = _as_int(entry.get("tgid"))
|
||||||
if tgid is None:
|
if tgid is None:
|
||||||
return # a grant with no talkgroup is nothing we can record or label
|
return
|
||||||
|
|
||||||
# OP25's own stamp. Fall back to now only if the field is missing/garbage.
|
|
||||||
started_at = _as_float(entry.get("time"))
|
started_at = _as_float(entry.get("time"))
|
||||||
if started_at is None:
|
if started_at is None:
|
||||||
logger.warning(f"call_log entry for tgid={tgid} has no usable time — using local clock.")
|
logger.warning(f"call_log entry for tgid={tgid} has no usable time — using local clock.")
|
||||||
started_at = now
|
started_at = now
|
||||||
|
|
||||||
if self._active_call_id is None:
|
if self._active_call_id is None:
|
||||||
await self._open_segment(entry, tgid, started_at, now)
|
await self._open_from_console(entry, tgid, started_at, now)
|
||||||
return
|
return
|
||||||
|
|
||||||
if tgid == self._current_tgid:
|
if tgid == self._current_tgid:
|
||||||
# CONTINUE: same talkgroup, keep one recording so the back-and-forth
|
|
||||||
# of a single conversation lands in one file.
|
|
||||||
self._transmissions += 1
|
self._transmissions += 1
|
||||||
self._tx_active = True
|
self._tx_active = True
|
||||||
self._last_tx_end = None
|
self._last_tx_end = None
|
||||||
@@ -204,18 +627,8 @@ class MetadataWatcher:
|
|||||||
self._refresh_meta_from_log(entry)
|
self._refresh_meta_from_log(entry)
|
||||||
return
|
return
|
||||||
|
|
||||||
# SPLIT: different talkgroup. The new grant's OP25 timestamp is the most
|
|
||||||
# precise CONTROL-CHANNEL end for the outgoing segment, but the buffered
|
|
||||||
# audio lags control by ~1.5s, so slicing exactly there cut the outgoing
|
|
||||||
# call's last words. Pad past it and let the recorder's bounded tail wait
|
|
||||||
# block until that audio has actually been captured.
|
|
||||||
#
|
|
||||||
# The incoming call's pre-roll comes from the ring buffer, so the delay
|
|
||||||
# costs it nothing, and the two slices overlapping in the underlying
|
|
||||||
# audio is correct — the stream genuinely contains one call's tail and
|
|
||||||
# then the next call's start.
|
|
||||||
await self._close_segment(started_at + _tail_pad(), reason="tgid_change")
|
await self._close_segment(started_at + _tail_pad(), reason="tgid_change")
|
||||||
await self._open_segment(entry, tgid, started_at, now)
|
await self._open_from_console(entry, tgid, started_at, now)
|
||||||
|
|
||||||
async def _handle_channels(self, channels: List[Dict[str, Any]], now: float) -> None:
|
async def _handle_channels(self, channels: List[Dict[str, Any]], now: float) -> None:
|
||||||
if self._active_call_id is None:
|
if self._active_call_id is None:
|
||||||
@@ -241,19 +654,13 @@ class MetadataWatcher:
|
|||||||
self._last_tx_end = None
|
self._last_tx_end = None
|
||||||
self._last_activity = now
|
self._last_activity = now
|
||||||
elif self._tx_active:
|
elif self._tx_active:
|
||||||
# The srcaddr != 0 → 0 edge: OP25 has torn the call down.
|
# The srcaddr != 0 → 0 edge. Note this is NOT trusted as an end of
|
||||||
|
# speech any more (it fires mid-word in the field) — in fallback
|
||||||
|
# mode there is simply nothing better available.
|
||||||
self._tx_active = False
|
self._tx_active = False
|
||||||
self._last_tx_end = now
|
self._last_tx_end = now
|
||||||
self._last_activity = now
|
self._last_activity = now
|
||||||
|
|
||||||
# Safety net for a dropped call_log event (deque is capped at 10): the one
|
|
||||||
# receiver we have is plainly on another talkgroup, so our segment is over
|
|
||||||
# even though we never saw its grant. Close now rather than record
|
|
||||||
# call_idle_timeout seconds of the wrong tgid.
|
|
||||||
#
|
|
||||||
# Restricted to single-receiver setups on purpose: with several receivers,
|
|
||||||
# another channel being busy says nothing about ours, and closing on it
|
|
||||||
# would truncate every call whenever a second receiver is active.
|
|
||||||
if not tx_active and foreign_active_tgid is not None and len(channels) == 1:
|
if not tx_active and foreign_active_tgid is not None and len(channels) == 1:
|
||||||
logger.warning(
|
logger.warning(
|
||||||
f"tgid {foreign_active_tgid} active without a call_log entry — "
|
f"tgid {foreign_active_tgid} active without a call_log entry — "
|
||||||
@@ -263,14 +670,6 @@ class MetadataWatcher:
|
|||||||
return
|
return
|
||||||
|
|
||||||
if (now - self._last_activity) >= settings.call_idle_timeout:
|
if (now - self._last_activity) >= settings.call_idle_timeout:
|
||||||
# STOP: quiet for long enough. End the audio at the last transmission
|
|
||||||
# plus a short pad, not at "now" — otherwise every recording carries
|
|
||||||
# call_idle_timeout seconds of silence.
|
|
||||||
#
|
|
||||||
# The measured idle below is the CONTROL-CHANNEL idle (srcaddr 1→0
|
|
||||||
# edge → now). It is NOT comparable to silence measured in the audio,
|
|
||||||
# which additionally contains the ~1.9 s P25 grant→speech delay.
|
|
||||||
# Tune settings.call_idle_timeout from THIS number and nothing else.
|
|
||||||
if self._last_tx_end is not None:
|
if self._last_tx_end is not None:
|
||||||
measured_idle = now - self._last_tx_end
|
measured_idle = now - self._last_tx_end
|
||||||
end = self._last_tx_end + _tail_pad()
|
end = self._last_tx_end + _tail_pad()
|
||||||
@@ -292,6 +691,18 @@ class MetadataWatcher:
|
|||||||
logger.warning(f"Segment for tgid {self._current_tgid} hit the {MAX_SEGMENT_SECONDS}s cap — closing.")
|
logger.warning(f"Segment for tgid {self._current_tgid} hit the {MAX_SEGMENT_SECONDS}s cap — closing.")
|
||||||
await self._close_segment(now, reason="max_length")
|
await self._close_segment(now, reason="max_length")
|
||||||
|
|
||||||
|
async def _open_from_console(self, entry: Dict[str, Any], tgid: int, started_at: float, now: float) -> None:
|
||||||
|
await self._open_segment(
|
||||||
|
started_at=started_at,
|
||||||
|
now=now,
|
||||||
|
tgid=tgid,
|
||||||
|
tgid_name=entry.get("tgtag") or "",
|
||||||
|
freq=entry.get("freq"),
|
||||||
|
srcaddr=_as_int(entry.get("rid")),
|
||||||
|
audio_driven=False,
|
||||||
|
transmissions=1,
|
||||||
|
)
|
||||||
|
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
# Segment open / close
|
# Segment open / close
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
@@ -311,35 +722,48 @@ class MetadataWatcher:
|
|||||||
if not self._current_freq and channel.get("freq"):
|
if not self._current_freq and channel.get("freq"):
|
||||||
self._current_freq = channel.get("freq")
|
self._current_freq = channel.get("freq")
|
||||||
|
|
||||||
async def _open_segment(self, entry: Dict[str, Any], tgid: int, started_at: float, now: float) -> None:
|
async def _open_segment(
|
||||||
|
self,
|
||||||
|
started_at: float,
|
||||||
|
now: float,
|
||||||
|
tgid: Optional[int],
|
||||||
|
tgid_name: str,
|
||||||
|
freq: Any,
|
||||||
|
srcaddr: Optional[int],
|
||||||
|
audio_driven: bool,
|
||||||
|
transmissions: int = 1,
|
||||||
|
) -> None:
|
||||||
self._active_call_id = str(uuid.uuid4())
|
self._active_call_id = str(uuid.uuid4())
|
||||||
self._current_tgid = tgid
|
self._current_tgid = tgid
|
||||||
self._current_tgid_name = entry.get("tgtag") or ""
|
self._current_tgid_name = tgid_name
|
||||||
self._current_freq = entry.get("freq")
|
self._current_freq = freq
|
||||||
self._current_srcaddr = _as_int(entry.get("rid"))
|
self._current_srcaddr = srcaddr
|
||||||
self._started_at = started_at
|
self._started_at = started_at
|
||||||
self._transmissions = 1
|
self._transmissions = max(1, transmissions)
|
||||||
|
self._audio_driven = audio_driven
|
||||||
|
|
||||||
# Assume the transmission is still up: we learn otherwise from the next
|
# Console fallback assumes the transmission is still up; it learns
|
||||||
# channel scan. A grant whose call already ended before we polled simply
|
# otherwise from the next channel scan.
|
||||||
# closes on the very next tick via the idle timeout.
|
self._tx_active = not audio_driven
|
||||||
self._tx_active = True
|
|
||||||
self._last_tx_end = None
|
self._last_tx_end = None
|
||||||
self._last_activity = now
|
self._last_activity = now
|
||||||
|
|
||||||
payload = {
|
payload = {
|
||||||
"call_id": self._active_call_id,
|
"call_id": self._active_call_id,
|
||||||
"tgid": tgid,
|
"tgid": tgid,
|
||||||
"tgid_name": self._current_tgid_name,
|
"tgid_name": tgid_name,
|
||||||
"freq": self._current_freq,
|
"freq": freq,
|
||||||
"srcaddr": self._current_srcaddr,
|
"srcaddr": srcaddr,
|
||||||
"started_at": _iso(started_at),
|
"started_at": _iso(started_at),
|
||||||
# Raw epoch for the recorder's ring-buffer slice — same clock domain.
|
# Raw epoch for the recorder's ring-buffer slice — same clock domain.
|
||||||
"started_at_epoch": started_at,
|
"started_at_epoch": started_at,
|
||||||
|
"attributed": tgid is not None,
|
||||||
|
"driver": "audio" if audio_driven else "console",
|
||||||
}
|
}
|
||||||
|
source = "audio onset" if audio_driven else "op25 grant"
|
||||||
logger.info(
|
logger.info(
|
||||||
f"Call start: tgid={tgid} id={self._active_call_id} "
|
f"Call start: tgid={tgid} id={self._active_call_id} "
|
||||||
f"(op25 t={started_at:.3f}, detected {now - started_at:+.2f}s later)"
|
f"({source} t={started_at:.3f}, detected {now - started_at:+.2f}s later)"
|
||||||
)
|
)
|
||||||
if self.on_call_start:
|
if self.on_call_start:
|
||||||
await self.on_call_start(payload)
|
await self.on_call_start(payload)
|
||||||
@@ -352,6 +776,10 @@ class MetadataWatcher:
|
|||||||
if started_at is not None:
|
if started_at is not None:
|
||||||
end_epoch = max(end_epoch, started_at)
|
end_epoch = max(end_epoch, started_at)
|
||||||
|
|
||||||
|
if self._audio_driven and reason not in _SPLIT_REASONS:
|
||||||
|
self._resolve_attribution(started_at if started_at is not None else end_epoch, end_epoch)
|
||||||
|
|
||||||
|
attributed = self._current_tgid is not None
|
||||||
payload = {
|
payload = {
|
||||||
"call_id": self._active_call_id,
|
"call_id": self._active_call_id,
|
||||||
"tgid": self._current_tgid,
|
"tgid": self._current_tgid,
|
||||||
@@ -364,8 +792,25 @@ class MetadataWatcher:
|
|||||||
"ended_at_epoch": end_epoch,
|
"ended_at_epoch": end_epoch,
|
||||||
"transmissions": self._transmissions,
|
"transmissions": self._transmissions,
|
||||||
"end_reason": reason,
|
"end_reason": reason,
|
||||||
|
"attributed": attributed,
|
||||||
|
"driver": "audio" if self._audio_driven else "console",
|
||||||
}
|
}
|
||||||
duration = (end_epoch - started_at) if started_at is not None else 0.0
|
duration = (end_epoch - started_at) if started_at is not None else 0.0
|
||||||
|
|
||||||
|
if not attributed:
|
||||||
|
self._unattributed_segments += 1
|
||||||
|
window_start = started_at if started_at is not None else end_epoch
|
||||||
|
logger.error(
|
||||||
|
f"ORPHAN AUDIO: {duration:.2f}s of audio ({self._active_call_id}, reason={reason}, "
|
||||||
|
f"window {window_start:.3f}-{end_epoch:.3f}) had NO OP25 talkgroup anywhere within "
|
||||||
|
f"{ATTRIBUTION_LOOKBACK_SECONDS:.0f}s before or {ATTRIBUTION_LOOKAHEAD_SECONDS:.0f}s "
|
||||||
|
f"after it. It will be DISCARDED, not uploaded — an untagged call would poison "
|
||||||
|
f"incident correlation. Causes: Liquidsoap fallback/test audio on drb_sink, OP25 not "
|
||||||
|
f"decoding the control channel, or a dropped call_log. Console history holds "
|
||||||
|
f"{len(self._console)} recent observations; total orphans this run: "
|
||||||
|
f"{self._unattributed_segments}."
|
||||||
|
)
|
||||||
|
else:
|
||||||
logger.info(
|
logger.info(
|
||||||
f"Call end: id={self._active_call_id} tgid={self._current_tgid} "
|
f"Call end: id={self._active_call_id} tgid={self._current_tgid} "
|
||||||
f"reason={reason} transmissions={self._transmissions} duration={duration:.2f}s"
|
f"reason={reason} transmissions={self._transmissions} duration={duration:.2f}s"
|
||||||
@@ -382,10 +827,57 @@ class MetadataWatcher:
|
|||||||
self._transmissions = 0
|
self._transmissions = 0
|
||||||
self._tx_active = False
|
self._tx_active = False
|
||||||
self._last_tx_end = None
|
self._last_tx_end = None
|
||||||
|
self._audio_driven = False
|
||||||
|
|
||||||
if self.on_call_end:
|
if self.on_call_end:
|
||||||
await self.on_call_end(payload)
|
await self.on_call_end(payload)
|
||||||
|
|
||||||
|
def _resolve_attribution(self, start: float, end: float) -> None:
|
||||||
|
"""
|
||||||
|
Last chance to label an audio-driven segment, run at close.
|
||||||
|
|
||||||
|
Only ADOPTS a talkgroup when the segment still has none. A tgid we
|
||||||
|
already hold came from a grant or a channel row — the console stating
|
||||||
|
outright who was transmitting — and an inference over a window is not
|
||||||
|
allowed to overrule a direct statement. This matters because the window
|
||||||
|
deliberately extends past the audio (ATTRIBUTION_LOOKAHEAD_SECONDS, and
|
||||||
|
the tail pad on a split), so a neighbouring call's console activity can
|
||||||
|
legitimately fall inside it.
|
||||||
|
|
||||||
|
A disagreement is still worth knowing about, so it is logged: it means
|
||||||
|
two talkgroups' console activity overlaps one recording, i.e. the split
|
||||||
|
logic should have fired and did not.
|
||||||
|
"""
|
||||||
|
found = self._attribute(start, end)
|
||||||
|
if found is None:
|
||||||
|
return
|
||||||
|
|
||||||
|
if self._current_tgid is None:
|
||||||
|
logger.info(
|
||||||
|
f"Attributed {self._active_call_id} at close to tgid {found.tgid} "
|
||||||
|
f"(overlap {found.overlap}, grants {found.grants}, nearby {found.nearby})."
|
||||||
|
)
|
||||||
|
self._current_tgid = found.tgid
|
||||||
|
if found.name:
|
||||||
|
self._current_tgid_name = found.name
|
||||||
|
if found.freq is not None and not self._current_freq:
|
||||||
|
self._current_freq = found.freq
|
||||||
|
if found.rid is not None and self._current_srcaddr is None:
|
||||||
|
self._current_srcaddr = found.rid
|
||||||
|
self._transmissions = max(self._transmissions, found.grants)
|
||||||
|
return
|
||||||
|
|
||||||
|
others = sorted(set(found.competing) | ({found.tgid} if found.tgid != self._current_tgid else set()))
|
||||||
|
others = [tgid for tgid in others if tgid != self._current_tgid]
|
||||||
|
if others:
|
||||||
|
logger.warning(
|
||||||
|
f"Segment {self._active_call_id} (tgid {self._current_tgid}) overlaps console "
|
||||||
|
f"activity for {others} as well — the split logic should have fired and did not. "
|
||||||
|
"Keeping the talkgroup the console stated directly."
|
||||||
|
)
|
||||||
|
if not self._current_tgid_name and found.tgid == self._current_tgid and found.name:
|
||||||
|
self._current_tgid_name = found.name
|
||||||
|
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
# Public state (consumed by routers/api.py, main.py and the dashboards)
|
# Public state (consumed by routers/api.py, main.py and the dashboards)
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
@@ -406,5 +898,10 @@ class MetadataWatcher:
|
|||||||
def is_active(self) -> bool:
|
def is_active(self) -> bool:
|
||||||
return self._active_call_id is not None
|
return self._active_call_id is not None
|
||||||
|
|
||||||
|
@property
|
||||||
|
def unattributed_segments(self) -> int:
|
||||||
|
"""Orphan-audio segments discarded since start. Surfaced on /api/status."""
|
||||||
|
return self._unattributed_segments
|
||||||
|
|
||||||
|
|
||||||
metadata_watcher = MetadataWatcher()
|
metadata_watcher = MetadataWatcher()
|
||||||
|
|||||||
@@ -0,0 +1,131 @@
|
|||||||
|
"""
|
||||||
|
Raw PCM primitives: the one place that knows the capture format.
|
||||||
|
|
||||||
|
The capture pipeline buffers RAW PCM (signed 16-bit little-endian, mono,
|
||||||
|
22050 Hz) instead of MP3. Three things fall out of that, and they are the whole
|
||||||
|
reason for the change:
|
||||||
|
|
||||||
|
1. Silence detection is integer arithmetic over the bytes as they arrive —
|
||||||
|
no decode, no FFmpeg, no second process. That is what makes an
|
||||||
|
AUDIO-DRIVEN call boundary possible at all.
|
||||||
|
2. Trimming becomes a byte-offset slice instead of a second encode pass.
|
||||||
|
3. MP3 encoding happens exactly ONCE, at save time, so uploads stop being
|
||||||
|
double-encoded.
|
||||||
|
|
||||||
|
WHY SILENCE IS UNAMBIGUOUS HERE: between transmissions the captured stream is
|
||||||
|
the monitor of a PulseAudio *null sink*, which emits digital silence, not an
|
||||||
|
analog noise floor. Measured on a live node, the gap between transmissions sits
|
||||||
|
at about -91 dBFS — that is 20*log10(1/32768), i.e. one least-significant bit,
|
||||||
|
the quietest thing a 16-bit sample can be without being exactly zero. Speech on
|
||||||
|
the same node averages about -18 dBFS. There is therefore ~70 dB of daylight
|
||||||
|
between "silence" and "voice", and the threshold does NOT need field
|
||||||
|
calibration against radio noise the way an analog squelch tail would.
|
||||||
|
|
||||||
|
MEASUREMENT IS RMS, NOT PEAK. Peak would be cheaper but a single decoder click
|
||||||
|
would read as voice for a whole window; RMS over a window is the honest
|
||||||
|
"is there signal here" answer. The cost is a Python loop over the window's
|
||||||
|
samples, which is affordable because of how little audio is ever scanned:
|
||||||
|
one ~46 ms chunk per chunk arrival at capture time, and only the head/tail of a
|
||||||
|
finished recording at trim time (see audio_trim.MAX_SCAN_SECONDS). A cheap
|
||||||
|
all-zero fast path in C skips the loop entirely for exactly-silent windows.
|
||||||
|
|
||||||
|
BYTE ORDER: FFmpeg is asked for s16le. `array("h")` is native-endian, so on a
|
||||||
|
big-endian host the samples are byte-swapped before use. Every DRB target is
|
||||||
|
little-endian today; this is three lines of insurance, not a real scenario.
|
||||||
|
"""
|
||||||
|
import math
|
||||||
|
import sys
|
||||||
|
from array import array
|
||||||
|
from typing import Union
|
||||||
|
|
||||||
|
# Capture format. MP3_SAMPLE_RATE in call_recorder must stay equal to
|
||||||
|
# SAMPLE_RATE — the encode at save time is a straight pass with no resample.
|
||||||
|
SAMPLE_RATE = 22050
|
||||||
|
SAMPLE_WIDTH = 2
|
||||||
|
CHANNELS = 1
|
||||||
|
FRAME_BYTES = SAMPLE_WIDTH * CHANNELS
|
||||||
|
BYTES_PER_SECOND = SAMPLE_RATE * FRAME_BYTES # 44100 B/s
|
||||||
|
|
||||||
|
# 16-bit full scale. A sample of 32768 (or -32768) is 0 dBFS.
|
||||||
|
FULL_SCALE = 32768.0
|
||||||
|
|
||||||
|
# Reported for a window with no signal at all. Any real threshold is far above
|
||||||
|
# this, so it always compares as "silent" without special-casing log10(0).
|
||||||
|
SILENT_DBFS = -120.0
|
||||||
|
|
||||||
|
_NEEDS_BYTESWAP = sys.byteorder != "little"
|
||||||
|
|
||||||
|
Buffer = Union[bytes, bytearray]
|
||||||
|
|
||||||
|
|
||||||
|
def align(nbytes: int) -> int:
|
||||||
|
"""Round a byte count DOWN to a whole number of samples."""
|
||||||
|
if nbytes <= 0:
|
||||||
|
return 0
|
||||||
|
return nbytes - (nbytes % FRAME_BYTES)
|
||||||
|
|
||||||
|
|
||||||
|
def seconds(nbytes: int) -> float:
|
||||||
|
"""Duration of `nbytes` of PCM."""
|
||||||
|
return nbytes / BYTES_PER_SECOND
|
||||||
|
|
||||||
|
|
||||||
|
def byte_offset(sec: float) -> int:
|
||||||
|
"""Sample-aligned byte offset of `sec` seconds into a PCM buffer."""
|
||||||
|
return align(int(sec * BYTES_PER_SECOND))
|
||||||
|
|
||||||
|
|
||||||
|
def samples(buf: Buffer) -> array:
|
||||||
|
"""View a PCM buffer as signed 16-bit samples, dropping any partial frame."""
|
||||||
|
usable = align(len(buf))
|
||||||
|
data = array("h")
|
||||||
|
if usable:
|
||||||
|
data.frombytes(bytes(buf[:usable]))
|
||||||
|
if _NEEDS_BYTESWAP:
|
||||||
|
data.byteswap()
|
||||||
|
return data
|
||||||
|
|
||||||
|
|
||||||
|
def is_all_zero(buf: Buffer) -> bool:
|
||||||
|
"""
|
||||||
|
True when every byte is zero — exact digital silence.
|
||||||
|
|
||||||
|
`bytes.count` runs in C, so this is the cheap path that lets a long scan
|
||||||
|
over silence stay fast without touching the per-sample loop below.
|
||||||
|
"""
|
||||||
|
return len(buf) > 0 and buf.count(0) == len(buf)
|
||||||
|
|
||||||
|
|
||||||
|
def rms(buf: Buffer) -> float:
|
||||||
|
"""Root-mean-square amplitude in raw sample units (0 .. 32768)."""
|
||||||
|
data = samples(buf)
|
||||||
|
if not data:
|
||||||
|
return 0.0
|
||||||
|
total = 0
|
||||||
|
for sample in data:
|
||||||
|
total += sample * sample
|
||||||
|
return math.sqrt(total / len(data))
|
||||||
|
|
||||||
|
|
||||||
|
def rms_dbfs(buf: Buffer) -> float:
|
||||||
|
"""RMS level of a PCM window in dBFS. SILENT_DBFS for an empty/zero window."""
|
||||||
|
if not buf or is_all_zero(buf):
|
||||||
|
return SILENT_DBFS
|
||||||
|
value = rms(buf)
|
||||||
|
if value <= 0.0:
|
||||||
|
return SILENT_DBFS
|
||||||
|
return 20.0 * math.log10(min(value, FULL_SCALE) / FULL_SCALE)
|
||||||
|
|
||||||
|
|
||||||
|
def is_silent(buf: Buffer, threshold_db: float) -> bool:
|
||||||
|
"""
|
||||||
|
True when a PCM window carries no signal above `threshold_db` (dBFS RMS).
|
||||||
|
|
||||||
|
An empty buffer counts as silence: "no audio arrived" must never read as
|
||||||
|
"someone is talking", or a stalled capture would hold a segment open.
|
||||||
|
"""
|
||||||
|
if not buf:
|
||||||
|
return True
|
||||||
|
if is_all_zero(buf):
|
||||||
|
return True
|
||||||
|
return rms_dbfs(buf) < threshold_db
|
||||||
@@ -30,21 +30,56 @@ def _iso(epoch: Optional[float]) -> Optional[str]:
|
|||||||
return datetime.fromtimestamp(epoch, timezone.utc).isoformat()
|
return datetime.fromtimestamp(epoch, timezone.utc).isoformat()
|
||||||
|
|
||||||
|
|
||||||
|
# call_ids whose `call_start` has already gone out over MQTT. A segment can open
|
||||||
|
# before its talkgroup is known (audio onset can precede the OP25 grant), and
|
||||||
|
# C2's _on_call_start writes talkgroup_id straight into a new Firestore `calls`
|
||||||
|
# doc — publishing early with tgid=None would create a permanently untagged call.
|
||||||
|
# So the start is held back until attribution succeeds, and replayed just before
|
||||||
|
# the end event if it resolved late.
|
||||||
|
_published_starts: set = set()
|
||||||
|
|
||||||
|
|
||||||
async def on_call_start(data: dict):
|
async def on_call_start(data: dict):
|
||||||
radio_bot.start_stream()
|
radio_bot.start_stream()
|
||||||
await mqtt_manager.publish_status("recording")
|
await mqtt_manager.publish_status("recording")
|
||||||
await mqtt_manager.publish_metadata("call_start", data)
|
# started_at_epoch is the detected voice onset (or, in console fallback mode,
|
||||||
# started_at_epoch is OP25's own call_log timestamp — the recorder slices the
|
# OP25's call_log timestamp). The recorder slices the ring buffer back to it
|
||||||
# ring buffer back to it (minus pre-roll), so however late we detected the
|
# minus the pre-roll, so however late the poll loop noticed, the audio still
|
||||||
# grant, the audio still starts in the right place.
|
# starts in the right place.
|
||||||
await call_recorder.start_recording(
|
await call_recorder.start_recording(
|
||||||
data["call_id"],
|
data["call_id"],
|
||||||
start_epoch=data.get("started_at_epoch"),
|
start_epoch=data.get("started_at_epoch"),
|
||||||
)
|
)
|
||||||
|
|
||||||
|
if data.get("attributed", True):
|
||||||
|
_published_starts.add(data["call_id"])
|
||||||
|
await mqtt_manager.publish_metadata("call_start", data)
|
||||||
|
else:
|
||||||
|
logger.info(
|
||||||
|
f"Call {data['call_id']} started on audio onset with no talkgroup yet — holding the "
|
||||||
|
"call_start event until the console attributes it."
|
||||||
|
)
|
||||||
|
|
||||||
|
|
||||||
async def on_call_end(data: dict):
|
async def on_call_end(data: dict):
|
||||||
radio_bot.stop_stream()
|
radio_bot.stop_stream()
|
||||||
|
call_id = data["call_id"]
|
||||||
|
published_start = call_id in _published_starts
|
||||||
|
_published_starts.discard(call_id)
|
||||||
|
|
||||||
|
if not data.get("attributed", True):
|
||||||
|
# ORPHAN AUDIO. metadata_watcher has already logged the details at ERROR.
|
||||||
|
# The audio is dropped rather than uploaded: a call with no talkgroup is
|
||||||
|
# worse than no call at all, because it silently poisons correlation.
|
||||||
|
await call_recorder.discard_recording()
|
||||||
|
if published_start:
|
||||||
|
# Should not happen (attribution only ever improves), but if a start
|
||||||
|
# did go out, the doc must not be left hanging in "active".
|
||||||
|
data["audio_skipped"] = "unattributed"
|
||||||
|
await mqtt_manager.publish_metadata("call_end", data)
|
||||||
|
await mqtt_manager.publish_status("online")
|
||||||
|
return
|
||||||
|
|
||||||
recording = await call_recorder.stop_recording(end_epoch=data.get("ended_at_epoch"))
|
recording = await call_recorder.stop_recording(end_epoch=data.get("ended_at_epoch"))
|
||||||
|
|
||||||
if recording is not None and recording.path is not None:
|
if recording is not None and recording.path is not None:
|
||||||
@@ -89,6 +124,18 @@ async def on_call_end(data: dict):
|
|||||||
"— PulseAudio capture may be down (check the op25 container and "
|
"— PulseAudio capture may be down (check the op25 container and "
|
||||||
f"the {settings.pulse_source} source)."
|
f"the {settings.pulse_source} source)."
|
||||||
)
|
)
|
||||||
|
|
||||||
|
if not published_start:
|
||||||
|
# Attribution arrived after the segment opened. Replay the start so C2
|
||||||
|
# creates the `calls` doc with the right talkgroup before the end event
|
||||||
|
# updates it.
|
||||||
|
start_payload = {
|
||||||
|
key: data[key]
|
||||||
|
for key in ("call_id", "tgid", "tgid_name", "freq", "srcaddr",
|
||||||
|
"started_at", "started_at_epoch", "attributed", "driver")
|
||||||
|
if key in data
|
||||||
|
}
|
||||||
|
await mqtt_manager.publish_metadata("call_start", start_payload)
|
||||||
await mqtt_manager.publish_metadata("call_end", data)
|
await mqtt_manager.publish_metadata("call_end", data)
|
||||||
await mqtt_manager.publish_status("online")
|
await mqtt_manager.publish_status("online")
|
||||||
|
|
||||||
@@ -225,6 +272,10 @@ async def lifespan(app: FastAPI):
|
|||||||
# Wire callbacks
|
# Wire callbacks
|
||||||
metadata_watcher.on_call_start = on_call_start
|
metadata_watcher.on_call_start = on_call_start
|
||||||
metadata_watcher.on_call_end = on_call_end
|
metadata_watcher.on_call_end = on_call_end
|
||||||
|
# Segment boundaries come from the audio itself; this is how the watcher
|
||||||
|
# sees it. Without this the watcher falls back to control-channel
|
||||||
|
# segmentation, which is measurably wrong in both directions.
|
||||||
|
metadata_watcher.audio_activity = call_recorder.audio_activity
|
||||||
mqtt_manager.on_command = on_command
|
mqtt_manager.on_command = on_command
|
||||||
mqtt_manager.on_config_push = on_config_push
|
mqtt_manager.on_config_push = on_config_push
|
||||||
mqtt_manager.on_api_key = on_api_key
|
mqtt_manager.on_api_key = on_api_key
|
||||||
|
|||||||
@@ -49,9 +49,16 @@ async def get_status():
|
|||||||
"system_name": system_name,
|
"system_name": system_name,
|
||||||
"is_recording": call_recorder.is_recording,
|
"is_recording": call_recorder.is_recording,
|
||||||
# Health of the PulseAudio capture that feeds every recording — the single
|
# Health of the PulseAudio capture that feeds every recording — the single
|
||||||
# most useful signal when recordings come back empty.
|
# most useful signal when recordings come back empty. Segment boundaries
|
||||||
|
# come from this stream, so audio_silence_seconds is also how far the
|
||||||
|
# node currently is from closing whatever it is recording.
|
||||||
"audio_capture": call_recorder.is_capturing,
|
"audio_capture": call_recorder.is_capturing,
|
||||||
"buffered_seconds": round(call_recorder.buffered_seconds, 1),
|
"buffered_seconds": round(call_recorder.buffered_seconds, 1),
|
||||||
|
"audio_silence_seconds": round(call_recorder.audio_activity().silence_seconds, 1),
|
||||||
|
# Audio that was recorded but had no OP25 talkgroup anywhere near it, so
|
||||||
|
# it was discarded rather than uploaded. Non-zero means either the
|
||||||
|
# console is not decoding or something else is feeding drb_sink.
|
||||||
|
"unattributed_segments": metadata_watcher.unattributed_segments,
|
||||||
"active_tgid": active_tgid,
|
"active_tgid": active_tgid,
|
||||||
"active_tgid_name": active_tgid_name,
|
"active_tgid_name": active_tgid_name,
|
||||||
"active_call_id": metadata_watcher.active_call_id,
|
"active_call_id": metadata_watcher.active_call_id,
|
||||||
|
|||||||
@@ -1,160 +1,218 @@
|
|||||||
"""
|
"""
|
||||||
Unit tests for silence-trim decision logic.
|
Unit tests for silence trimming, now a byte-offset slice of raw PCM.
|
||||||
|
|
||||||
`speech_bounds` is pure on purpose so the "what do we keep" decision — the part
|
`keep_window` is pure on purpose so the "what do we keep" decision — the part
|
||||||
that can destroy a transmission if it is wrong — is testable without FFmpeg.
|
that can destroy a transmission if it is wrong — stays testable without any
|
||||||
The numbers below come from ffmpeg silencedetect run against six real recordings
|
audio at all. The rest of the file drives the real detector over synthesised
|
||||||
off a live P25 node: 1.71–2.45 s of leading silence and 0.00–1.11 s trailing.
|
buffers shaped like the six real recordings measured off a live P25 node:
|
||||||
|
1.71-2.45 s of leading silence and 0.00-1.11 s trailing.
|
||||||
|
|
||||||
|
The old implementation shelled out to FFmpeg twice (silencedetect, then a
|
||||||
|
re-encode) and these tests parsed its stderr. Both passes are gone; the recorder
|
||||||
|
buffers PCM, so detection is arithmetic and the cut is a slice.
|
||||||
"""
|
"""
|
||||||
|
from array import array
|
||||||
|
|
||||||
import pytest
|
import pytest
|
||||||
|
|
||||||
|
from app.config import settings
|
||||||
|
from app.internal import audio_trim, pcm
|
||||||
from app.internal.audio_trim import (
|
from app.internal.audio_trim import (
|
||||||
TrimResult,
|
TrimResult,
|
||||||
_parse_duration,
|
first_signal_offset,
|
||||||
_parse_silences,
|
keep_window,
|
||||||
speech_bounds,
|
last_signal_offset,
|
||||||
|
trim_pcm,
|
||||||
)
|
)
|
||||||
|
|
||||||
GUARD = 0.25
|
GUARD = 0.25
|
||||||
|
SPEECH_LEVEL = 4096 # -18 dBFS, the measured field average
|
||||||
|
FLOOR_LEVEL = 1 # -90.3 dBFS, the measured digital-silence floor
|
||||||
|
|
||||||
|
|
||||||
def test_leading_silence_is_trimmed_with_a_guard_margin():
|
def speech(seconds: float) -> bytes:
|
||||||
# Real shape of file f4bfaa1f: 1.85s lead, 0.34s trail, 4.54s total.
|
count = int(pcm.SAMPLE_RATE * seconds)
|
||||||
regions = [(0.0, 1.85), (4.20, None)]
|
return array("h", [SPEECH_LEVEL, -SPEECH_LEVEL] * (count // 2)).tobytes()
|
||||||
start, end, all_silence = speech_bounds(regions, duration=4.54, guard=GUARD)
|
|
||||||
|
|
||||||
assert not all_silence
|
|
||||||
assert start == pytest.approx(1.85 - GUARD)
|
|
||||||
assert end == pytest.approx(4.20 + GUARD)
|
|
||||||
# The guard must never eat into detected speech.
|
|
||||||
assert start < 1.85 and end > 4.20
|
|
||||||
|
|
||||||
|
|
||||||
def test_guard_margin_never_runs_past_the_file_bounds():
|
def silence(seconds: float, level: int = FLOOR_LEVEL) -> bytes:
|
||||||
regions = [(0.0, 0.10), (3.95, None)]
|
count = int(pcm.SAMPLE_RATE * seconds)
|
||||||
start, end, _ = speech_bounds(regions, duration=4.0, guard=1.0)
|
return array("h", [level, -level] * (count // 2)).tobytes()
|
||||||
|
|
||||||
assert start == 0.0
|
|
||||||
assert end == 4.0
|
|
||||||
|
|
||||||
|
|
||||||
def test_trailing_silence_is_trimmed_when_ffmpeg_closes_the_region_at_eof():
|
|
||||||
"""
|
|
||||||
FFmpeg 6.x flushes a `silence_end` at EOF, so a trailing region looks closed.
|
|
||||||
Treating "no silence_end" as the only trailing signal silently disabled tail
|
|
||||||
trimming entirely — verified against ffmpeg 6.1.1.
|
|
||||||
"""
|
|
||||||
# Real ffmpeg 6.1.1 output for a 2s-silence + 1.5s-tone + 1s-silence file.
|
|
||||||
regions = [(0.0, 2.05361), (3.56367, 4.63102)]
|
|
||||||
start, end, all_silence = speech_bounds(regions, duration=4.65, guard=GUARD)
|
|
||||||
|
|
||||||
assert not all_silence
|
|
||||||
assert start == pytest.approx(2.05361 - GUARD)
|
|
||||||
assert end == pytest.approx(3.56367 + GUARD), "the trailing second must be trimmed"
|
|
||||||
|
|
||||||
|
|
||||||
def test_all_silence_survives_ffmpeg_closing_the_region_at_eof():
|
|
||||||
# Real ffmpeg 6.1.1 output for a 4s file of pure silence.
|
|
||||||
_, _, all_silence = speech_bounds([(0.0, 4.0)], duration=4.03, guard=GUARD)
|
|
||||||
assert all_silence
|
|
||||||
|
|
||||||
|
|
||||||
def test_trailing_silence_that_does_not_reach_eof_is_left_alone():
|
|
||||||
"""
|
|
||||||
A silence region with a closing silence_end is an internal pause between
|
|
||||||
transmissions, not dead air at the tail. Trimming it would cut the middle
|
|
||||||
out of a conversation.
|
|
||||||
"""
|
|
||||||
regions = [(0.0, 1.9), (5.0, 7.5)]
|
|
||||||
start, end, _ = speech_bounds(regions, duration=12.0, guard=GUARD)
|
|
||||||
|
|
||||||
assert start == pytest.approx(1.9 - GUARD)
|
|
||||||
assert end == 12.0, "an internal pause must not shorten the file"
|
|
||||||
|
|
||||||
|
|
||||||
def test_no_silence_detected_keeps_the_whole_file():
|
|
||||||
start, end, all_silence = speech_bounds([], duration=6.0, guard=GUARD)
|
|
||||||
|
|
||||||
assert (start, end) == (0.0, 6.0)
|
|
||||||
assert not all_silence
|
|
||||||
|
|
||||||
|
|
||||||
def test_silence_starting_late_is_not_treated_as_leading():
|
|
||||||
"""Only a region at the very head counts as leading silence."""
|
|
||||||
regions = [(1.20, 2.00)]
|
|
||||||
start, end, _ = speech_bounds(regions, duration=5.0, guard=GUARD)
|
|
||||||
|
|
||||||
assert start == 0.0, "speech before 1.20s must not be trimmed away"
|
|
||||||
assert end == 5.0
|
|
||||||
|
|
||||||
|
|
||||||
def test_all_silence_is_reported_not_trimmed_to_nothing():
|
|
||||||
# One region covering the whole file and running to EOF.
|
|
||||||
regions = [(0.0, None)]
|
|
||||||
start, end, all_silence = speech_bounds(regions, duration=4.0, guard=GUARD)
|
|
||||||
|
|
||||||
assert all_silence
|
|
||||||
assert (start, end) == (0.0, 4.0), "an all-silence file must not become zero-length"
|
|
||||||
|
|
||||||
|
|
||||||
def test_all_silence_when_head_and_tail_regions_overlap():
|
|
||||||
regions = [(0.0, 3.2), (3.0, None)]
|
|
||||||
_, _, all_silence = speech_bounds(regions, duration=4.0, guard=GUARD)
|
|
||||||
|
|
||||||
assert all_silence
|
|
||||||
|
|
||||||
|
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
# FFmpeg output parsing
|
# keep_window — the pure decision
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
# Verbatim shape of ffmpeg 6.1.1 output.
|
def test_guard_margin_is_kept_around_detected_speech():
|
||||||
FFMPEG_STDERR = """
|
guard = pcm.byte_offset(GUARD)
|
||||||
Input #0, mp3, from '/recordings/x.mp3':
|
start, end = keep_window(
|
||||||
Duration: 00:00:04.70, start: 0.050113, bitrate: 16 kb/s
|
first_signal=pcm.byte_offset(1.85),
|
||||||
[silencedetect @ 0000029160e63f40] silence_start: 0
|
last_signal=pcm.byte_offset(4.20),
|
||||||
[silencedetect @ 0000029160e63f40] silence_end: 2.05361 | silence_duration: 2.05361
|
total_bytes=pcm.byte_offset(4.54),
|
||||||
[silencedetect @ 0000029160e63f40] silence_start: 3.56367
|
guard_bytes=guard,
|
||||||
[silencedetect @ 0000029160e63f40] silence_end: 4.63102 | silence_duration: 1.06735
|
)
|
||||||
[out#0/null @ 0x2] video:0kB audio:97kB
|
assert pcm.seconds(start) == pytest.approx(1.85 - GUARD, abs=0.001)
|
||||||
|
assert pcm.seconds(end) == pytest.approx(4.20 + GUARD, abs=0.001)
|
||||||
|
|
||||||
|
|
||||||
|
def test_guard_margin_never_runs_past_the_buffer_bounds():
|
||||||
|
total = pcm.byte_offset(4.0)
|
||||||
|
start, end = keep_window(
|
||||||
|
first_signal=pcm.byte_offset(0.10),
|
||||||
|
last_signal=pcm.byte_offset(3.95),
|
||||||
|
total_bytes=total,
|
||||||
|
guard_bytes=pcm.byte_offset(1.0),
|
||||||
|
)
|
||||||
|
assert (start, end) == (0, total)
|
||||||
|
|
||||||
|
|
||||||
|
def test_keep_window_offsets_are_sample_aligned():
|
||||||
|
start, end = keep_window(3, 9, 21, 1)
|
||||||
|
assert start % pcm.FRAME_BYTES == 0
|
||||||
|
assert end % pcm.FRAME_BYTES == 0
|
||||||
|
|
||||||
|
|
||||||
|
def test_no_signal_found_keeps_everything():
|
||||||
|
total = pcm.byte_offset(6.0)
|
||||||
|
assert keep_window(None, None, total, pcm.byte_offset(GUARD)) == (0, total)
|
||||||
|
|
||||||
|
|
||||||
|
def test_an_inverted_window_degrades_to_keeping_everything():
|
||||||
|
"""Never return an empty slice, whatever the inputs say."""
|
||||||
|
total = pcm.byte_offset(4.0)
|
||||||
|
assert keep_window(pcm.byte_offset(3.0), pcm.byte_offset(0.5), total, 0) == (0, total)
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Scanning
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
def test_first_and_last_signal_are_found_in_a_realistic_recording():
|
||||||
|
audio = silence(1.85) + speech(2.35) + silence(0.34)
|
||||||
|
threshold = -40.0
|
||||||
|
|
||||||
|
first = first_signal_offset(audio, threshold)
|
||||||
|
last = last_signal_offset(audio, threshold)
|
||||||
|
|
||||||
|
assert pcm.seconds(first) == pytest.approx(1.85, abs=audio_trim.ANALYSIS_WINDOW_SECONDS)
|
||||||
|
assert pcm.seconds(last) == pytest.approx(4.20, abs=audio_trim.ANALYSIS_WINDOW_SECONDS)
|
||||||
|
|
||||||
|
|
||||||
|
def test_internal_pauses_are_not_treated_as_the_tail():
|
||||||
|
"""Trimming the middle out of a conversation would be unrecoverable."""
|
||||||
|
audio = silence(1.9) + speech(3.1) + silence(2.5) + speech(4.5)
|
||||||
|
last = last_signal_offset(audio, -40.0)
|
||||||
|
assert pcm.seconds(last) == pytest.approx(12.0, abs=audio_trim.ANALYSIS_WINDOW_SECONDS)
|
||||||
|
|
||||||
|
|
||||||
|
def test_all_silence_returns_no_signal_offset():
|
||||||
|
assert first_signal_offset(silence(4.0), -40.0) is None
|
||||||
|
assert last_signal_offset(silence(4.0), -40.0) is None
|
||||||
|
|
||||||
|
|
||||||
|
def test_the_scan_is_bounded_so_a_long_buffer_cannot_stall_the_upload():
|
||||||
|
"""The per-sample loop is the only unbounded cost; it must have a ceiling."""
|
||||||
|
audio = silence(2.0)
|
||||||
|
assert first_signal_offset(audio, -40.0, limit_seconds=0.5) is None
|
||||||
|
assert first_signal_offset(speech(0.1) + silence(1.9), -40.0, limit_seconds=0.5) == 0
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# trim_pcm — end to end over synthesised audio
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
def test_leading_and_trailing_silence_are_trimmed_to_the_guard_margin():
|
||||||
|
audio = silence(1.85) + speech(2.35) + silence(0.34)
|
||||||
|
kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||||
|
|
||||||
|
assert result.applied and not result.all_silence
|
||||||
|
assert result.lead == pytest.approx(1.85 - GUARD, abs=0.05)
|
||||||
|
assert result.tail == pytest.approx(0.34 - GUARD, abs=0.05)
|
||||||
|
assert pcm.seconds(len(kept)) == pytest.approx(result.duration_after, abs=0.001)
|
||||||
|
assert result.duration_after < result.duration_before
|
||||||
|
|
||||||
|
|
||||||
|
def test_the_guard_margin_never_eats_into_speech():
|
||||||
|
audio = silence(2.0) + speech(1.0) + silence(2.0)
|
||||||
|
kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||||
|
|
||||||
|
# Everything removed from the head must be silence, and the first sample of
|
||||||
|
# real speech must survive.
|
||||||
|
assert result.lead < 2.0
|
||||||
|
assert pcm.seconds(len(kept)) > 1.0
|
||||||
|
|
||||||
|
|
||||||
|
def test_measured_trailing_silence_is_reported_for_field_tuning():
|
||||||
"""
|
"""
|
||||||
|
The recorder deliberately over-captures the tail (it closes only after the
|
||||||
FFMPEG_STDERR_OPEN_TAIL = """
|
silence timeout has actually elapsed in the audio), so `tail` is how the
|
||||||
Duration: 00:00:04.54, start: 0.000000, bitrate: 16 kb/s
|
real silence run reaches the logs.
|
||||||
[silencedetect @ 0x1] silence_start: 0
|
|
||||||
[silencedetect @ 0x1] silence_end: 1.85042 | silence_duration: 1.85042
|
|
||||||
[silencedetect @ 0x1] silence_start: 4.20134
|
|
||||||
"""
|
"""
|
||||||
|
audio = silence(0.5) + speech(2.0) + silence(3.0)
|
||||||
|
_, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||||
|
assert result.tail == pytest.approx(3.0 - GUARD, abs=0.05)
|
||||||
|
assert result.trimmed_seconds == pytest.approx(result.lead + result.tail)
|
||||||
|
|
||||||
|
|
||||||
def test_duration_is_corrected_for_the_mp3_container_start_offset():
|
def test_an_all_silence_buffer_is_reported_not_truncated_to_nothing():
|
||||||
|
audio = silence(4.0)
|
||||||
|
kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||||
|
|
||||||
|
assert result.all_silence
|
||||||
|
assert not result.applied
|
||||||
|
assert kept == audio, "an all-silence recording must not become zero-length"
|
||||||
|
|
||||||
|
|
||||||
|
def test_digital_silence_at_the_measured_field_floor_is_detected():
|
||||||
"""
|
"""
|
||||||
MP3 encoder delay makes the container duration longer than the audio
|
The -91 dBFS floor is the whole reason this needs no field calibration.
|
||||||
silencedetect timestamps. Without this correction the trailing-region test
|
Detection must not depend on the threshold being tuned to a noise floor.
|
||||||
needs a slack epsilon big enough to clip real speech.
|
|
||||||
"""
|
"""
|
||||||
assert _parse_duration(FFMPEG_STDERR) == pytest.approx(4.70 - 0.050113)
|
audio = silence(1.0, level=1) + speech(1.0) + silence(1.0, level=1)
|
||||||
|
for threshold in (-70.0, -60.0, -50.0, -40.0):
|
||||||
|
_, result = trim_pcm(audio, threshold_db=threshold, guard=GUARD)
|
||||||
|
assert result.applied, f"threshold {threshold} should still find the speech"
|
||||||
|
assert result.lead == pytest.approx(0.75, abs=0.05)
|
||||||
|
|
||||||
|
|
||||||
def test_duration_is_none_when_absent():
|
def test_audio_with_no_silence_at_either_end_is_left_alone():
|
||||||
assert _parse_duration("no duration here") is None
|
audio = speech(3.0)
|
||||||
|
kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||||
|
|
||||||
|
assert not result.applied
|
||||||
|
assert kept == audio
|
||||||
|
assert result.duration_before == pytest.approx(result.duration_after)
|
||||||
|
|
||||||
|
|
||||||
def test_silence_regions_are_parsed():
|
def test_an_empty_buffer_is_handled():
|
||||||
regions = _parse_silences(FFMPEG_STDERR)
|
kept, result = trim_pcm(b"", threshold_db=-40.0, guard=GUARD)
|
||||||
|
assert kept == b"" and not result.applied and not result.all_silence
|
||||||
assert len(regions) == 2
|
|
||||||
assert regions[0] == (pytest.approx(0.0), pytest.approx(2.05361))
|
|
||||||
assert regions[1] == (pytest.approx(3.56367), pytest.approx(4.63102))
|
|
||||||
|
|
||||||
|
|
||||||
def test_a_region_with_no_silence_end_is_still_parsed():
|
def test_thresholds_default_to_settings():
|
||||||
"""Older FFmpeg simply stopped reporting at EOF — keep handling that."""
|
audio = silence(1.0) + speech(1.0) + silence(1.0)
|
||||||
regions = _parse_silences(FFMPEG_STDERR_OPEN_TAIL)
|
_, result = trim_pcm(audio)
|
||||||
|
assert result.applied
|
||||||
|
assert settings.trim_silence_threshold_db == -40.0
|
||||||
|
assert settings.trim_silence_guard_seconds == 0.25
|
||||||
|
assert result.lead == pytest.approx(1.0 - settings.trim_silence_guard_seconds, abs=0.05)
|
||||||
|
|
||||||
assert regions[-1][1] is None
|
|
||||||
|
def test_a_scan_that_gives_up_leaves_the_audio_untouched_and_says_so():
|
||||||
|
"""
|
||||||
|
Refusing to guess is the point: an untrimmed upload is always better than a
|
||||||
|
wrongly-truncated one, and better than dropping a call as "all silence"
|
||||||
|
without having actually looked at all of it.
|
||||||
|
"""
|
||||||
|
long_silence = silence(audio_trim.MAX_SCAN_SECONDS + 5.0)
|
||||||
|
kept, result = trim_pcm(long_silence, threshold_db=-40.0, guard=GUARD)
|
||||||
|
|
||||||
|
assert result.scan_truncated
|
||||||
|
assert not result.all_silence
|
||||||
|
assert not result.applied
|
||||||
|
assert kept == long_silence
|
||||||
|
|
||||||
|
|
||||||
def test_trim_result_reports_total_trimmed():
|
def test_trim_result_reports_total_trimmed():
|
||||||
result = TrimResult(path=None, lead=1.9, tail=0.35)
|
assert TrimResult(lead=1.9, tail=0.35).trimmed_seconds == pytest.approx(2.25)
|
||||||
assert result.trimmed_seconds == pytest.approx(2.25)
|
|
||||||
|
|||||||
@@ -1,13 +1,17 @@
|
|||||||
"""
|
"""
|
||||||
Unit tests for the CallRecorder pre-roll ring buffer and per-call accumulator.
|
Unit tests for the CallRecorder: PCM ring buffer, per-call accumulator, the
|
||||||
|
continuous voice-activity signal the segmenter reads, and the single encode.
|
||||||
|
|
||||||
No FFmpeg and no PulseAudio: chunks are pushed through _ingest() with a patched
|
No FFmpeg and no PulseAudio: chunks are pushed through _ingest() with a patched
|
||||||
clock, which is exactly what the capture loop does at runtime. Silence trimming
|
clock, which is exactly what the capture loop does at runtime, and the MP3
|
||||||
is disabled by default here and exercised separately with a stubbed trimmer.
|
encoder is replaced with a stub that writes the raw PCM it was handed. That stub
|
||||||
|
is also how "exactly one encode per call" is asserted — the old design captured
|
||||||
|
MP3 and then re-encoded it to trim, so every upload was double-encoded.
|
||||||
"""
|
"""
|
||||||
import asyncio
|
import asyncio
|
||||||
import itertools
|
import itertools
|
||||||
import time
|
import time
|
||||||
|
from array import array
|
||||||
from typing import List
|
from typing import List
|
||||||
from unittest.mock import patch
|
from unittest.mock import patch
|
||||||
|
|
||||||
@@ -15,7 +19,7 @@ import pytest
|
|||||||
|
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
from app.internal import call_recorder as recorder_mod
|
from app.internal import call_recorder as recorder_mod
|
||||||
from app.internal.audio_trim import TrimResult
|
from app.internal import pcm
|
||||||
from app.internal.call_recorder import (
|
from app.internal.call_recorder import (
|
||||||
CallRecorder,
|
CallRecorder,
|
||||||
MAX_RECORDING_BYTES,
|
MAX_RECORDING_BYTES,
|
||||||
@@ -25,11 +29,42 @@ from app.internal.call_recorder import (
|
|||||||
)
|
)
|
||||||
|
|
||||||
T0 = 1_700_000_000.0
|
T0 = 1_700_000_000.0
|
||||||
CHUNK_INTERVAL = 0.1 # seconds of audio per synthetic chunk
|
|
||||||
|
# One synthetic chunk carries exactly CHUNK_INTERVAL seconds of audio AND
|
||||||
|
# arrives CHUNK_INTERVAL apart, so arrival-timestamp arithmetic (slicing) and
|
||||||
|
# byte-offset arithmetic (trimming) agree with each other.
|
||||||
|
CHUNK_INTERVAL = 0.1
|
||||||
|
CHUNK_SAMPLES = int(pcm.SAMPLE_RATE * CHUNK_INTERVAL)
|
||||||
|
CHUNK_BYTES = CHUNK_SAMPLES * pcm.FRAME_BYTES
|
||||||
|
|
||||||
|
SPEECH_LEVEL = 4096 # -18 dBFS, the measured field average
|
||||||
|
FLOOR_LEVEL = 1 # -90.3 dBFS, the measured digital-silence floor
|
||||||
|
|
||||||
|
|
||||||
|
def block(level: int, samples: int = CHUNK_SAMPLES) -> bytes:
|
||||||
|
return array("h", [level, -level] * (samples // 2)).tobytes()
|
||||||
|
|
||||||
|
|
||||||
|
VOICE = block(SPEECH_LEVEL)
|
||||||
|
QUIET = block(FLOOR_LEVEL)
|
||||||
|
|
||||||
|
|
||||||
@pytest.fixture
|
@pytest.fixture
|
||||||
def recorder(tmp_path, monkeypatch):
|
def encodes(monkeypatch):
|
||||||
|
"""Replace the one encode with a stub that writes the PCM it was given."""
|
||||||
|
calls: List[tuple] = []
|
||||||
|
|
||||||
|
async def _encode(audio: bytes, path):
|
||||||
|
calls.append((audio, path))
|
||||||
|
path.write_bytes(audio)
|
||||||
|
return True
|
||||||
|
|
||||||
|
monkeypatch.setattr(recorder_mod, "encode_mp3", _encode)
|
||||||
|
return calls
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.fixture
|
||||||
|
def recorder(tmp_path, monkeypatch, encodes):
|
||||||
monkeypatch.setattr(settings, "trim_silence", False)
|
monkeypatch.setattr(settings, "trim_silence", False)
|
||||||
r = CallRecorder()
|
r = CallRecorder()
|
||||||
r._recordings_dir = tmp_path
|
r._recordings_dir = tmp_path
|
||||||
@@ -37,64 +72,51 @@ def recorder(tmp_path, monkeypatch):
|
|||||||
return r
|
return r
|
||||||
|
|
||||||
|
|
||||||
def ingest(recorder, start: float, end: float, marker: bytes = b"A", index: int = 0) -> int:
|
def ingest(recorder, start: float, end: float, chunk: bytes = VOICE) -> None:
|
||||||
"""Feed one chunk every CHUNK_INTERVAL seconds over [start, end) through _ingest."""
|
"""Feed one chunk every CHUNK_INTERVAL seconds over [start, end)."""
|
||||||
stamps: List[float] = []
|
stamps: List[float] = []
|
||||||
chunks: List[bytes] = []
|
|
||||||
ts = start
|
ts = start
|
||||||
while ts < end:
|
while ts < end:
|
||||||
stamps.append(ts)
|
stamps.append(ts)
|
||||||
chunks.append(marker + str(index).encode() + b";")
|
|
||||||
index += 1
|
|
||||||
ts = round(ts + CHUNK_INTERVAL, 6)
|
ts = round(ts + CHUNK_INTERVAL, 6)
|
||||||
|
if not stamps:
|
||||||
|
return
|
||||||
with patch("app.internal.call_recorder.time.time", side_effect=stamps):
|
with patch("app.internal.call_recorder.time.time", side_effect=stamps):
|
||||||
for chunk in chunks:
|
for _ in stamps:
|
||||||
recorder._ingest(chunk)
|
recorder._ingest(chunk)
|
||||||
return index
|
|
||||||
|
|
||||||
|
|
||||||
def fill(recorder, start: float, end: float, marker: bytes = b"A", index: int = 0) -> int:
|
def duration_of(path) -> float:
|
||||||
"""Alias kept for readability where the accumulator is not the point."""
|
return pcm.seconds(len(path.read_bytes()))
|
||||||
return ingest(recorder, start, end, marker=marker, index=index)
|
|
||||||
|
|
||||||
|
|
||||||
def timestamps(recorder):
|
def timestamps(recorder):
|
||||||
return [ts for ts, _ in recorder._buffer]
|
return [ts for ts, _ in recorder._buffer]
|
||||||
|
|
||||||
|
|
||||||
def markers(path) -> List[str]:
|
|
||||||
return path.read_bytes().decode().strip(";").split(";")
|
|
||||||
|
|
||||||
|
|
||||||
def indices(path) -> List[int]:
|
|
||||||
return [int(m[1:]) for m in markers(path) if m[1:].isdigit()]
|
|
||||||
|
|
||||||
|
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
# Ring buffer trimming (pre-roll duty only)
|
# Ring buffer trimming (pre-roll duty only)
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
def test_idle_buffer_keeps_only_the_rolling_window(recorder):
|
def test_idle_buffer_keeps_only_the_rolling_window(recorder):
|
||||||
for offset in range(0, int(RING_BUFFER_SECONDS) + 20):
|
ingest(recorder, T0, T0 + RING_BUFFER_SECONDS + 20)
|
||||||
with patch("app.internal.call_recorder.time.time", return_value=T0 + offset):
|
|
||||||
recorder._ingest(b"x" * 16)
|
|
||||||
|
|
||||||
assert len(recorder._buffer) <= RING_BUFFER_SECONDS + 1
|
assert recorder.buffered_seconds <= RING_BUFFER_SECONDS + CHUNK_INTERVAL
|
||||||
assert min(timestamps(recorder)) >= (T0 + RING_BUFFER_SECONDS + 19) - RING_BUFFER_SECONDS
|
newest = max(timestamps(recorder))
|
||||||
|
assert min(timestamps(recorder)) >= newest - RING_BUFFER_SECONDS
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_ring_buffer_is_trimmed_even_while_recording(recorder):
|
async def test_ring_buffer_is_trimmed_even_while_recording(recorder):
|
||||||
"""
|
"""
|
||||||
The ring buffer serves PRE-ROLL only. An open recording must no longer pin
|
The ring buffer serves PRE-ROLL only. An open recording must not pin it —
|
||||||
it — that was the mechanism that made call length depend on buffer size.
|
that was the mechanism that made call length depend on buffer size.
|
||||||
"""
|
"""
|
||||||
index = ingest(recorder, T0, T0 + 2.0)
|
ingest(recorder, T0, T0 + 2.0)
|
||||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
ingest(recorder, T0 + 2.0, T0 + 2.0 + RING_BUFFER_SECONDS + 10, index=index)
|
ingest(recorder, T0 + 2.0, T0 + 2.0 + RING_BUFFER_SECONDS + 10)
|
||||||
|
|
||||||
assert recorder.buffered_seconds <= RING_BUFFER_SECONDS + 1
|
assert recorder.buffered_seconds <= RING_BUFFER_SECONDS + CHUNK_INTERVAL
|
||||||
# ...and the audio the ring buffer dropped is safe in the accumulator.
|
# ...and the audio the ring buffer dropped is safe in the accumulator.
|
||||||
assert recorder._active is not None
|
assert recorder._active is not None
|
||||||
assert recorder._active.chunks[0][0] == pytest.approx(T0 + 1.0 - PRE_ROLL_SECONDS, abs=CHUNK_INTERVAL)
|
assert recorder._active.chunks[0][0] == pytest.approx(T0 + 1.0 - PRE_ROLL_SECONDS, abs=CHUNK_INTERVAL)
|
||||||
@@ -110,19 +132,16 @@ async def test_call_longer_than_the_ring_buffer_is_captured_whole(recorder):
|
|||||||
grant = T0 + 1.0
|
grant = T0 + 1.0
|
||||||
end = grant + call_length
|
end = grant + call_length
|
||||||
|
|
||||||
index = ingest(recorder, T0, grant)
|
ingest(recorder, T0, grant)
|
||||||
await recorder.start_recording("call-long", start_epoch=grant)
|
await recorder.start_recording("call-long", start_epoch=grant)
|
||||||
ingest(recorder, grant, end + 1.0, index=index)
|
ingest(recorder, grant, end + 1.0)
|
||||||
|
|
||||||
rec = await recorder.stop_recording(end_epoch=end)
|
rec = await recorder.stop_recording(end_epoch=end)
|
||||||
assert rec is not None and rec.path is not None
|
assert rec is not None and rec.path is not None
|
||||||
|
|
||||||
kept = indices(rec.path)
|
captured = duration_of(rec.path)
|
||||||
# Contiguous: no hole anywhere in the middle of a 65s call.
|
assert captured > RING_BUFFER_SECONDS, "call length must not be clamped by the ring buffer"
|
||||||
assert kept == list(range(kept[0], kept[-1] + 1))
|
assert captured == pytest.approx(call_length + PRE_ROLL_SECONDS, abs=2 * CHUNK_INTERVAL)
|
||||||
span = (kept[-1] - kept[0]) * CHUNK_INTERVAL
|
|
||||||
assert span > RING_BUFFER_SECONDS, "call length must not be clamped by the ring buffer"
|
|
||||||
assert span == pytest.approx(call_length + PRE_ROLL_SECONDS, abs=2 * CHUNK_INTERVAL)
|
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
@@ -130,8 +149,12 @@ async def test_accumulator_stops_growing_at_the_memory_ceiling(recorder, caplog)
|
|||||||
"""A runaway call must not be able to exhaust RAM on a Pi."""
|
"""A runaway call must not be able to exhaust RAM on a Pi."""
|
||||||
await recorder.start_recording("call-runaway", start_epoch=T0)
|
await recorder.start_recording("call-runaway", start_epoch=T0)
|
||||||
|
|
||||||
big = b"z" * 64_000
|
# Silent blocks on purpose: this test is about bytes, not content, and the
|
||||||
|
# all-zero fast path keeps it from spending seconds in the RMS loop.
|
||||||
|
big = b"\x00" * 64_000
|
||||||
needed = (MAX_RECORDING_BYTES // len(big)) + 5
|
needed = (MAX_RECORDING_BYTES // len(big)) + 5
|
||||||
|
# An unbounded clock: patching time.time patches it for everything running
|
||||||
|
# inside the block, not only for our calls.
|
||||||
ticks = itertools.count()
|
ticks = itertools.count()
|
||||||
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
||||||
with patch("app.internal.call_recorder.time.time",
|
with patch("app.internal.call_recorder.time.time",
|
||||||
@@ -145,73 +168,133 @@ async def test_accumulator_stops_growing_at_the_memory_ceiling(recorder, caplog)
|
|||||||
assert any("memory ceiling" in r.message for r in caplog.records)
|
assert any("memory ceiling" in r.message for r in caplog.records)
|
||||||
|
|
||||||
|
|
||||||
|
def test_the_byte_ceiling_can_never_truncate_a_legal_call():
|
||||||
|
"""
|
||||||
|
PCM costs 44.1 KB/s where MP3 cost 2 KB/s, so this had to be re-derived.
|
||||||
|
The TIME cap must always bite before the BYTE cap, or a long pursuit would
|
||||||
|
be silently cut short by a memory limit.
|
||||||
|
"""
|
||||||
|
assert MAX_RECORDING_BYTES > MAX_RECORDING_SECONDS * pcm.BYTES_PER_SECOND
|
||||||
|
# ...and it still has to be a deliberate, bounded number on a Pi.
|
||||||
|
assert MAX_RECORDING_BYTES <= 48 * 1024 * 1024
|
||||||
|
|
||||||
|
|
||||||
|
def test_the_ring_buffer_memory_cost_is_bounded():
|
||||||
|
assert RING_BUFFER_SECONDS * pcm.BYTES_PER_SECOND < 2 * 1024 * 1024
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Voice activity — the signal the segmenter starts and stops on
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
def test_digital_silence_produces_no_voice_marks(recorder):
|
||||||
|
ingest(recorder, T0, T0 + 5.0, chunk=QUIET)
|
||||||
|
|
||||||
|
activity = recorder.audio_activity()
|
||||||
|
assert activity.last_voice_epoch is None
|
||||||
|
assert activity.voice_onset_epoch is None
|
||||||
|
|
||||||
|
|
||||||
|
def test_voice_onset_is_the_arrival_of_the_first_non_silent_chunk(recorder):
|
||||||
|
ingest(recorder, T0, T0 + 2.0, chunk=QUIET)
|
||||||
|
ingest(recorder, T0 + 2.0, T0 + 3.0, chunk=VOICE)
|
||||||
|
|
||||||
|
activity = recorder.audio_activity()
|
||||||
|
assert activity.voice_onset_epoch == pytest.approx(T0 + 2.0)
|
||||||
|
assert activity.last_voice_epoch == pytest.approx(T0 + 3.0 - CHUNK_INTERVAL)
|
||||||
|
|
||||||
|
|
||||||
|
def test_a_gap_shorter_than_the_silence_timeout_does_not_start_a_new_run(recorder, monkeypatch):
|
||||||
|
"""Back-and-forth inside the window is ONE run, hence one recording."""
|
||||||
|
monkeypatch.setattr(settings, "call_silence_timeout", 3.0)
|
||||||
|
ingest(recorder, T0, T0 + 1.0, chunk=VOICE)
|
||||||
|
ingest(recorder, T0 + 1.0, T0 + 2.5, chunk=QUIET)
|
||||||
|
ingest(recorder, T0 + 2.5, T0 + 3.5, chunk=VOICE)
|
||||||
|
|
||||||
|
assert recorder.audio_activity().voice_onset_epoch == pytest.approx(T0)
|
||||||
|
|
||||||
|
|
||||||
|
def test_a_gap_longer_than_the_silence_timeout_starts_a_new_run(recorder, monkeypatch):
|
||||||
|
monkeypatch.setattr(settings, "call_silence_timeout", 3.0)
|
||||||
|
ingest(recorder, T0, T0 + 1.0, chunk=VOICE)
|
||||||
|
ingest(recorder, T0 + 1.0, T0 + 6.0, chunk=QUIET)
|
||||||
|
ingest(recorder, T0 + 6.0, T0 + 7.0, chunk=VOICE)
|
||||||
|
|
||||||
|
assert recorder.audio_activity().voice_onset_epoch == pytest.approx(T0 + 6.0)
|
||||||
|
|
||||||
|
|
||||||
|
def test_activity_snapshot_reports_capture_and_recording_state(recorder):
|
||||||
|
activity = recorder.audio_activity()
|
||||||
|
assert activity.capturing is True
|
||||||
|
assert activity.recording is False
|
||||||
|
|
||||||
|
recorder._capturing = False
|
||||||
|
assert recorder.audio_activity().capturing is False
|
||||||
|
|
||||||
|
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
# Pre-roll and slicing
|
# Pre-roll and slicing
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_slice_starts_pre_roll_before_the_op25_timestamp(recorder):
|
async def test_slice_starts_pre_roll_before_the_detected_onset(recorder):
|
||||||
fill(recorder, T0, T0 + 10.0)
|
ingest(recorder, T0, T0 + 10.0)
|
||||||
grant_time = T0 + 5.0
|
onset = T0 + 5.0
|
||||||
|
|
||||||
await recorder.start_recording("call-1", start_epoch=grant_time)
|
await recorder.start_recording("call-1", start_epoch=onset)
|
||||||
assert recorder._active.slice_start == pytest.approx(grant_time - PRE_ROLL_SECONDS)
|
assert recorder._active.slice_start == pytest.approx(onset - PRE_ROLL_SECONDS)
|
||||||
|
|
||||||
rec = await recorder.stop_recording(end_epoch=grant_time + 2.0)
|
rec = await recorder.stop_recording(end_epoch=onset + 2.0)
|
||||||
assert rec is not None and rec.path is not None and rec.path.exists()
|
assert rec is not None and rec.path is not None and rec.path.exists()
|
||||||
|
|
||||||
first_ts = T0 + indices(rec.path)[0] * CHUNK_INTERVAL
|
first_ts = recorder._active.chunks[0][0] if recorder._active else None
|
||||||
|
assert first_ts is None # recording closed
|
||||||
# A chunk stamped `ts` holds the audio that arrived over [ts - interval, ts],
|
# The audio actually covered must begin at or before the requested slice
|
||||||
# so the audio actually covered must begin at or before the requested slice
|
# start — erring early is safe, erring late loses speech.
|
||||||
# start — erring early is the safe direction, erring late loses speech.
|
assert rec.audio_start_epoch <= onset - PRE_ROLL_SECONDS + 1e-6
|
||||||
assert first_ts - CHUNK_INTERVAL <= grant_time - PRE_ROLL_SECONDS + 1e-6
|
|
||||||
# ...and no more than one chunk of extra pre-roll is dragged in.
|
|
||||||
assert first_ts >= grant_time - PRE_ROLL_SECONDS - 1e-6
|
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_tail_chunk_straddling_the_end_is_included(recorder):
|
async def test_tail_chunk_straddling_the_end_is_included(recorder):
|
||||||
fill(recorder, T0, T0 + 10.0)
|
ingest(recorder, T0, T0 + 10.0)
|
||||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
|
||||||
# End halfway through a chunk interval.
|
|
||||||
rec = await recorder.stop_recording(end_epoch=T0 + 3.05)
|
rec = await recorder.stop_recording(end_epoch=T0 + 3.05)
|
||||||
last_ts = T0 + indices(rec.path)[-1] * CHUNK_INTERVAL
|
|
||||||
|
|
||||||
assert last_ts >= T0 + 3.05, "the chunk covering the end instant must be kept"
|
# The chunk covering the end instant must be kept, so the captured audio
|
||||||
|
# reaches past the requested end rather than stopping short of it.
|
||||||
|
assert rec.audio_end_epoch >= T0 + 3.05
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_max_recording_seconds_caps_the_slice(recorder):
|
async def test_max_recording_seconds_caps_the_slice(recorder):
|
||||||
index = fill(recorder, T0, T0 + 1.0)
|
ingest(recorder, T0, T0 + 1.0)
|
||||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
ingest(recorder, T0 + 1.0, T0 + MAX_RECORDING_SECONDS + 60, index=index)
|
ingest(recorder, T0 + 1.0, T0 + MAX_RECORDING_SECONDS + 60)
|
||||||
|
|
||||||
rec = await recorder.stop_recording(end_epoch=T0 + MAX_RECORDING_SECONDS + 50)
|
rec = await recorder.stop_recording(end_epoch=T0 + MAX_RECORDING_SECONDS + 50)
|
||||||
last_ts = T0 + indices(rec.path)[-1] * CHUNK_INTERVAL
|
|
||||||
|
|
||||||
assert last_ts <= T0 + 1.0 + MAX_RECORDING_SECONDS + CHUNK_INTERVAL
|
assert duration_of(rec.path) <= MAX_RECORDING_SECONDS + PRE_ROLL_SECONDS + CHUNK_INTERVAL
|
||||||
|
|
||||||
|
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
# Tail wait — the fix for recordings that ended mid-word
|
# Tail wait — still needed for control-channel-derived ends (tgid splits)
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_stop_waits_for_captured_audio_to_reach_the_call_end(recorder, caplog):
|
async def test_stop_waits_for_captured_audio_to_reach_the_call_end(recorder, caplog):
|
||||||
"""
|
"""
|
||||||
PulseAudio → FFmpeg → encoder → muxer → our pipe read has latency, so at the
|
A tgid_change close pads past a control-channel timestamp that is ~now, so
|
||||||
instant a call ends the newest captured chunk is OLDER than the end epoch.
|
the audio it asks for has not been captured yet. Slicing immediately would
|
||||||
Slicing immediately cuts the last word off. stop_recording must wait for it.
|
cut the last word off.
|
||||||
"""
|
"""
|
||||||
index = ingest(recorder, T0, T0 + 4.0)
|
ingest(recorder, T0, T0 + 4.0)
|
||||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
|
||||||
async def late_tail():
|
async def late_tail():
|
||||||
await asyncio.sleep(0.15)
|
await asyncio.sleep(0.15)
|
||||||
with patch("app.internal.call_recorder.time.time", return_value=T0 + 4.6):
|
with patch("app.internal.call_recorder.time.time", return_value=T0 + 4.6):
|
||||||
recorder._ingest(b"TAIL;")
|
recorder._ingest(block(SPEECH_LEVEL))
|
||||||
|
|
||||||
task = asyncio.create_task(late_tail())
|
task = asyncio.create_task(late_tail())
|
||||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||||
@@ -219,10 +302,14 @@ async def test_stop_waits_for_captured_audio_to_reach_the_call_end(recorder, cap
|
|||||||
await task
|
await task
|
||||||
|
|
||||||
assert rec is not None and rec.path is not None
|
assert rec is not None and rec.path is not None
|
||||||
assert b"TAIL" in rec.path.read_bytes(), "the late-arriving tail must be in the file"
|
# The slice covers the chunks stamped T0+0.8 .. T0+3.9 (32 of them) plus the
|
||||||
|
# one that arrived late — and that last one is where the final word of the
|
||||||
|
# transmission lives. Without the wait it would have been cut.
|
||||||
|
chunk_seconds = pcm.seconds(len(VOICE))
|
||||||
|
assert duration_of(rec.path) == pytest.approx(33 * chunk_seconds, abs=0.01)
|
||||||
|
assert duration_of(rec.path) > 32 * chunk_seconds
|
||||||
assert any("Waited" in r.message and "tail" in r.message for r in caplog.records), \
|
assert any("Waited" in r.message and "tail" in r.message for r in caplog.records), \
|
||||||
"a tail wait must be observable in the field logs"
|
"a tail wait must be observable in the field logs"
|
||||||
assert index # sanity: the pre-roll fill actually ran
|
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
@@ -245,6 +332,10 @@ async def test_tail_wait_is_bounded_and_warns_when_audio_never_arrives(recorder,
|
|||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_no_wait_when_the_buffer_already_covers_the_end(recorder, caplog):
|
async def test_no_wait_when_the_buffer_already_covers_the_end(recorder, caplog):
|
||||||
|
"""
|
||||||
|
An audio-driven close derives its end epoch from audio that is already
|
||||||
|
buffered, so the common path must never pay the tail wait at all.
|
||||||
|
"""
|
||||||
ingest(recorder, T0, T0 + 10.0)
|
ingest(recorder, T0, T0 + 10.0)
|
||||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
|
||||||
@@ -261,7 +352,7 @@ async def test_no_wait_when_the_buffer_already_covers_the_end(recorder, caplog):
|
|||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_pre_roll_earlier_than_buffer_start_is_clamped_and_warned(recorder, caplog):
|
async def test_pre_roll_earlier_than_buffer_start_is_clamped_and_warned(recorder, caplog):
|
||||||
"""A grant older than anything buffered must still produce a file, loudly."""
|
"""An onset older than anything buffered must still produce a file, loudly."""
|
||||||
ingest(recorder, T0 + 5.0, T0 + 10.0) # buffer only covers T0+5 onwards
|
ingest(recorder, T0 + 5.0, T0 + 10.0) # buffer only covers T0+5 onwards
|
||||||
|
|
||||||
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
||||||
@@ -269,36 +360,87 @@ async def test_pre_roll_earlier_than_buffer_start_is_clamped_and_warned(recorder
|
|||||||
rec = await recorder.stop_recording(end_epoch=T0 + 8.0)
|
rec = await recorder.stop_recording(end_epoch=T0 + 8.0)
|
||||||
|
|
||||||
assert rec is not None and rec.path is not None and rec.path.stat().st_size > 0
|
assert rec is not None and rec.path is not None and rec.path.stat().st_size > 0
|
||||||
assert markers(rec.path)[0] == "A0", "slice should begin at the buffer head, not fail"
|
|
||||||
# Buffer head is T0+5.0, requested slice start is T0-PRE_ROLL: everything in
|
|
||||||
# between is audio we can never recover, and the number must be reported.
|
|
||||||
assert rec.clamped_seconds == pytest.approx(5.0 + PRE_ROLL_SECONDS, abs=CHUNK_INTERVAL)
|
assert rec.clamped_seconds == pytest.approx(5.0 + PRE_ROLL_SECONDS, abs=CHUNK_INTERVAL)
|
||||||
assert any("BUFFER CLAMP" in r.message for r in caplog.records)
|
assert any("BUFFER CLAMP" in r.message for r in caplog.records)
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_no_buffered_audio_returns_none(recorder):
|
async def test_no_buffered_audio_returns_none(recorder, encodes):
|
||||||
await recorder.start_recording("call-1", start_epoch=T0)
|
await recorder.start_recording("call-1", start_epoch=T0)
|
||||||
assert await recorder.stop_recording(end_epoch=T0 + 2.0) is None
|
assert await recorder.stop_recording(end_epoch=T0 + 2.0) is None
|
||||||
|
assert encodes == [], "nothing to encode means no encoder subprocess"
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_start_epoch_omitted_falls_back_to_now(recorder):
|
async def test_start_epoch_omitted_falls_back_to_now(recorder):
|
||||||
now = time.time()
|
now = time.time()
|
||||||
fill(recorder, now - 5.0, now)
|
ingest(recorder, now - 5.0, now)
|
||||||
|
|
||||||
await recorder.start_recording("call-1")
|
await recorder.start_recording("call-1")
|
||||||
assert recorder._active.slice_start == pytest.approx(now - PRE_ROLL_SECONDS, abs=1.0)
|
assert recorder._active.slice_start == pytest.approx(now - PRE_ROLL_SECONDS, abs=1.0)
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Encode — exactly once, at save time
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_audio_is_encoded_exactly_once_per_call(recorder, encodes, monkeypatch):
|
||||||
|
"""
|
||||||
|
The old pipeline captured MP3 and then re-encoded it to trim, so every
|
||||||
|
upload was double-encoded. Capture is PCM now and MP3 happens once, after
|
||||||
|
trimming, at save time.
|
||||||
|
"""
|
||||||
|
monkeypatch.setattr(settings, "trim_silence", True)
|
||||||
|
ingest(recorder, T0, T0 + 1.0, chunk=QUIET)
|
||||||
|
ingest(recorder, T0 + 1.0, T0 + 3.0, chunk=VOICE)
|
||||||
|
ingest(recorder, T0 + 3.0, T0 + 6.0, chunk=QUIET)
|
||||||
|
|
||||||
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
rec = await recorder.stop_recording(end_epoch=T0 + 6.0)
|
||||||
|
|
||||||
|
assert rec is not None and rec.path is not None
|
||||||
|
assert len(encodes) == 1, "exactly one encode per recording"
|
||||||
|
encoded_audio, encoded_path = encodes[0]
|
||||||
|
assert encoded_path == rec.path
|
||||||
|
# What was encoded is the TRIMMED audio, not the raw slice.
|
||||||
|
assert pcm.seconds(len(encoded_audio)) < 5.0
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_a_failed_encode_leaves_no_file_and_no_recording(recorder, monkeypatch):
|
||||||
|
async def _fail(audio, path):
|
||||||
|
return False
|
||||||
|
|
||||||
|
monkeypatch.setattr(recorder_mod, "encode_mp3", _fail)
|
||||||
|
ingest(recorder, T0, T0 + 5.0)
|
||||||
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
|
||||||
|
assert await recorder.stop_recording(end_epoch=T0 + 3.0) is None
|
||||||
|
assert list(recorder._recordings_dir.glob("*.mp3")) == []
|
||||||
|
|
||||||
|
|
||||||
|
def test_encoder_command_contract_matches_what_c2_expects():
|
||||||
|
"""
|
||||||
|
/upload has always received mono MP3 at 22050 Hz / 16 kbps, and Whisper
|
||||||
|
consumes it downstream. The single encode must not quietly change that.
|
||||||
|
"""
|
||||||
|
assert recorder_mod.MP3_SAMPLE_RATE == str(pcm.SAMPLE_RATE) == "22050"
|
||||||
|
assert recorder_mod.MP3_BITRATE == "16k"
|
||||||
|
|
||||||
|
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
# Silence trimming and timing metadata
|
# Silence trimming and timing metadata
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
async def _recorded(recorder, end_offset: float = 3.0):
|
async def _recorded(recorder, lead_silence=1.0, voice=2.0, tail_silence=1.0):
|
||||||
ingest(recorder, T0, T0 + 10.0)
|
start = T0
|
||||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
ingest(recorder, start, start + lead_silence, chunk=QUIET)
|
||||||
return await recorder.stop_recording(end_epoch=T0 + end_offset)
|
ingest(recorder, start + lead_silence, start + lead_silence + voice, chunk=VOICE)
|
||||||
|
ingest(recorder, start + lead_silence + voice,
|
||||||
|
start + lead_silence + voice + tail_silence, chunk=QUIET)
|
||||||
|
await recorder.start_recording("call-1", start_epoch=start + 0.5)
|
||||||
|
return await recorder.stop_recording(end_epoch=start + lead_silence + voice + tail_silence)
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
@@ -306,12 +448,12 @@ async def test_trimming_is_off_when_the_setting_is_off(recorder, monkeypatch):
|
|||||||
monkeypatch.setattr(settings, "trim_silence", False)
|
monkeypatch.setattr(settings, "trim_silence", False)
|
||||||
called = False
|
called = False
|
||||||
|
|
||||||
async def _never(*args, **kwargs):
|
def _never(*args, **kwargs):
|
||||||
nonlocal called
|
nonlocal called
|
||||||
called = True
|
called = True
|
||||||
return TrimResult(path=None)
|
return b"", None
|
||||||
|
|
||||||
monkeypatch.setattr(recorder_mod.audio_trim, "trim_silence", _never)
|
monkeypatch.setattr(recorder_mod.audio_trim, "trim_pcm", _never)
|
||||||
rec = await _recorded(recorder)
|
rec = await _recorded(recorder)
|
||||||
assert rec is not None and not called
|
assert rec is not None and not called
|
||||||
|
|
||||||
@@ -325,41 +467,31 @@ async def test_trim_shifts_the_audio_bounds_but_not_the_call_bounds(recorder, mo
|
|||||||
"""
|
"""
|
||||||
monkeypatch.setattr(settings, "trim_silence", True)
|
monkeypatch.setattr(settings, "trim_silence", True)
|
||||||
|
|
||||||
async def _trim(path, **kwargs):
|
rec = await _recorded(recorder, lead_silence=1.0, voice=2.0, tail_silence=1.5)
|
||||||
return TrimResult(path=path, lead=1.9, tail=0.4, duration_before=3.3,
|
|
||||||
duration_after=1.0, applied=True)
|
|
||||||
|
|
||||||
monkeypatch.setattr(recorder_mod.audio_trim, "trim_silence", _trim)
|
|
||||||
|
|
||||||
rec = await _recorded(recorder)
|
|
||||||
assert rec is not None and rec.path is not None
|
assert rec is not None and rec.path is not None
|
||||||
assert rec.lead_trimmed == pytest.approx(1.9)
|
assert rec.lead_trimmed > 0.0 and rec.tail_trimmed > 0.0
|
||||||
assert rec.tail_trimmed == pytest.approx(0.4)
|
guard = settings.trim_silence_guard_seconds
|
||||||
# Untrimmed slice was [T0+0.75, T0+3.0]; the audio now starts 1.9s later and
|
# Slice began at T0+0.25; speech begins at T0+1.0, so the audio now starts
|
||||||
# ends 0.4s earlier, which is exactly what downstream needs to map an audio
|
# one guard margin before the speech.
|
||||||
# offset back to wall clock.
|
assert rec.audio_start_epoch == pytest.approx(T0 + 1.0 - guard, abs=3 * CHUNK_INTERVAL)
|
||||||
assert rec.audio_start_epoch == pytest.approx(T0 + 1.0 - PRE_ROLL_SECONDS + 1.9, abs=CHUNK_INTERVAL)
|
assert rec.audio_end_epoch == pytest.approx(T0 + 3.0 + guard, abs=3 * CHUNK_INTERVAL)
|
||||||
assert rec.audio_end_epoch == pytest.approx(T0 + 3.0 - 0.4, abs=CHUNK_INTERVAL)
|
assert rec.audio_end_epoch > rec.audio_start_epoch
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_all_silence_recording_is_dropped_and_logged(recorder, monkeypatch, caplog):
|
async def test_all_silence_recording_is_dropped_and_logged(recorder, monkeypatch, caplog, encodes):
|
||||||
monkeypatch.setattr(settings, "trim_silence", True)
|
monkeypatch.setattr(settings, "trim_silence", True)
|
||||||
seen = {}
|
ingest(recorder, T0, T0 + 5.0, chunk=QUIET)
|
||||||
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
async def _trim(path, **kwargs):
|
|
||||||
seen["path"] = path
|
|
||||||
return TrimResult(path=path, duration_before=4.0, duration_after=4.0, all_silence=True)
|
|
||||||
|
|
||||||
monkeypatch.setattr(recorder_mod.audio_trim, "trim_silence", _trim)
|
|
||||||
|
|
||||||
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
||||||
rec = await _recorded(recorder)
|
rec = await recorder.stop_recording(end_epoch=T0 + 4.0)
|
||||||
|
|
||||||
assert rec is not None
|
assert rec is not None
|
||||||
assert rec.all_silence is True
|
assert rec.all_silence is True
|
||||||
assert rec.path is None, "an all-silence recording must not be uploaded"
|
assert rec.path is None, "an all-silence recording must not be uploaded"
|
||||||
assert not seen["path"].exists(), "the file must be cleaned up, not left on disk"
|
assert encodes == [], "and must not be encoded either"
|
||||||
assert any("no speech" in r.message for r in caplog.records)
|
assert any("no speech" in r.message for r in caplog.records)
|
||||||
|
|
||||||
|
|
||||||
@@ -369,7 +501,7 @@ async def test_all_silence_recording_is_dropped_and_logged(recorder, monkeypatch
|
|||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_second_start_is_rejected_while_recording(recorder):
|
async def test_second_start_is_rejected_while_recording(recorder):
|
||||||
fill(recorder, T0, T0 + 5.0)
|
ingest(recorder, T0, T0 + 5.0)
|
||||||
assert await recorder.start_recording("call-1", start_epoch=T0 + 1.0) is True
|
assert await recorder.start_recording("call-1", start_epoch=T0 + 1.0) is True
|
||||||
assert await recorder.start_recording("call-2", start_epoch=T0 + 2.0) is False
|
assert await recorder.start_recording("call-2", start_epoch=T0 + 2.0) is False
|
||||||
assert recorder.is_recording
|
assert recorder.is_recording
|
||||||
@@ -381,6 +513,21 @@ async def test_stop_without_start_is_a_noop(recorder):
|
|||||||
assert not recorder.is_recording
|
assert not recorder.is_recording
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_discard_drops_the_audio_without_writing_anything(recorder, encodes):
|
||||||
|
"""The orphan-audio path: unattributed audio must never reach a file."""
|
||||||
|
ingest(recorder, T0, T0 + 5.0)
|
||||||
|
await recorder.start_recording("call-orphan", start_epoch=T0 + 1.0)
|
||||||
|
|
||||||
|
await recorder.discard_recording()
|
||||||
|
|
||||||
|
assert not recorder.is_recording
|
||||||
|
assert encodes == []
|
||||||
|
assert list(recorder._recordings_dir.glob("*.mp3")) == []
|
||||||
|
# ...and the recorder is immediately reusable.
|
||||||
|
assert await recorder.start_recording("call-next", start_epoch=T0 + 2.0) is True
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
async def test_split_then_immediate_restart_keeps_both_slices(recorder):
|
async def test_split_then_immediate_restart_keeps_both_slices(recorder):
|
||||||
"""
|
"""
|
||||||
@@ -405,22 +552,26 @@ async def test_split_then_immediate_restart_keeps_both_slices(recorder):
|
|||||||
# FFmpeg invocation
|
# FFmpeg invocation
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
def test_ffmpeg_command_reads_pulse_and_flushes_packets(recorder):
|
def test_capture_command_asks_for_raw_pcm_not_mp3(recorder):
|
||||||
cmd = recorder._ffmpeg_command()
|
cmd = recorder._ffmpeg_command()
|
||||||
joined = " ".join(cmd)
|
joined = " ".join(cmd)
|
||||||
|
|
||||||
assert "-f pulse" in joined
|
assert "-f pulse" in joined
|
||||||
assert "drb_sink.monitor" in joined, "must address the monitor explicitly, not 'default'"
|
assert "drb_sink.monitor" in joined, "must address the monitor explicitly, not 'default'"
|
||||||
# Without -flush_packets the mp3 muxer buffers 32 KB (~16 s at 16 kbps) before
|
assert cmd[-1] == "-" and cmd[-2] == "s16le", "capture must emit raw PCM on stdout"
|
||||||
# writing, which would destroy the ring buffer's timestamp resolution.
|
assert "mp3" not in joined, "MP3 now happens once at save time, not in the capture"
|
||||||
assert "-flush_packets" in cmd
|
assert "-ar" in cmd and str(pcm.SAMPLE_RATE) in cmd
|
||||||
assert cmd[-1] == "-" and cmd[-2] == "mp3", "must emit MP3 on stdout for /upload"
|
assert "-ac" in cmd and str(pcm.CHANNELS) in cmd
|
||||||
|
|
||||||
|
|
||||||
def test_memory_ceiling_covers_the_longest_allowed_call():
|
def test_read_chunk_is_finer_than_the_pre_roll(recorder):
|
||||||
"""The cap must bound RAM without ever being able to truncate a legal call."""
|
"""
|
||||||
bytes_per_second = 16_000 // 8
|
Chunk size is both the ring buffer's timestamp resolution and the window
|
||||||
assert MAX_RECORDING_BYTES >= MAX_RECORDING_SECONDS * bytes_per_second
|
silence detection runs over, so it has to stay well under the pre-roll.
|
||||||
|
"""
|
||||||
|
chunk_seconds = pcm.seconds(recorder_mod.READ_CHUNK_BYTES)
|
||||||
|
assert chunk_seconds < PRE_ROLL_SECONDS / 4
|
||||||
|
assert recorder_mod.READ_CHUNK_BYTES % pcm.FRAME_BYTES == 0
|
||||||
|
|
||||||
|
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
@@ -481,4 +632,3 @@ def test_capture_exit_with_no_stderr_captured_is_generic_warning(recorder, caplo
|
|||||||
recorder._log_capture_exit()
|
recorder._log_capture_exit()
|
||||||
|
|
||||||
assert _log_levels(caplog) == ["WARNING"]
|
assert _log_levels(caplog) == ["WARNING"]
|
||||||
assert MAX_RECORDING_BYTES <= 8 * 1024 * 1024, "must stay small enough for a Pi"
|
|
||||||
|
|||||||
@@ -1,15 +1,30 @@
|
|||||||
"""
|
"""
|
||||||
Unit tests for the event-driven MetadataWatcher state machine.
|
Unit tests for the MetadataWatcher segmentation state machine.
|
||||||
|
|
||||||
Call START comes from OP25 `call_log` entries (stamped with OP25's own
|
TWO MODES, both covered here:
|
||||||
time.time()); call END comes from the srcaddr != 0 -> srcaddr == 0 transition in
|
|
||||||
`channel_update`. All OP25 HTTP calls are mocked — no running services required.
|
AUDIO MODE (production) — a recording STARTS at voice onset heard in the
|
||||||
|
captured audio and STOPS after settings.call_silence_timeout seconds of
|
||||||
|
silence heard in the same audio. The OP25 console supplies only the LABEL
|
||||||
|
(talkgroup/alias/rid), resolved at CLOSE time from a rolling history, and the
|
||||||
|
forced SPLIT when the talkgroup changes with no silence between calls.
|
||||||
|
|
||||||
|
CONSOLE FALLBACK (capture down) — the older state machine: `call_log` grants
|
||||||
|
start segments, the srcaddr != 0 -> 0 edge plus call_idle_timeout ends them.
|
||||||
|
Tests that wire no audio provider exercise this path, which is exactly the
|
||||||
|
behaviour a node falls back to when PulseAudio is not producing audio.
|
||||||
|
|
||||||
|
All OP25 HTTP calls are mocked — no running services required.
|
||||||
"""
|
"""
|
||||||
import pytest
|
import pytest
|
||||||
from unittest.mock import AsyncMock, patch
|
from unittest.mock import AsyncMock, patch
|
||||||
|
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
|
from app.internal.call_recorder import AudioActivity
|
||||||
from app.internal.metadata_watcher import (
|
from app.internal.metadata_watcher import (
|
||||||
|
ATTRIBUTION_LOOKAHEAD_SECONDS,
|
||||||
|
ATTRIBUTION_LOOKBACK_SECONDS,
|
||||||
|
MAX_SEGMENT_SECONDS,
|
||||||
MetadataWatcher,
|
MetadataWatcher,
|
||||||
OP25_OFFLINE_GRACE,
|
OP25_OFFLINE_GRACE,
|
||||||
)
|
)
|
||||||
@@ -37,6 +52,7 @@ def clock():
|
|||||||
|
|
||||||
@pytest.fixture
|
@pytest.fixture
|
||||||
def watcher(clock):
|
def watcher(clock):
|
||||||
|
"""Console fallback mode: no audio provider wired, capture assumed down."""
|
||||||
w = MetadataWatcher()
|
w = MetadataWatcher()
|
||||||
w._clock = clock
|
w._clock = clock
|
||||||
w.on_call_start = AsyncMock()
|
w.on_call_start = AsyncMock()
|
||||||
@@ -44,6 +60,58 @@ def watcher(clock):
|
|||||||
return w
|
return w
|
||||||
|
|
||||||
|
|
||||||
|
class FakeAudio:
|
||||||
|
"""
|
||||||
|
Stands in for CallRecorder.audio_activity.
|
||||||
|
|
||||||
|
Mirrors the recorder's own rule for what starts a new voice RUN: a
|
||||||
|
non-silent chunk more than settings.call_silence_timeout after the previous
|
||||||
|
one. Tests drive it with speak()/quiet() instead of synthesising PCM, so the
|
||||||
|
segmentation logic is tested independently of the detector.
|
||||||
|
"""
|
||||||
|
|
||||||
|
def __init__(self, clock):
|
||||||
|
self.clock = clock
|
||||||
|
self.capturing = True
|
||||||
|
self.recording = False
|
||||||
|
self.last_voice = None
|
||||||
|
self.onset = None
|
||||||
|
|
||||||
|
def speak(self, at=None):
|
||||||
|
"""Mark voice heard now (or at `at`)."""
|
||||||
|
moment = self.clock.now if at is None else at
|
||||||
|
if self.last_voice is None or (moment - self.last_voice) >= settings.call_silence_timeout:
|
||||||
|
self.onset = moment
|
||||||
|
self.last_voice = moment
|
||||||
|
return moment
|
||||||
|
|
||||||
|
def __call__(self) -> AudioActivity:
|
||||||
|
silence = 0.0 if self.last_voice is None else max(0.0, self.clock.now - self.last_voice)
|
||||||
|
return AudioActivity(
|
||||||
|
capturing=self.capturing,
|
||||||
|
recording=self.recording,
|
||||||
|
last_voice_epoch=self.last_voice,
|
||||||
|
voice_onset_epoch=self.onset,
|
||||||
|
silence_seconds=silence,
|
||||||
|
)
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.fixture
|
||||||
|
def audio(clock):
|
||||||
|
return FakeAudio(clock)
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.fixture
|
||||||
|
def hearing(clock, audio):
|
||||||
|
"""Audio mode: the production wiring, with a controllable audio stream."""
|
||||||
|
w = MetadataWatcher()
|
||||||
|
w._clock = clock
|
||||||
|
w.on_call_start = AsyncMock()
|
||||||
|
w.on_call_end = AsyncMock()
|
||||||
|
w.audio_activity = audio
|
||||||
|
return w
|
||||||
|
|
||||||
|
|
||||||
def grant(tgid: int, time_: float, tgtag: str = "", rid: int = 101, freq: int = 851_000_000):
|
def grant(tgid: int, time_: float, tgtag: str = "", rid: int = 101, freq: int = 851_000_000):
|
||||||
"""One OP25 call_log entry (see tk_p25.log_call)."""
|
"""One OP25 call_log entry (see tk_p25.log_call)."""
|
||||||
return {
|
return {
|
||||||
@@ -195,7 +263,12 @@ async def test_op25_unreachable_does_not_start_call(watcher):
|
|||||||
|
|
||||||
|
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
# Call end — srcaddr edge + idle timeout
|
# Console fallback: call end — srcaddr edge + idle timeout
|
||||||
|
#
|
||||||
|
# This is the path a node uses ONLY when PulseAudio capture is not producing
|
||||||
|
# audio. It is measurably wrong (the srcaddr edge fires mid-word) but it is all
|
||||||
|
# there is when there is no audio to segment on, and it keeps the node
|
||||||
|
# reporting radio activity to C2 while the audio path is broken.
|
||||||
# ---------------------------------------------------------------------------
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
@@ -452,9 +525,11 @@ async def test_different_tgid_grant_splits_recording(watcher, clock):
|
|||||||
assert ended["call_id"] == first_id
|
assert ended["call_id"] == first_id
|
||||||
assert ended["tgid"] == 1111
|
assert ended["tgid"] == 1111
|
||||||
assert ended["end_reason"] == "tgid_change"
|
assert ended["end_reason"] == "tgid_change"
|
||||||
# The outgoing segment ends exactly where the new one begins — no tail pad,
|
# The outgoing segment is padded PAST where the new one begins. The buffered
|
||||||
# or it would swallow the first moments of the new talkgroup.
|
# audio lags control-channel timestamps by ~1.5s, so ending exactly at the
|
||||||
assert ended["ended_at_epoch"] == split_time
|
# split cut the outgoing call's last words. The overlap is correct — the
|
||||||
|
# audio stream really does hold one call's tail then the next call's start.
|
||||||
|
assert ended["ended_at_epoch"] == split_time + settings.call_tail_pad_seconds
|
||||||
assert watcher.on_call_start.call_args[0][0]["started_at_epoch"] == split_time
|
assert watcher.on_call_start.call_args[0][0]["started_at_epoch"] == split_time
|
||||||
|
|
||||||
|
|
||||||
@@ -482,7 +557,8 @@ async def test_multiple_call_log_entries_in_one_poll(watcher, clock):
|
|||||||
assert ended["tgid"] == 1111
|
assert ended["tgid"] == 1111
|
||||||
assert ended["transmissions"] == 2
|
assert ended["transmissions"] == 2
|
||||||
assert ended["started_at_epoch"] == t0
|
assert ended["started_at_epoch"] == t0
|
||||||
assert ended["ended_at_epoch"] == t0 + 0.9
|
# Split close is padded past the new grant — see the tgid_change test above.
|
||||||
|
assert ended["ended_at_epoch"] == t0 + 0.9 + settings.call_tail_pad_seconds
|
||||||
|
|
||||||
|
|
||||||
@pytest.mark.asyncio
|
@pytest.mark.asyncio
|
||||||
@@ -575,3 +651,499 @@ async def test_end_never_precedes_start(watcher, clock):
|
|||||||
|
|
||||||
payload = watcher.on_call_end.call_args[0][0]
|
payload = watcher.on_call_end.call_args[0][0]
|
||||||
assert payload["ended_at_epoch"] >= payload["started_at_epoch"]
|
assert payload["ended_at_epoch"] >= payload["started_at_epoch"]
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# AUDIO MODE — boundaries from the audio, label from the console
|
||||||
|
#
|
||||||
|
# This is the production path. Everything above this line is the fallback that
|
||||||
|
# only runs when PulseAudio capture is down.
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_audio_onset_starts_the_recording(hearing, clock, audio):
|
||||||
|
"""Voice onset opens the segment, and the recorder is told to slice to it."""
|
||||||
|
onset = audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1234, clock.now, tgtag="Police Dispatch")],
|
||||||
|
channels=[channel(tgid=1234, srcaddr=555)],
|
||||||
|
))
|
||||||
|
|
||||||
|
assert hearing.is_active
|
||||||
|
hearing.on_call_start.assert_called_once()
|
||||||
|
payload = hearing.on_call_start.call_args[0][0]
|
||||||
|
assert payload["driver"] == "audio"
|
||||||
|
# The recorder slices the ring buffer back to THIS epoch, so it has to be
|
||||||
|
# the audio onset, not the grant and not our detection time.
|
||||||
|
assert payload["started_at_epoch"] == onset
|
||||||
|
assert payload["tgid"] == 1234
|
||||||
|
assert payload["tgid_name"] == "Police Dispatch"
|
||||||
|
assert payload["attributed"] is True
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_a_grant_with_no_audio_does_not_start_a_recording(hearing, clock):
|
||||||
|
"""
|
||||||
|
The grant fires 0.84-1.62s before anyone speaks. Opening on it is what put
|
||||||
|
seconds of dead air at the head of every recording.
|
||||||
|
"""
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1234, clock.now, tgtag="Fire")],
|
||||||
|
channels=[channel(tgid=1234, srcaddr=555)],
|
||||||
|
))
|
||||||
|
|
||||||
|
assert not hearing.is_active
|
||||||
|
hearing.on_call_start.assert_not_called()
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_recording_closes_after_the_configured_silence(hearing, clock, audio):
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1234, clock.now)],
|
||||||
|
channels=[channel(tgid=1234, srcaddr=555)],
|
||||||
|
))
|
||||||
|
|
||||||
|
clock.advance(0.5)
|
||||||
|
last_voice = audio.speak()
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=1234, srcaddr=555)]))
|
||||||
|
|
||||||
|
# Quiet, but not for long enough yet.
|
||||||
|
clock.advance(settings.call_silence_timeout - 0.5)
|
||||||
|
await tick(hearing, update(channels=[channel()]))
|
||||||
|
assert hearing.is_active
|
||||||
|
hearing.on_call_end.assert_not_called()
|
||||||
|
|
||||||
|
clock.advance(0.6)
|
||||||
|
await tick(hearing, update(channels=[channel()]))
|
||||||
|
|
||||||
|
assert not hearing.is_active
|
||||||
|
payload = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert payload["end_reason"] == "audio_silence"
|
||||||
|
assert payload["tgid"] == 1234
|
||||||
|
# The audio ends where the silence run began plus the threshold, so the
|
||||||
|
# trim can measure and strip exactly that run.
|
||||||
|
assert payload["ended_at_epoch"] == pytest.approx(last_voice + settings.call_silence_timeout)
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_a_false_srcaddr_drop_mid_speech_does_not_end_the_recording(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
THE BUG THIS REARCHITECTURE EXISTS FOR. srcaddr can reset to 0 while someone
|
||||||
|
is still talking; under the old design that started the idle timer and the
|
||||||
|
window closed on top of live speech (recording 0ff35b20: "-1.61s lead,
|
||||||
|
-0.00s tail" — nothing left to trim because the cut landed mid-word).
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1234, clock.now)],
|
||||||
|
channels=[channel(tgid=1234, srcaddr=555)],
|
||||||
|
))
|
||||||
|
call_id = hearing.active_call_id
|
||||||
|
|
||||||
|
# The control channel now says the call is over. It is wrong; the audio
|
||||||
|
# keeps arriving. This runs well past call_idle_timeout, which is what
|
||||||
|
# would have closed the segment before.
|
||||||
|
for _ in range(10):
|
||||||
|
clock.advance(0.5)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=1234, srcaddr=0, hold_tgid=1234)]))
|
||||||
|
assert hearing.is_active, "a false srcaddr drop must never end a recording"
|
||||||
|
|
||||||
|
assert (clock.now - hearing._started_at) > settings.call_idle_timeout
|
||||||
|
assert hearing.active_call_id == call_id
|
||||||
|
hearing.on_call_end.assert_not_called()
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_silence_close_logs_the_measured_trailing_silence(hearing, clock, audio, caplog):
|
||||||
|
"""
|
||||||
|
call_silence_timeout can only be tuned from the real trailing silence, so
|
||||||
|
the measured number has to reach the log — the audio-mode counterpart of
|
||||||
|
the "measured control-channel idle" line.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now)]))
|
||||||
|
|
||||||
|
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||||
|
clock.advance(settings.call_silence_timeout + 0.25)
|
||||||
|
await tick(hearing, update(channels=[channel()]))
|
||||||
|
|
||||||
|
lines = [r.message for r in caplog.records if "measured trailing silence" in r.message]
|
||||||
|
assert lines, "audio closes must log the measured silence for later tuning"
|
||||||
|
assert "3.25s" in lines[0]
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_same_tgid_grant_continues_one_audio_recording(hearing, clock, audio):
|
||||||
|
"""Back-and-forth on one talkgroup must stay a single call/recording."""
|
||||||
|
onset = audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1234, clock.now)],
|
||||||
|
channels=[channel(tgid=1234, srcaddr=555)],
|
||||||
|
))
|
||||||
|
call_id = hearing.active_call_id
|
||||||
|
|
||||||
|
# The other party keys up on the SAME tgid while audio is still flowing.
|
||||||
|
clock.advance(1.0)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1234, clock.now)],
|
||||||
|
channels=[channel(tgid=1234, srcaddr=777)],
|
||||||
|
))
|
||||||
|
|
||||||
|
assert hearing.active_call_id == call_id, "same tgid must not open a new call"
|
||||||
|
hearing.on_call_start.assert_called_once()
|
||||||
|
hearing.on_call_end.assert_not_called()
|
||||||
|
|
||||||
|
clock.advance(settings.call_silence_timeout + 0.5)
|
||||||
|
await tick(hearing, update(channels=[channel()]))
|
||||||
|
|
||||||
|
hearing.on_call_end.assert_called_once()
|
||||||
|
payload = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert payload["call_id"] == call_id
|
||||||
|
assert payload["started_at_epoch"] == onset
|
||||||
|
assert payload["transmissions"] == 2
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_different_tgid_splits_even_with_no_silence_between(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
Back-to-back calls on two talkgroups with no gap. Pure audio segmentation
|
||||||
|
would merge them into ONE file under ONE label, which corrupts correlation.
|
||||||
|
The console talkgroup change has to force the cut.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1111, clock.now, tgtag="Fire")],
|
||||||
|
channels=[channel(tgid=1111, srcaddr=1)],
|
||||||
|
))
|
||||||
|
first_id = hearing.active_call_id
|
||||||
|
|
||||||
|
clock.advance(2.0)
|
||||||
|
audio.speak() # still talking — no silence anywhere in this test
|
||||||
|
split = clock.now
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(2222, split, tgtag="EMS")],
|
||||||
|
channels=[channel(tgid=2222, srcaddr=2)],
|
||||||
|
))
|
||||||
|
|
||||||
|
hearing.on_call_end.assert_called_once()
|
||||||
|
ended = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert ended["call_id"] == first_id
|
||||||
|
assert ended["tgid"] == 1111
|
||||||
|
assert ended["end_reason"] == "tgid_change"
|
||||||
|
# Padded past the split: buffered audio lags the control channel, so cutting
|
||||||
|
# at the exact grant timestamp clipped the outgoing call's last words. The
|
||||||
|
# overlap between the two slices is correct.
|
||||||
|
assert ended["ended_at_epoch"] == split + settings.call_tail_pad_seconds
|
||||||
|
|
||||||
|
assert hearing.is_active and hearing.current_tgid == 2222
|
||||||
|
assert hearing.active_call_id != first_id
|
||||||
|
assert hearing.on_call_start.call_count == 2
|
||||||
|
assert hearing.on_call_start.call_args[0][0]["started_at_epoch"] == split
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_an_unlogged_tgid_change_also_splits_and_reopens(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
OP25's call_log deque is capped at 10, so grants get dropped. If our only
|
||||||
|
receiver is plainly on another talkgroup the segment is over — and in audio
|
||||||
|
mode a new one must open immediately or the audio would be dropped on the
|
||||||
|
floor until the next voice run.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1111, clock.now)],
|
||||||
|
channels=[channel(tgid=1111, srcaddr=1)],
|
||||||
|
))
|
||||||
|
first_id = hearing.active_call_id
|
||||||
|
|
||||||
|
clock.advance(1.0)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=3333, srcaddr=7)])) # no call_log
|
||||||
|
|
||||||
|
ended = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert ended["call_id"] == first_id
|
||||||
|
assert ended["end_reason"] == "tgid_change_unlogged"
|
||||||
|
assert hearing.is_active and hearing.current_tgid == 3333
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_max_length_backstop_closes_and_reopens(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
A talkgroup that never goes quiet must not produce an unbounded recording —
|
||||||
|
but the audio must not be dropped either, so the segment is immediately
|
||||||
|
reopened rather than simply abandoned.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now)]))
|
||||||
|
first_id = hearing.active_call_id
|
||||||
|
|
||||||
|
clock.advance(MAX_SEGMENT_SECONDS / 2)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=1234, srcaddr=5)]))
|
||||||
|
assert hearing.active_call_id == first_id
|
||||||
|
|
||||||
|
clock.advance(MAX_SEGMENT_SECONDS / 2 + 1)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=1234, srcaddr=5)]))
|
||||||
|
|
||||||
|
ended = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert ended["call_id"] == first_id
|
||||||
|
assert ended["end_reason"] == "max_length"
|
||||||
|
assert hearing.is_active, "a still-live transmission must not be dropped at the cap"
|
||||||
|
assert hearing.active_call_id != first_id
|
||||||
|
assert hearing.on_call_start.call_count == 2
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Attribution: resolved at close, from a bounded rolling console history
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_orphan_audio_is_discarded_flagged_and_counted(hearing, clock, audio, caplog):
|
||||||
|
"""
|
||||||
|
Audio with no console talkgroup anywhere near it — Liquidsoap fallback, a
|
||||||
|
test tone, stray noise, a dropped call_log. It must be impossible to miss
|
||||||
|
and must never be uploaded: an untagged call poisons correlation.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update()) # console says nothing at all
|
||||||
|
|
||||||
|
assert hearing.is_active
|
||||||
|
started = hearing.on_call_start.call_args[0][0]
|
||||||
|
assert started["tgid"] is None
|
||||||
|
assert started["attributed"] is False
|
||||||
|
|
||||||
|
with caplog.at_level("ERROR", logger="drb-edge-node"):
|
||||||
|
clock.advance(settings.call_silence_timeout + 0.5)
|
||||||
|
await tick(hearing, update())
|
||||||
|
|
||||||
|
ended = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert ended["attributed"] is False
|
||||||
|
assert ended["tgid"] is None
|
||||||
|
assert hearing.unattributed_segments == 1
|
||||||
|
assert any("ORPHAN AUDIO" in r.message for r in caplog.records), \
|
||||||
|
"unattributed audio must be loud in the logs, not silent"
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_a_grant_before_audio_onset_still_attributes_the_recording(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
The common ordering: the console grants the channel, then 0.84-1.62s later
|
||||||
|
(plus pipeline lag) the audio shows up. The lookback has to cover it.
|
||||||
|
"""
|
||||||
|
grant_time = clock.now
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, grant_time, tgtag="Fire")]))
|
||||||
|
assert not hearing.is_active
|
||||||
|
|
||||||
|
clock.advance(2.0)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update()) # console says nothing NOW
|
||||||
|
|
||||||
|
assert hearing.is_active
|
||||||
|
payload = hearing.on_call_start.call_args[0][0]
|
||||||
|
assert payload["tgid"] == 1234
|
||||||
|
assert payload["tgid_name"] == "Fire"
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_a_grant_after_audio_onset_attributes_the_recording_late(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
There is no guaranteed ordering: the console is polled every 500ms, so the
|
||||||
|
grant can land after voice onset. The segment starts unattributed and picks
|
||||||
|
the talkgroup up part-way through — expected, and fine.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update())
|
||||||
|
|
||||||
|
assert hearing.is_active
|
||||||
|
assert hearing.on_call_start.call_args[0][0]["attributed"] is False
|
||||||
|
|
||||||
|
clock.advance(0.5)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now, tgtag="EMS")]))
|
||||||
|
assert hearing.current_tgid == 1234
|
||||||
|
|
||||||
|
clock.advance(settings.call_silence_timeout + 0.5)
|
||||||
|
await tick(hearing, update())
|
||||||
|
|
||||||
|
ended = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert ended["attributed"] is True
|
||||||
|
assert ended["tgid"] == 1234
|
||||||
|
assert ended["tgid_name"] == "EMS"
|
||||||
|
assert hearing.unattributed_segments == 0
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_attribution_resolves_from_a_channel_row_when_the_grant_was_dropped(hearing, clock, audio):
|
||||||
|
"""A dropped grant is survivable: an active channel row names the talkgroup."""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update())
|
||||||
|
assert hearing.on_call_start.call_args[0][0]["tgid"] is None
|
||||||
|
|
||||||
|
clock.advance(0.5)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=4321, srcaddr=99, tag="Sheriff")]))
|
||||||
|
|
||||||
|
clock.advance(settings.call_silence_timeout + 0.5)
|
||||||
|
await tick(hearing, update())
|
||||||
|
|
||||||
|
ended = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert ended["tgid"] == 4321
|
||||||
|
assert ended["attributed"] is True
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_console_activity_outside_the_tolerance_does_not_attribute(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
The tolerance is deliberately bounded. A grant from long before the audio is
|
||||||
|
not evidence about this audio, and borrowing it would be worse than
|
||||||
|
admitting the audio is unattributed.
|
||||||
|
"""
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now)]))
|
||||||
|
|
||||||
|
clock.advance(ATTRIBUTION_LOOKBACK_SECONDS + 5.0)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update())
|
||||||
|
|
||||||
|
assert hearing.is_active
|
||||||
|
assert hearing.on_call_start.call_args[0][0]["tgid"] is None
|
||||||
|
assert ATTRIBUTION_LOOKAHEAD_SECONDS > 0
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_a_directly_stated_talkgroup_is_not_overruled_at_close(hearing, clock, audio, caplog):
|
||||||
|
"""
|
||||||
|
The attribution window extends past the audio on purpose, so a neighbouring
|
||||||
|
call's console activity can fall inside it. An inference over that window
|
||||||
|
must never overrule a talkgroup the console stated outright — but the
|
||||||
|
overlap does mean the split logic missed something, so it is logged.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1111, clock.now, tgtag="Fire")],
|
||||||
|
channels=[channel(tgid=1111, srcaddr=1)],
|
||||||
|
))
|
||||||
|
|
||||||
|
# A second talkgroup is busy on ANOTHER receiver, so no split fires, and it
|
||||||
|
# produces more console observations than ours did.
|
||||||
|
for _ in range(4):
|
||||||
|
clock.advance(0.5)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(channels=[
|
||||||
|
channel(tgid=1111, srcaddr=0, hold_tgid=1111),
|
||||||
|
channel(tgid=2222, srcaddr=7),
|
||||||
|
]))
|
||||||
|
|
||||||
|
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
||||||
|
clock.advance(settings.call_silence_timeout + 0.5)
|
||||||
|
await tick(hearing, update())
|
||||||
|
|
||||||
|
ended = hearing.on_call_end.call_args[0][0]
|
||||||
|
assert ended["tgid"] == 1111, "the console said 1111 directly; inference must not overrule it"
|
||||||
|
assert any("split logic should have fired" in r.message for r in caplog.records)
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_the_same_voice_run_does_not_reopen_a_second_recording(hearing, clock, audio):
|
||||||
|
"""A closed run must stay closed; only NEW audio opens the next segment."""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now)]))
|
||||||
|
|
||||||
|
clock.advance(settings.call_silence_timeout + 0.5)
|
||||||
|
await tick(hearing, update())
|
||||||
|
assert not hearing.is_active
|
||||||
|
|
||||||
|
# Several more quiet polls must not resurrect it.
|
||||||
|
for _ in range(3):
|
||||||
|
clock.advance(0.5)
|
||||||
|
await tick(hearing, update())
|
||||||
|
assert not hearing.is_active
|
||||||
|
assert hearing.on_call_start.call_count == 1
|
||||||
|
|
||||||
|
# ...but the next voice run does open a new segment.
|
||||||
|
clock.advance(1.0)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now)]))
|
||||||
|
assert hearing.is_active
|
||||||
|
assert hearing.on_call_start.call_count == 2
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Mode changes: capture loss, console loss
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_losing_capture_closes_an_audio_segment(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
An audio-driven segment must never hang open when the audio stops arriving:
|
||||||
|
with no chunks there is no silence to detect, so the mode change is the
|
||||||
|
thing that has to close it.
|
||||||
|
"""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now)]))
|
||||||
|
assert hearing.is_active
|
||||||
|
|
||||||
|
audio.capturing = False
|
||||||
|
clock.advance(0.5)
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=1234, srcaddr=555)]))
|
||||||
|
|
||||||
|
assert not hearing.is_active
|
||||||
|
assert hearing.on_call_end.call_args[0][0]["end_reason"] == "capture_lost"
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_console_segmentation_takes_over_while_capture_is_down(hearing, clock, audio):
|
||||||
|
"""
|
||||||
|
No audio means no recordings, but the node must still report real radio
|
||||||
|
activity to C2 rather than going silent about it.
|
||||||
|
"""
|
||||||
|
audio.capturing = False
|
||||||
|
|
||||||
|
await tick(hearing, update(
|
||||||
|
call_log=[grant(1234, clock.now, tgtag="Police")],
|
||||||
|
channels=[channel(tgid=1234, srcaddr=555)],
|
||||||
|
))
|
||||||
|
assert hearing.is_active
|
||||||
|
assert hearing.on_call_start.call_args[0][0]["driver"] == "console"
|
||||||
|
|
||||||
|
clock.advance(0.5)
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=1234, srcaddr=0, hold_tgid=1234)]))
|
||||||
|
clock.advance(settings.call_idle_timeout + 0.5)
|
||||||
|
await tick(hearing, update(channels=[channel()]))
|
||||||
|
|
||||||
|
assert not hearing.is_active
|
||||||
|
assert hearing.on_call_end.call_args[0][0]["end_reason"] == "idle_timeout"
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_op25_unreachable_still_closes_an_audio_segment(hearing, clock, audio):
|
||||||
|
"""Without the console there is no attribution, so there is nothing to keep open."""
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, update(call_log=[grant(1234, clock.now)]))
|
||||||
|
|
||||||
|
clock.advance(OP25_OFFLINE_GRACE + 0.5)
|
||||||
|
audio.speak()
|
||||||
|
await tick(hearing, None)
|
||||||
|
|
||||||
|
assert not hearing.is_active
|
||||||
|
assert hearing.on_call_end.call_args[0][0]["end_reason"] == "op25_unreachable"
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_console_history_is_bounded(hearing, clock, audio):
|
||||||
|
"""A rolling history that grows without limit would be a slow memory leak."""
|
||||||
|
from app.internal.metadata_watcher import CONSOLE_HISTORY_MAX, CONSOLE_HISTORY_SECONDS
|
||||||
|
|
||||||
|
for _ in range(CONSOLE_HISTORY_MAX + 200):
|
||||||
|
clock.advance(0.05)
|
||||||
|
await tick(hearing, update(channels=[channel(tgid=1234, srcaddr=5)]))
|
||||||
|
|
||||||
|
assert len(hearing._console) <= CONSOLE_HISTORY_MAX
|
||||||
|
|
||||||
|
# ...and old entries age out even when the count is low.
|
||||||
|
clock.advance(CONSOLE_HISTORY_SECONDS + 1)
|
||||||
|
await tick(hearing, update())
|
||||||
|
assert all(e.epoch >= clock.now - CONSOLE_HISTORY_SECONDS for e in hearing._console)
|
||||||
|
|||||||
@@ -0,0 +1,134 @@
|
|||||||
|
"""
|
||||||
|
Unit tests for the raw-PCM primitives that silence detection rests on.
|
||||||
|
|
||||||
|
The whole audio-driven design depends on one field observation: between
|
||||||
|
transmissions the captured stream is DIGITAL silence (a PulseAudio null-sink
|
||||||
|
monitor), measured at about -91 dBFS — one least-significant bit — not an analog
|
||||||
|
noise floor. These tests pin that assumption down in code: a 1-LSB "silent"
|
||||||
|
buffer must read as silence at every sane threshold, and speech-level audio must
|
||||||
|
never read as silence.
|
||||||
|
"""
|
||||||
|
from array import array
|
||||||
|
|
||||||
|
import pytest
|
||||||
|
|
||||||
|
from app.internal import pcm
|
||||||
|
|
||||||
|
|
||||||
|
def tone(level: int, samples: int = 1024) -> bytes:
|
||||||
|
"""A square wave at +/-level, so RMS == level exactly."""
|
||||||
|
return array("h", [level, -level] * (samples // 2)).tobytes()
|
||||||
|
|
||||||
|
|
||||||
|
def zeros(samples: int = 1024) -> bytes:
|
||||||
|
return b"\x00\x00" * samples
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Format arithmetic
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
def test_capture_format_is_22050_mono_16bit():
|
||||||
|
"""MP3_SAMPLE_RATE in call_recorder must match, or the encode resamples."""
|
||||||
|
assert (pcm.SAMPLE_RATE, pcm.CHANNELS, pcm.SAMPLE_WIDTH) == (22050, 1, 2)
|
||||||
|
assert pcm.BYTES_PER_SECOND == 44100
|
||||||
|
|
||||||
|
|
||||||
|
def test_seconds_and_byte_offset_round_trip():
|
||||||
|
assert pcm.seconds(pcm.BYTES_PER_SECOND) == pytest.approx(1.0)
|
||||||
|
assert pcm.byte_offset(1.0) == pcm.BYTES_PER_SECOND
|
||||||
|
assert pcm.byte_offset(0.5) == 22050
|
||||||
|
|
||||||
|
|
||||||
|
def test_byte_offset_is_always_sample_aligned():
|
||||||
|
"""A byte offset that splits a sample would shift every later sample."""
|
||||||
|
for seconds in (0.001, 0.0137, 0.25, 1.7):
|
||||||
|
assert pcm.byte_offset(seconds) % pcm.FRAME_BYTES == 0
|
||||||
|
|
||||||
|
|
||||||
|
def test_align_drops_a_trailing_half_sample():
|
||||||
|
assert pcm.align(9) == 8
|
||||||
|
assert pcm.align(0) == 0
|
||||||
|
assert pcm.align(-4) == 0
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Silence detection
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
def test_exact_digital_zero_is_silence():
|
||||||
|
assert pcm.is_all_zero(zeros())
|
||||||
|
assert pcm.rms_dbfs(zeros()) == pcm.SILENT_DBFS
|
||||||
|
assert pcm.is_silent(zeros(), -50.0)
|
||||||
|
assert pcm.is_silent(zeros(), -90.0)
|
||||||
|
|
||||||
|
|
||||||
|
def test_one_lsb_of_dither_is_the_measured_field_floor():
|
||||||
|
"""
|
||||||
|
The gap between transmissions measures ~-91 dBFS on a live node, which is
|
||||||
|
exactly 20*log10(1/32768) — a single LSB. It must read as silence at any
|
||||||
|
threshold we would ever configure.
|
||||||
|
"""
|
||||||
|
floor = tone(1)
|
||||||
|
assert pcm.rms_dbfs(floor) == pytest.approx(-90.3, abs=0.2)
|
||||||
|
assert pcm.is_silent(floor, -50.0)
|
||||||
|
assert pcm.is_silent(floor, -70.0)
|
||||||
|
assert not pcm.is_silent(floor, -95.0), "an absurd threshold should still be honoured"
|
||||||
|
|
||||||
|
|
||||||
|
def test_speech_level_audio_is_never_silence():
|
||||||
|
"""Speech on the live node averages about -18 dBFS."""
|
||||||
|
speech = tone(4096) # -18.06 dBFS
|
||||||
|
assert pcm.rms_dbfs(speech) == pytest.approx(-18.06, abs=0.1)
|
||||||
|
assert not pcm.is_silent(speech, -50.0)
|
||||||
|
assert not pcm.is_silent(speech, -40.0)
|
||||||
|
|
||||||
|
|
||||||
|
def test_threshold_is_honoured_exactly_at_the_boundary():
|
||||||
|
# RMS 104 -> -49.96 dBFS, just above a -50 threshold.
|
||||||
|
assert not pcm.is_silent(tone(104), -50.0)
|
||||||
|
# RMS 100 -> -50.30 dBFS, just below it.
|
||||||
|
assert pcm.is_silent(tone(100), -50.0)
|
||||||
|
|
||||||
|
|
||||||
|
def test_empty_buffer_counts_as_silence():
|
||||||
|
"""
|
||||||
|
"No audio arrived" must never read as "someone is talking" — otherwise a
|
||||||
|
stalled capture would hold a segment open forever.
|
||||||
|
"""
|
||||||
|
assert pcm.is_silent(b"", -50.0)
|
||||||
|
assert pcm.rms_dbfs(b"") == pcm.SILENT_DBFS
|
||||||
|
|
||||||
|
|
||||||
|
def test_full_scale_is_zero_dbfs():
|
||||||
|
assert pcm.rms_dbfs(tone(32767)) == pytest.approx(0.0, abs=0.001)
|
||||||
|
|
||||||
|
|
||||||
|
def test_a_trailing_odd_byte_does_not_break_detection():
|
||||||
|
"""Short reads at EOF can leave half a sample; it must be dropped, not skew."""
|
||||||
|
assert not pcm.is_silent(tone(8000) + b"\x00", -50.0)
|
||||||
|
assert pcm.samples(zeros(4) + b"\x01").itemsize == 2
|
||||||
|
assert len(pcm.samples(zeros(4) + b"\x01")) == 4
|
||||||
|
|
||||||
|
|
||||||
|
def test_rms_attenuates_an_isolated_click_the_way_peak_would_not():
|
||||||
|
"""
|
||||||
|
Why RMS and not peak. A single stray sample in an otherwise silent window is
|
||||||
|
a decoder click, not speech. Peak would score it at its full amplitude and
|
||||||
|
hold a recording open; RMS spreads it over the window and divides it down by
|
||||||
|
sqrt(N) — 30 dB for a 1024-sample window.
|
||||||
|
|
||||||
|
A full-scale click still reads as signal even after that attenuation, which
|
||||||
|
is deliberate: at worst it extends a recording by the silence timeout, and
|
||||||
|
the trim strips the result before upload. Under-detecting speech is the
|
||||||
|
failure that loses words permanently.
|
||||||
|
"""
|
||||||
|
moderate = bytearray(zeros(1024))
|
||||||
|
moderate[0:2] = array("h", [1000]).tobytes() # -30 dBFS peak
|
||||||
|
assert pcm.rms_dbfs(bytes(moderate)) == pytest.approx(-60.4, abs=0.2)
|
||||||
|
assert pcm.is_silent(bytes(moderate), -50.0)
|
||||||
|
|
||||||
|
full_scale = bytearray(zeros(1024))
|
||||||
|
full_scale[0:2] = array("h", [32767]).tobytes()
|
||||||
|
assert pcm.rms_dbfs(bytes(full_scale)) == pytest.approx(-30.1, abs=0.2)
|
||||||
|
assert not pcm.is_silent(bytes(full_scale), -50.0)
|
||||||
@@ -17,6 +17,8 @@ is proven at the layer that matters.
|
|||||||
import subprocess
|
import subprocess
|
||||||
from unittest.mock import Mock
|
from unittest.mock import Mock
|
||||||
|
|
||||||
|
import pytest
|
||||||
|
|
||||||
from app.internal import pulse
|
from app.internal import pulse
|
||||||
|
|
||||||
|
|
||||||
@@ -53,6 +55,7 @@ def test_is_ready_false_when_daemon_does_not_respond(monkeypatch):
|
|||||||
assert pulse.is_ready() is False
|
assert pulse.is_ready() is False
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
async def test_wait_until_ready_short_circuits_when_already_live(monkeypatch):
|
async def test_wait_until_ready_short_circuits_when_already_live(monkeypatch):
|
||||||
calls = Mock(return_value=True)
|
calls = Mock(return_value=True)
|
||||||
monkeypatch.setattr(pulse, "_daemon_responds", calls)
|
monkeypatch.setattr(pulse, "_daemon_responds", calls)
|
||||||
@@ -60,6 +63,7 @@ async def test_wait_until_ready_short_circuits_when_already_live(monkeypatch):
|
|||||||
assert calls.call_count == 1
|
assert calls.call_count == 1
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
async def test_wait_until_ready_polls_until_daemon_comes_up(monkeypatch):
|
async def test_wait_until_ready_polls_until_daemon_comes_up(monkeypatch):
|
||||||
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
||||||
responses = iter([False, False, True])
|
responses = iter([False, False, True])
|
||||||
@@ -67,12 +71,14 @@ async def test_wait_until_ready_polls_until_daemon_comes_up(monkeypatch):
|
|||||||
assert await pulse.wait_until_ready(timeout=5) is True
|
assert await pulse.wait_until_ready(timeout=5) is True
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
async def test_wait_until_ready_times_out_when_daemon_never_responds(monkeypatch):
|
async def test_wait_until_ready_times_out_when_daemon_never_responds(monkeypatch):
|
||||||
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
||||||
monkeypatch.setattr(pulse, "_daemon_responds", lambda: False)
|
monkeypatch.setattr(pulse, "_daemon_responds", lambda: False)
|
||||||
assert await pulse.wait_until_ready(timeout=0.05) is False
|
assert await pulse.wait_until_ready(timeout=0.05) is False
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
async def test_wait_until_ready_uses_settings_default_when_timeout_omitted(monkeypatch):
|
async def test_wait_until_ready_uses_settings_default_when_timeout_omitted(monkeypatch):
|
||||||
monkeypatch.setattr(pulse.settings, "pulse_wait_timeout", 0.05)
|
monkeypatch.setattr(pulse.settings, "pulse_wait_timeout", 0.05)
|
||||||
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
||||||
|
|||||||
Reference in New Issue
Block a user