diff --git a/.env.example b/.env.example index 4e57722..c11be14 100644 --- a/.env.example +++ b/.env.example @@ -29,29 +29,49 @@ PULSE_SOURCE=drb_sink.monitor # Seconds to wait for the shared PulseAudio socket before giving up and retrying. PULSE_WAIT_TIMEOUT=30 -# Call segmentation: seconds of radio silence before the current recording is -# closed. Grants on the same talkgroup within this window stay in ONE recording. -# Tune ONLY from the "measured control-channel idle" line the edge node logs on -# every idle-timeout close — silence measured in the audio is a different clock -# (it also contains the ~1.9s P25 grant-to-speech delay). +# --- Call segmentation ------------------------------------------------------- +# Recording boundaries come from the AUDIO, not the control channel: a recording +# starts at voice onset and ends after this many seconds of silence actually +# heard in the stream. Transmissions on the same talkgroup separated by less +# 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 -# Seconds of audio kept after the last transmission ends. This is the only -# headroom protecting the final word of a transmission — usually the disposition -# or the address. Raised 1.0 -> 3.0 after field measurement showed the -# grant-to-speech offset is ~0.84-1.62s (typically ~1.5s): at 1.0s pad, short -# calls had their recording window close before the voice even started, -# clipping speech mid-word. Safe to be generous — trim_silence already strips -# the extra back off long calls before upload, so only short transmissions -# actually benefit from the larger window. +# Seconds of audio kept past a CONTROL-CHANNEL-derived boundary — a talkgroup +# change, or a close in the fallback mode above. Buffered audio lags the +# control channel by ~1.5s (grant-to-speech offset measured 0.84-1.62s), so +# cutting at the exact control-channel timestamp clipped the last words of the +# outgoing call. Does NOT apply to the normal end of a call any more; that +# boundary comes from the audio and needs no pad. Safe to be generous — the +# extra is trimmed off again before upload. CALL_TAIL_PAD_SECONDS=3.0 -# Strip leading/trailing dead air before upload. ~63% of an untrimmed recording -# is silence, which costs Whisper spend and makes it hallucinate text that was -# never spoken. Only the head and tail are touched, with a guard margin so no -# syllable is clipped. Set to false to upload raw audio. +# Strip leading/trailing dead air before upload. Recordings deliberately +# over-capture at both ends, and silence costs Whisper spend and makes it +# hallucinate text that was never spoken. Trimming is a sample-offset slice of +# 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 -# 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 # Seconds of audio kept either side of detected speech. TRIM_SILENCE_GUARD_SECONDS=0.25 diff --git a/drb-edge-node/app/config.py b/drb-edge-node/app/config.py index 57b923a..1e825cb 100644 --- a/drb-edge-node/app/config.py +++ b/drb-edge-node/app/config.py @@ -34,49 +34,80 @@ class Settings(BaseSettings): # Bounded wait for the shared PulseAudio socket before launching FFmpeg. 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 - # window are kept in one recording so back-and-forth traffic stays together. + # ------------------------------------------------------------------ + # Call segmentation # - # Do NOT tune this against measured *audio* silence: audio gaps also contain - # the ~1.9 s P25 grant→speech delay, so they are always longer than the - # control-channel idle this timer measures. metadata_watcher logs the real - # measured idle on every idle-timeout close — tune from that. + # Boundaries come from the AUDIO, not the control channel. A recording + # starts at voice onset and ends after call_silence_timeout seconds of + # silence actually heard in the stream. See internal/metadata_watcher.py + # 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 - # Audio kept after the observed end of the last transmission. The srcaddr - # 1→0 edge can be up to one poll (0.5 s) late and the encoder adds its own - # latency, so this is the only headroom protecting the last word of a - # transmission — which is usually the disposition or the address. + # Audio kept past a CONSOLE-DERIVED segment boundary, covering the fact that + # buffered audio lags control-channel timestamps by ~1.5s (grant->speech + # offset measured 0.84-1.62s across 7 field calls). # - # Raised 1.0 -> 3.0 after field measurement showed the recording WINDOW - # (anchored to OP25 control-channel timestamps) closing well before the - # actual voice audio arrives: grant->speech offset measured 0.84-1.62s - # across 7 calls (~1.5s typical). At the old 1.0s pad, a short - # transmission (e.g. a 0.97s control-channel call) had its window close - # at T+1.97 while voice didn't start until ~T+1.5 — leaving ~0.4s of - # captured speech, clipped mid-word. Confirmed by a 0.57s output file - # whose final 0.10s measured -12.2dB, louder than its own -18.2dB - # average (i.e. clipped speech, not trailing silence), and by two short - # calls that produced no "Trimmed" log line at all because there was no - # trailing silence left to trim. + # Still needed, with a narrower job than before. It no longer pads the + # normal end of a call — that boundary now comes from the audio itself and + # needs no pad at all. It applies to the three boundaries that are still + # control-channel timestamps: # - # Safe to be generous here: trim_silence already strips trailing silence - # back to trim_silence_guard_seconds before upload, so a larger pad costs - # long calls nothing (the extra is trimmed away) while giving short - # transmissions enough window to actually capture the voice. Over-capture - # is free; under-capture loses words permanently. Do not tune this back - # down without new field data showing the grant->speech offset has - # shrunk — see DEFERRED.md for the call_idle_timeout coupling this value - # now sits at. + # tgid_change close the outgoing call at the new grant + pad + # tgid_change_unlogged close at the observing poll + pad + # idle_timeout console fallback mode only + # + # Safe to be generous: trim_silence strips trailing silence back to + # trim_silence_guard_seconds before upload, so a larger pad costs long calls + # nothing. Over-capture is free; under-capture loses words permanently. If + # 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 - # Strip leading/trailing dead air before upload. ~63% of a typical recording - # is silence (the grant→speech delay plus the tail pad), which inflates - # Whisper cost and is a well-documented trigger for hallucinated transcript - # text. Trimming is conservative — see internal/audio_trim.py. + # Strip leading/trailing dead air before upload. A recording deliberately + # over-captures at both ends (pre-roll at the head, the whole measured + # silence run at the tail), which inflates Whisper cost and is a + # 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 - # 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 # Guard margin kept around detected speech so no syllable is clipped. trim_silence_guard_seconds: float = 0.25 diff --git a/drb-edge-node/app/internal/audio_trim.py b/drb-edge-node/app/internal/audio_trim.py index 840da6c..cdae285 100644 --- a/drb-edge-node/app/internal/audio_trim.py +++ b/drb-edge-node/app/internal/audio_trim.py @@ -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 -talking. Measured on six real recordings from a live node, that costs 1.71–2.45 s -of dead air at the head of every single file, and the tail pad adds its own -~0.3–1.0 s. Roughly 63% of every uploaded MP3 was silence. That is not just -wasted Whisper spend: silence is a well-documented trigger for Whisper -hallucinating text that was never spoken, and a hallucinated sentence poisons -entity extraction and then incident correlation downstream. +talking; the recorder also deliberately over-captures at the tail (it closes a +call only after N seconds of silence have actually been HEARD). Both ends +therefore carry dead air. That is not just wasted Whisper spend: silence is a +well-documented trigger for Whisper hallucinating text that was never spoken, +and a hallucinated sentence poisons entity extraction and then incident +correlation downstream. 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. -If detection says the whole file is silent we do NOT emit a zero-length file — -the caller is told and decides (see call_recorder: it skips the upload and logs). +If detection says the whole buffer is silent we do NOT emit a zero-length +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 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 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 -dependency of this container and is already running the capture, so this adds no -new moving parts. `silenceremove` in one pass was rejected on purpose: it gives -no way to learn how much it removed, which would make the timing metadata above -impossible to produce. +HISTORY — THIS USED TO BE TWO FFMPEG PASSES. Detection was `silencedetect` +parsed out of FFmpeg's stderr, and the cut was a second FFmpeg re-encode. Both +are gone: the recorder now buffers PCM, so detection is arithmetic over the +samples and the cut is a byte-offset slice. Consequences worth keeping in mind: + + * 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 pathlib import Path -from typing import List, Optional, Tuple +from typing import Optional, Tuple from app.config import settings +from app.internal import pcm from app.internal.logger import logger -# Minimum run of quiet before FFmpeg calls it a silence region. Below ~0.3 s this -# starts firing on the natural pauses between words, which is not what we want — -# we only care about the big block of dead air at each end. -MIN_SILENCE_SECONDS = 0.3 +# Window the head/tail scan works in. 20 ms is short enough that the guard +# margin below dwarfs the quantisation error, and long enough that RMS means +# something. +ANALYSIS_WINDOW_SECONDS = 0.02 -# A silence region only counts as "leading" if it begins essentially at the file -# head. One chunk of slop. -HEAD_EPSILON_SECONDS = 0.15 - -# ...and only as "trailing" if it reaches the end of the audio. Do NOT assume a -# missing `silence_end` marks that case: FFmpeg 6.x flushes a closing -# `silence_end` at EOF, so an all-silence file looks exactly like a file with one -# closed silence region. Verified against ffmpeg 6.1.1 — the reported end lands -# ~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.]+)") +# How far in from each end the scan is willing to look before giving up. +# +# 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 +# starts on voice onset) and within the silence run at the tail, so this cap is +# never reached in practice. If it IS reached, we leave the audio untrimmed and +# say so — shipping an untrimmed recording is always better than shipping none. +MAX_SCAN_SECONDS = 30.0 @dataclass(frozen=True) class TrimResult: """Outcome of a trim attempt. `lead`/`tail` are seconds actually removed.""" - path: Optional[Path] lead: float = 0.0 tail: float = 0.0 duration_before: float = 0.0 duration_after: float = 0.0 all_silence: 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 def trimmed_seconds(self) -> float: return self.lead + self.tail -async def _run(cmd: List[str]) -> Tuple[int, str]: - """Run FFmpeg and return (returncode, stderr). FFmpeg reports on stderr.""" - 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 _window_bytes() -> int: + return max(pcm.FRAME_BYTES, pcm.byte_offset(ANALYSIS_WINDOW_SECONDS)) -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 - `start:` offset — the container duration is that much longer than the audio - silencedetect actually timestamps. Subtracting it is what lets - TAIL_EPSILON_SECONDS stay tight enough to be safe. + None means "no signal found" — either the buffer really is all silence or + the scan hit `limit_seconds` first; the caller distinguishes the two by + comparing the scanned span against the buffer length. """ - match = _DURATION_RE.search(stderr) - if not match: - 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 + window = _window_bytes() + 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 -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 - simply never emits the closing line for a region that reaches EOF. + Returns the offset one past the last signal-bearing window, so it can be + used directly as a slice bound. """ - regions: List[Tuple[float, Optional[float]]] = [] - pending: Optional[float] = None - for line in stderr.splitlines(): - if "silencedetect" not in line: - continue - start = _SILENCE_START_RE.search(line) - if start: - pending = float(start.group(1)) - continue - end = _SILENCE_END_RE.search(line) - 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 + window = _window_bytes() + total = pcm.align(len(audio)) + floor = max(0, total - (pcm.byte_offset(limit_seconds) or total)) + offset = total + while offset > floor: + start = max(floor, offset - window) + if not pcm.is_silent(audio[start:offset], threshold_db): + return offset + offset = start + return None -def speech_bounds( - regions: List[Tuple[float, Optional[float]]], - duration: float, - guard: float, -) -> Tuple[float, float, bool]: +def keep_window( + first_signal: Optional[int], + last_signal: Optional[int], + total_bytes: int, + 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 - FFmpeg. Returns (start, end, all_silence). + Pure and side-effect free so the decision that can destroy a transmission + stays unit-testable without any audio. Offsets are sample-aligned and + clamped to the buffer. """ - speech_start = 0.0 - speech_end = duration - - if regions: - head_start, head_end = regions[0] - if head_start <= HEAD_EPSILON_SECONDS and head_end is not None: - speech_start = head_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 + total = pcm.align(total_bytes) + 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) + start = pcm.align(start) + end = pcm.align(end) + if end <= start: + return 0, total + return start, end -async def trim_silence( - path: Path, - sample_rate: str, - bitrate: str, +def trim_pcm( + audio: bytes, threshold_db: 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", - because shipping an untrimmed recording is far better than shipping none. + An all-silence buffer is returned UNCHANGED with `all_silence=True`: 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), not something to silently truncate to nothing. """ 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 - try: - _, stderr = await _run([ - "ffmpeg", "-hide_banner", "-nostdin", "-nostats", - "-i", str(path), - "-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) + total = pcm.align(len(audio)) + duration = pcm.seconds(total) + if total <= 0: + return audio, TrimResult() - duration = _parse_duration(stderr) - if duration is None or duration <= 0: - logger.warning(f"Could not determine duration of {path.name} — uploading untrimmed.") - return TrimResult(path=path) - - 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). + first = first_signal_offset(audio, threshold) + if first is None: + scanned = min(total, pcm.byte_offset(MAX_SCAN_SECONDS) or total) + if scanned < total: + # Could not prove it is all silence; refuse to guess. + logger.warning( + 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"{path.name} is entirely silence ({duration:.2f}s, threshold {threshold}dB) — " + f"Recording is entirely silence ({duration:.2f}s, threshold {threshold:.1f}dBFS RMS) — " "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 - tail = duration - keep_end - if (lead + tail) < MIN_TRIM_SECONDS: - return TrimResult(path=path, duration_before=duration, duration_after=duration) + last = last_signal_offset(audio, threshold) + guard_bytes = pcm.byte_offset(margin) + keep_start, keep_end = keep_window(first, last, total, guard_bytes) - trimmed = path.with_name(f"{path.stem}_trimmed{path.suffix}") - try: - code, err = await _run([ - "ffmpeg", "-hide_banner", "-nostdin", "-nostats", - "-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) + lead = pcm.seconds(keep_start) + tail = pcm.seconds(total - keep_end) + if keep_start <= 0 and keep_end >= total: + return audio[:total], TrimResult(duration_before=duration, duration_after=duration) - if code != 0 or not trimmed.exists() or trimmed.stat().st_size == 0: - logger.warning(f"Silence trim produced no output for {path.name} ({err.strip()}) — uploading untrimmed.") - trimmed.unlink(missing_ok=True) - return TrimResult(path=path, duration_before=duration, duration_after=duration) - - trimmed.replace(path) + kept = audio[keep_start:keep_end] + after = pcm.seconds(len(kept)) logger.info( - f"Trimmed {path.name}: -{lead:.2f}s lead, -{tail:.2f}s tail " - f"({duration:.2f}s → {keep_end - keep_start:.2f}s)" + f"Trimmed recording: -{lead:.2f}s lead, -{tail:.2f}s tail " + f"({duration:.2f}s -> {after:.2f}s, threshold {threshold:.1f}dBFS RMS)" ) - return TrimResult( - path=path, + return kept, TrimResult( lead=lead, tail=tail, duration_before=duration, - duration_after=keep_end - keep_start, + duration_after=after, applied=True, ) diff --git a/drb-edge-node/app/internal/call_recorder.py b/drb-edge-node/app/internal/call_recorder.py index 2ac660e..602696f 100644 --- a/drb-edge-node/app/internal/call_recorder.py +++ b/drb-edge-node/app/internal/call_recorder.py @@ -1,16 +1,26 @@ """ 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 per call used to lose the first 1-2 s to process startup, which meant short 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: 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 - still seek back to OP25's exact timestamp. It is sized for + only job is PRE-ROLL: however late the segmenter notices voice + onset, we can still seek back before it. It is sized for detection latency, nothing else. 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 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 slice timestamps and audio content diverge without bound. Icecast stays in the 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 at most the calls in flight at that instant; the buffer self-heals within 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 time @@ -42,57 +66,72 @@ from typing import List, Optional, Tuple import httpx 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 # Safety cap on a single recording; mirrors MAX_SEGMENT_SECONDS in metadata_watcher. MAX_RECORDING_SECONDS = 600 -# Audio included ahead of OP25's call_log timestamp. The grant is logged when the -# channel is granted, so the first syllable can land marginally before it. +# Audio included ahead of the detected voice onset. # -# Kept small on purpose: measurement on a live node shows 1.71–2.45 s of real -# grant→speech delay on every call, so there is no clipping risk at the head and -# a larger pre-roll would only add dead air. +# Under audio-driven segmentation this is no longer covering a variable +# control-channel offset — it covers exactly two things: the analysis chunk +# 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 # 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 + -# up to 3 s httpx timeout on a stalled poll + callback work ≈ 4 s from grant to -# start_recording(). 30 s is ~7x that margin, and at 16 kbps costs only ~60 KB of -# RAM. This value does NOT bound call length — the accumulator does. +# detection latency: the segmenter polls every 0.5 s and can stall for up to a +# 3 s httpx timeout on a bad OP25 poll, so ~4 s from onset to start_recording(). +# 30 s is ~7x that margin. At 44.1 KB/s of PCM it costs ~1.3 MB of RAM. This +# value does NOT bound call length — the accumulator does. RING_BUFFER_SECONDS = 30 -# ~128 ms of audio per chunk at 16 kbps. Chunk size IS the timestamp resolution of -# the ring buffer, so it must stay well under PRE_ROLL_SECONDS — the old 4096-byte -# reads were ~2 s per chunk, which made sub-second slicing meaningless. -READ_CHUNK_BYTES = 256 +# ~46 ms of audio per chunk. Chunk size is BOTH the timestamp resolution of the +# ring buffer AND the window silence detection runs over, so it has to stay well +# under PRE_ROLL_SECONDS and well under the shortest utterance we care about. +READ_CHUNK_BYTES = 2048 -# Encoder settings, matched on purpose to what Liquidsoap already pushes to -# Icecast — %mp3(bitrate=16, samplerate=22050, stereo=false) — so the C2 /upload -# endpoint keeps receiving exactly the kind of MP3 it has always received -# (multipart "audio/mpeg", stored to GCS as .mp3, then fed to Whisper). -# Change both of these together if you ever want higher-fidelity uploads. +# Encoder settings for the single encode at save time, matched on purpose to +# what Liquidsoap already pushes to Icecast — %mp3(bitrate=16, samplerate=22050, +# stereo=false) — so the C2 /upload endpoint keeps receiving exactly the kind of +# MP3 it has always received (multipart "audio/mpeg", stored to GCS as .mp3, +# 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_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 -# call is ~1.2 MB; 4x that is the ceiling, which both leaves room for encoder -# overshoot and guarantees a runaway call can never eat a Pi's RAM. -_MP3_BYTES_PER_SECOND = 16_000 // 8 -MAX_RECORDING_BYTES = MAX_RECORDING_SECONDS * _MP3_BYTES_PER_SECOND * 4 +# Bounded so a wedged encoder can never stall the upload path. +ENCODE_TIMEOUT_SECONDS = 60.0 + +# Hard memory ceiling for one call's accumulator. +# +# 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 -# call's end timestamp. PulseAudio → FFmpeg → MP3 encoder → muxer → our pipe read -# is a pipeline with latency, so at the instant a call ends the newest buffered -# chunk is typically a few hundred ms OLDER than the end epoch. Slicing -# immediately therefore cuts the tail short — which costs the last word of the -# transmission, usually the disposition or the address. Bounded so a dead capture -# can never hang the upload path. +# call's end timestamp. PulseAudio → FFmpeg → our pipe read is a pipeline with +# latency, so at the instant a CONTROL-CHANNEL derived end is computed the +# newest buffered chunk is typically a few hundred ms OLDER than that epoch. +# Slicing immediately therefore cuts the tail short — which costs the last word +# of the transmission, usually the disposition or the address. # -# Must exceed settings.call_tail_pad_seconds (default 3.0), otherwise a -# tgid_change close — which pads past a timestamp that is still ~now — gives up -# before the padded audio has been captured and warns on every talkgroup switch. +# An audio-driven close never needs this (its end epoch is derived from audio +# that is already buffered, by construction), but a tgid_change close still +# 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_POLL_SECONDS = 0.05 @@ -114,12 +153,38 @@ _SOURCE_MISSING_MARKERS = ("no such process", "no such device") _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 class _ActiveRecording: """Audio accumulating for the call currently being recorded.""" 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 chunks: List[Tuple[float, bytes]] = field(default_factory=list) total_bytes: int = 0 @@ -140,7 +205,7 @@ class Recording: 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 @@ -153,13 +218,66 @@ class Recording: 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: """Continuous PulseAudio capture: ring buffer for pre-roll, accumulator per call.""" def __init__(self): 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. self._buffer: deque[Tuple[float, bytes]] = deque() self._buffer_bytes: int = 0 @@ -168,6 +286,10 @@ class CallRecorder: self._proc: Optional[asyncio.subprocess.Process] = None 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) self._active: Optional[_ActiveRecording] = None @@ -204,14 +326,12 @@ class CallRecorder: "-hide_banner", "-nostdin", "-nostats", "-loglevel", "warning", "-f", "pulse", "-i", settings.pulse_source, - "-ac", "1", + "-ac", str(pcm.CHANNELS), "-ar", MP3_SAMPLE_RATE, - "-b:a", MP3_BITRATE, - # Without this, the MP3 muxer fills its 32 KB AVIO buffer before - # writing anything — 16 s of audio per burst at 16 kbps, which would - # destroy the arrival timestamps the slicing depends on. - "-flush_packets", "1", - "-f", "mp3", "-", + # Raw PCM on stdout. No muxer, so no -flush_packets games: s16le is + # a bare byte stream and every byte FFmpeg produces is immediately + # readable, which is what keeps arrival timestamps honest. + "-f", "s16le", "-", ] async def _capture_loop(self) -> None: @@ -240,7 +360,7 @@ class CallRecorder: async def _run_capture(self) -> None: 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() proc = await asyncio.create_subprocess_exec( *cmd, @@ -252,8 +372,14 @@ class CallRecorder: try: assert proc.stdout is not None while True: - chunk = await proc.stdout.read(READ_CHUNK_BYTES) - if not chunk: + # readexactly, not read: a fixed chunk keeps every analysis + # 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 if not self._capturing: self._capturing = True @@ -339,9 +465,44 @@ class CallRecorder: except Exception: 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: """Append a chunk to the ring buffer and, if recording, the accumulator.""" now = time.time() + self._note_voice(chunk, now) + self._buffer.append((now, 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: """ - Open a recording. `start_epoch` is OP25's call_log timestamp (host wall - clock); the slice begins PRE_ROLL_SECONDS before it. Omit it only when no - OP25 timestamp is available — then we fall back to "now", losing precision. + Open a recording. `start_epoch` is the detected voice onset (host wall + clock, same clock as the chunk stamps); the slice begins + 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: 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 if oldest is not None and slice_start < oldest: # Pre-roll predates the buffer: node just started, capture restarted, - # or OP25's timestamp is far in the past. Clamp and say so LOUDLY — - # this is silent audio loss otherwise. + # or the onset is far in the past. Clamp and say so LOUDLY — this is + # silent audio loss otherwise. clamped = oldest - slice_start logger.warning( 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})") 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]: """ - 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 - slicing — see TAIL_WAIT_TIMEOUT_SECONDS. Returns None only when there was - no recording open or no audio at all. + slicing — see TAIL_WAIT_TIMEOUT_SECONDS. An audio-driven close never + 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 if active is None: @@ -439,19 +616,21 @@ class CallRecorder: await self._await_tail(end, call_id) self._active = None - chunks: List[bytes] = [] + parts: List[bytes] = [] + total = 0 last_ts = slice_start for ts, chunk in active.chunks: if ts < slice_start: continue - chunks.append(chunk) + parts.append(chunk) + total += len(chunk) last_ts = ts if ts >= end: # Include the chunk straddling `end` so the tail is never clipped, # then stop. break - if not chunks: + if not parts: logger.warning( f"No buffered audio for call {call_id} " 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." ) - 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}_{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)") - + raw = b"".join(parts) recording = Recording( call_id=call_id, - path=output_path, + path=None, audio_start_epoch=slice_start, - audio_end_epoch=audio_end, + audio_end_epoch=slice_start + pcm.seconds(len(raw)), 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: """ @@ -519,41 +724,6 @@ class CallRecorder: ) 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) # ------------------------------------------------------------------ diff --git a/drb-edge-node/app/internal/metadata_watcher.py b/drb-edge-node/app/internal/metadata_watcher.py index eee282d..b1d88cb 100644 --- a/drb-edge-node/app/internal/metadata_watcher.py +++ b/drb-edge-node/app/internal/metadata_watcher.py @@ -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 -appeared in channel_update" and call end from N polls of silence) with the two -authoritative signals OP25 actually exposes: + START first chunk of audio above the silence threshold (voice onset). + STOP settings.call_silence_timeout seconds of continuous silence HEARD in + 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 - its own time.time(). This is an exact start timestamp, not the moment - our poll happened to notice, so recordings can be sliced back to it. +WHY THE CONTROL CHANNEL NO LONGER DECIDES BOUNDARIES. The previous design +started a segment on an OP25 `call_log` grant and ended it by inferring from the +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`. - OP25 never reports call termination externally: internally it ends a - call on the P25 Terminator Data Unit (duid15) or 3 voice-framing - timeouts, but neither becomes a log entry. What *is* observable is that - `srcaddr`/`svcopts` reset to 0/false the instant the call ends, while - `tgid`/`hold_tgid` keep showing the just-ended talkgroup for - TGID_HOLD_TIME (2 s). So the srcaddr edge is a real state change, not a - timeout heuristic. + * The grant fires 0.84-1.62 s (variable) before anyone speaks, so a + grant-anchored window is always guessing at the offset. + * `srcaddr` can drop to 0 WHILE SOMEONE IS STILL TALKING. Measured across six + recordings, five had healthy trailing silence trimmed (-0.53 s to -2.48 s) + but one reported "-1.61s lead, -0.00s tail" — the trim found nothing to + remove because the capture window had closed on top of live speech. The + recording ends on an unfinished word. Working backwards from its lead trim, + 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 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 -for settings.call_idle_timeout seconds. +the same talkgroup and closes when the talkgroup changes or the AUDIO goes quiet +for settings.call_silence_timeout seconds. 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 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 time import uuid +from collections import deque +from dataclasses import dataclass, field from datetime import datetime, timezone from typing import Optional, Callable, Awaitable, Any, List, Dict from app.config import settings +from app.internal.call_recorder import AudioActivity from app.internal.op25_client import op25_client from app.internal.logger import logger CallbackFn = Callable[[dict], Awaitable[None]] +ActivityFn = Callable[[], AudioActivity] -# 500 ms. Do NOT lower: start precision already comes from OP25's own timestamp, -# and http_server.py's request handler has a ~200 ms blocking floor anyway. +# 500 ms. Do NOT lower: audio boundaries come from the recorder's own chunk +# 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 -# 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 # 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 +# 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: """ - Audio kept after the observed end of the last transmission, so the srcaddr - edge (up to one poll late) plus encoder latency never clips the tail. + Audio kept past a CONSOLE-DERIVED segment boundary, to cover the fact that + buffered audio lags control-channel timestamps. - Read live from settings (env CALL_TAIL_PAD_SECONDS) rather than frozen into a - module constant, so it is tunable per node. See the setting in config.py for - why the default moved 1.0 → 3.0 (short calls' recording window was closing - before the ~1.5s grant→speech offset let voice audio even start). + Under audio-driven segmentation this no longer applies to the normal end of + a call — that boundary now comes from the audio itself and needs no pad. It + still applies wherever a boundary is a control-channel timestamp: - All three close paths use this pad: idle_timeout, tgid_change, and - tgid_change_unlogged. An earlier version of this docstring claimed the - latter two close at "an exact, already-known boundary" (the new grant's - timestamp, or the same poll tick) and so intentionally added no pad — THAT + tgid_change close at the new grant's timestamp + pad + tgid_change_unlogged close at the observing poll's timestamp + pad + idle_timeout console fallback mode only + + 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 exact only in CONTROL-CHANNEL time; the buffered AUDIO lags control-channel - timestamps by ~1.5s (measured: 0.84-1.62s 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 - roughly the last 1.5s of its real speech — calls ending mid-word with ~0s - trailing silence. Do not reintroduce a zero-pad close for tgid_change or - tgid_change_unlogged; if the outgoing and incoming recordings end up - overlapping in the underlying audio because of this pad, that is correct — - the audio genuinely contains both. See _handle_call_log and - _handle_channels for how each path sources the timestamp this gets added to. + roughly the last 1.5 s of its real speech. Do not reintroduce a zero-pad + close for tgid_change or tgid_change_unlogged; if the outgoing and incoming + recordings end up overlapping in the underlying audio because of this pad, + that is correct — the audio genuinely contains both. """ return settings.call_tail_pad_seconds @@ -104,6 +183,35 @@ def _iso(epoch: Optional[float]) -> Optional[str]: 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: def __init__(self): self._running = False @@ -114,21 +222,38 @@ class MetadataWatcher: self._current_tgid_name: Optional[str] = None self._current_freq: Any = 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 + # 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._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_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. self._clock: Callable[[], float] = time.time # Set these before calling start() self.on_call_start: 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 @@ -138,7 +263,7 @@ class MetadataWatcher: self._running = True self._last_ok_poll = self._clock() 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): self._running = False @@ -168,6 +293,307 @@ class MetadataWatcher: return 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 # 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): 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) async def _handle_call_log(self, entry: Dict[str, Any], now: float) -> None: tgid = _as_int(entry.get("tgid")) 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")) 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: - await self._open_segment(entry, tgid, started_at, now) + await self._open_from_console(entry, tgid, started_at, now) 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._tx_active = True self._last_tx_end = None @@ -204,18 +627,8 @@ class MetadataWatcher: self._refresh_meta_from_log(entry) 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._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: if self._active_call_id is None: @@ -241,19 +654,13 @@ class MetadataWatcher: self._last_tx_end = None self._last_activity = now 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._last_tx_end = 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: logger.warning( f"tgid {foreign_active_tgid} active without a call_log entry — " @@ -263,14 +670,6 @@ class MetadataWatcher: return 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: measured_idle = now - self._last_tx_end 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.") 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 # ------------------------------------------------------------------ @@ -311,35 +722,48 @@ class MetadataWatcher: if not self._current_freq and 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._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._current_tgid_name = tgid_name + self._current_freq = freq + self._current_srcaddr = srcaddr 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 - # channel scan. A grant whose call already ended before we polled simply - # closes on the very next tick via the idle timeout. - self._tx_active = True + # Console fallback assumes the transmission is still up; it learns + # otherwise from the next channel scan. + self._tx_active = not audio_driven self._last_tx_end = None self._last_activity = now payload = { "call_id": self._active_call_id, "tgid": tgid, - "tgid_name": self._current_tgid_name, - "freq": self._current_freq, - "srcaddr": self._current_srcaddr, + "tgid_name": tgid_name, + "freq": freq, + "srcaddr": srcaddr, "started_at": _iso(started_at), # Raw epoch for the recorder's ring-buffer slice — same clock domain. "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( 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: await self.on_call_start(payload) @@ -352,6 +776,10 @@ class MetadataWatcher: if started_at is not None: 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 = { "call_id": self._active_call_id, "tgid": self._current_tgid, @@ -364,12 +792,29 @@ class MetadataWatcher: "ended_at_epoch": end_epoch, "transmissions": self._transmissions, "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 - logger.info( - f"Call end: id={self._active_call_id} tgid={self._current_tgid} " - f"reason={reason} transmissions={self._transmissions} duration={duration:.2f}s" - ) + + 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( + f"Call end: id={self._active_call_id} tgid={self._current_tgid} " + f"reason={reason} transmissions={self._transmissions} duration={duration:.2f}s" + ) # Clear state before awaiting so a re-entrant tick can't see a half-closed # segment (and so an immediately-following _open_segment is clean). @@ -382,10 +827,57 @@ class MetadataWatcher: self._transmissions = 0 self._tx_active = False self._last_tx_end = None + self._audio_driven = False if self.on_call_end: 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) # ------------------------------------------------------------------ @@ -406,5 +898,10 @@ class MetadataWatcher: def is_active(self) -> bool: 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() diff --git a/drb-edge-node/app/internal/pcm.py b/drb-edge-node/app/internal/pcm.py new file mode 100644 index 0000000..51a66ea --- /dev/null +++ b/drb-edge-node/app/internal/pcm.py @@ -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 diff --git a/drb-edge-node/app/main.py b/drb-edge-node/app/main.py index f22caf5..1e4df34 100644 --- a/drb-edge-node/app/main.py +++ b/drb-edge-node/app/main.py @@ -30,21 +30,56 @@ def _iso(epoch: Optional[float]) -> Optional[str]: 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): radio_bot.start_stream() await mqtt_manager.publish_status("recording") - await mqtt_manager.publish_metadata("call_start", data) - # started_at_epoch is OP25's own call_log timestamp — the recorder slices the - # ring buffer back to it (minus pre-roll), so however late we detected the - # grant, the audio still starts in the right place. + # started_at_epoch is the detected voice onset (or, in console fallback mode, + # OP25's call_log timestamp). The recorder slices the ring buffer back to it + # minus the pre-roll, so however late the poll loop noticed, the audio still + # starts in the right place. await call_recorder.start_recording( data["call_id"], 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): 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")) 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 " 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_status("online") @@ -225,6 +272,10 @@ async def lifespan(app: FastAPI): # Wire callbacks metadata_watcher.on_call_start = on_call_start 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_config_push = on_config_push mqtt_manager.on_api_key = on_api_key diff --git a/drb-edge-node/app/routers/api.py b/drb-edge-node/app/routers/api.py index fa9a740..29d84b0 100644 --- a/drb-edge-node/app/routers/api.py +++ b/drb-edge-node/app/routers/api.py @@ -49,9 +49,16 @@ async def get_status(): "system_name": system_name, "is_recording": call_recorder.is_recording, # 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, "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_name": active_tgid_name, "active_call_id": metadata_watcher.active_call_id, diff --git a/drb-edge-node/tests/test_audio_trim.py b/drb-edge-node/tests/test_audio_trim.py index c19fb6a..d84337b 100644 --- a/drb-edge-node/tests/test_audio_trim.py +++ b/drb-edge-node/tests/test_audio_trim.py @@ -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 -that can destroy a transmission if it is wrong — is testable without FFmpeg. -The numbers below come from ffmpeg silencedetect run against six real recordings -off a live P25 node: 1.71–2.45 s of leading silence and 0.00–1.11 s trailing. +`keep_window` is pure on purpose so the "what do we keep" decision — the part +that can destroy a transmission if it is wrong — stays testable without any +audio at all. The rest of the file drives the real detector over synthesised +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 +from app.config import settings +from app.internal import audio_trim, pcm from app.internal.audio_trim import ( TrimResult, - _parse_duration, - _parse_silences, - speech_bounds, + first_signal_offset, + keep_window, + last_signal_offset, + trim_pcm, ) 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(): - # Real shape of file f4bfaa1f: 1.85s lead, 0.34s trail, 4.54s total. - regions = [(0.0, 1.85), (4.20, None)] - 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 speech(seconds: float) -> bytes: + count = int(pcm.SAMPLE_RATE * seconds) + return array("h", [SPEECH_LEVEL, -SPEECH_LEVEL] * (count // 2)).tobytes() -def test_guard_margin_never_runs_past_the_file_bounds(): - regions = [(0.0, 0.10), (3.95, None)] - start, end, _ = speech_bounds(regions, duration=4.0, guard=1.0) - - 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 +def silence(seconds: float, level: int = FLOOR_LEVEL) -> bytes: + count = int(pcm.SAMPLE_RATE * seconds) + return array("h", [level, -level] * (count // 2)).tobytes() # --------------------------------------------------------------------------- -# FFmpeg output parsing +# keep_window — the pure decision # --------------------------------------------------------------------------- -# Verbatim shape of ffmpeg 6.1.1 output. -FFMPEG_STDERR = """ -Input #0, mp3, from '/recordings/x.mp3': - Duration: 00:00:04.70, start: 0.050113, bitrate: 16 kb/s -[silencedetect @ 0000029160e63f40] silence_start: 0 -[silencedetect @ 0000029160e63f40] silence_end: 2.05361 | silence_duration: 2.05361 -[silencedetect @ 0000029160e63f40] silence_start: 3.56367 -[silencedetect @ 0000029160e63f40] silence_end: 4.63102 | silence_duration: 1.06735 -[out#0/null @ 0x2] video:0kB audio:97kB -""" - -FFMPEG_STDERR_OPEN_TAIL = """ - Duration: 00:00:04.54, start: 0.000000, bitrate: 16 kb/s -[silencedetect @ 0x1] silence_start: 0 -[silencedetect @ 0x1] silence_end: 1.85042 | silence_duration: 1.85042 -[silencedetect @ 0x1] silence_start: 4.20134 -""" +def test_guard_margin_is_kept_around_detected_speech(): + guard = pcm.byte_offset(GUARD) + start, end = keep_window( + first_signal=pcm.byte_offset(1.85), + last_signal=pcm.byte_offset(4.20), + total_bytes=pcm.byte_offset(4.54), + guard_bytes=guard, + ) + 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_duration_is_corrected_for_the_mp3_container_start_offset(): +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(): """ - MP3 encoder delay makes the container duration longer than the audio - silencedetect timestamps. Without this correction the trailing-region test - needs a slack epsilon big enough to clip real speech. + The recorder deliberately over-captures the tail (it closes only after the + silence timeout has actually elapsed in the audio), so `tail` is how the + real silence run reaches the logs. """ - assert _parse_duration(FFMPEG_STDERR) == pytest.approx(4.70 - 0.050113) + 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_none_when_absent(): - assert _parse_duration("no duration here") is None +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_silence_regions_are_parsed(): - regions = _parse_silences(FFMPEG_STDERR) - - 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_digital_silence_at_the_measured_field_floor_is_detected(): + """ + The -91 dBFS floor is the whole reason this needs no field calibration. + Detection must not depend on the threshold being tuned to a noise floor. + """ + 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_a_region_with_no_silence_end_is_still_parsed(): - """Older FFmpeg simply stopped reporting at EOF — keep handling that.""" - regions = _parse_silences(FFMPEG_STDERR_OPEN_TAIL) +def test_audio_with_no_silence_at_either_end_is_left_alone(): + audio = speech(3.0) + kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD) - assert regions[-1][1] is None + assert not result.applied + assert kept == audio + assert result.duration_before == pytest.approx(result.duration_after) + + +def test_an_empty_buffer_is_handled(): + kept, result = trim_pcm(b"", threshold_db=-40.0, guard=GUARD) + assert kept == b"" and not result.applied and not result.all_silence + + +def test_thresholds_default_to_settings(): + audio = silence(1.0) + speech(1.0) + silence(1.0) + _, 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) + + +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(): - result = TrimResult(path=None, lead=1.9, tail=0.35) - assert result.trimmed_seconds == pytest.approx(2.25) + assert TrimResult(lead=1.9, tail=0.35).trimmed_seconds == pytest.approx(2.25) diff --git a/drb-edge-node/tests/test_call_recorder.py b/drb-edge-node/tests/test_call_recorder.py index 0727932..2ebf64f 100644 --- a/drb-edge-node/tests/test_call_recorder.py +++ b/drb-edge-node/tests/test_call_recorder.py @@ -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 -clock, which is exactly what the capture loop does at runtime. Silence trimming -is disabled by default here and exercised separately with a stubbed trimmer. +clock, which is exactly what the capture loop does at runtime, and the MP3 +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 itertools import time +from array import array from typing import List from unittest.mock import patch @@ -15,7 +19,7 @@ import pytest from app.config import settings 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 ( CallRecorder, MAX_RECORDING_BYTES, @@ -25,11 +29,42 @@ from app.internal.call_recorder import ( ) 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 -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) r = CallRecorder() r._recordings_dir = tmp_path @@ -37,64 +72,51 @@ def recorder(tmp_path, monkeypatch): return r -def ingest(recorder, start: float, end: float, marker: bytes = b"A", index: int = 0) -> int: - """Feed one chunk every CHUNK_INTERVAL seconds over [start, end) through _ingest.""" +def ingest(recorder, start: float, end: float, chunk: bytes = VOICE) -> None: + """Feed one chunk every CHUNK_INTERVAL seconds over [start, end).""" stamps: List[float] = [] - chunks: List[bytes] = [] ts = start while ts < end: stamps.append(ts) - chunks.append(marker + str(index).encode() + b";") - index += 1 ts = round(ts + CHUNK_INTERVAL, 6) - + if not stamps: + return with patch("app.internal.call_recorder.time.time", side_effect=stamps): - for chunk in chunks: + for _ in stamps: recorder._ingest(chunk) - return index -def fill(recorder, start: float, end: float, marker: bytes = b"A", index: int = 0) -> int: - """Alias kept for readability where the accumulator is not the point.""" - return ingest(recorder, start, end, marker=marker, index=index) +def duration_of(path) -> float: + return pcm.seconds(len(path.read_bytes())) def timestamps(recorder): 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) # --------------------------------------------------------------------------- def test_idle_buffer_keeps_only_the_rolling_window(recorder): - for offset in range(0, int(RING_BUFFER_SECONDS) + 20): - with patch("app.internal.call_recorder.time.time", return_value=T0 + offset): - recorder._ingest(b"x" * 16) + ingest(recorder, T0, T0 + RING_BUFFER_SECONDS + 20) - assert len(recorder._buffer) <= RING_BUFFER_SECONDS + 1 - assert min(timestamps(recorder)) >= (T0 + RING_BUFFER_SECONDS + 19) - RING_BUFFER_SECONDS + assert recorder.buffered_seconds <= RING_BUFFER_SECONDS + CHUNK_INTERVAL + newest = max(timestamps(recorder)) + assert min(timestamps(recorder)) >= newest - RING_BUFFER_SECONDS @pytest.mark.asyncio 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 - it — that was the mechanism that made call length depend on buffer size. + The ring buffer serves PRE-ROLL only. An open recording must not pin it — + 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) - 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. assert recorder._active is not None 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 end = grant + call_length - index = ingest(recorder, T0, grant) + ingest(recorder, T0, 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) assert rec is not None and rec.path is not None - kept = indices(rec.path) - # Contiguous: no hole anywhere in the middle of a 65s call. - assert kept == list(range(kept[0], kept[-1] + 1)) - 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) + captured = duration_of(rec.path) + assert captured > RING_BUFFER_SECONDS, "call length must not be clamped by the ring buffer" + assert captured == pytest.approx(call_length + PRE_ROLL_SECONDS, abs=2 * CHUNK_INTERVAL) @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.""" 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 + # An unbounded clock: patching time.time patches it for everything running + # inside the block, not only for our calls. ticks = itertools.count() with caplog.at_level("WARNING", logger="drb-edge-node"): 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) +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 # --------------------------------------------------------------------------- @pytest.mark.asyncio -async def test_slice_starts_pre_roll_before_the_op25_timestamp(recorder): - fill(recorder, T0, T0 + 10.0) - grant_time = T0 + 5.0 +async def test_slice_starts_pre_roll_before_the_detected_onset(recorder): + ingest(recorder, T0, T0 + 10.0) + onset = T0 + 5.0 - await recorder.start_recording("call-1", start_epoch=grant_time) - assert recorder._active.slice_start == pytest.approx(grant_time - PRE_ROLL_SECONDS) + await recorder.start_recording("call-1", start_epoch=onset) + 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() - first_ts = T0 + indices(rec.path)[0] * CHUNK_INTERVAL - - # A chunk stamped `ts` holds the audio that arrived over [ts - interval, ts], - # so the audio actually covered must begin at or before the requested slice - # start — erring early is the safe direction, erring late loses speech. - 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 + first_ts = recorder._active.chunks[0][0] if recorder._active else None + assert first_ts is None # recording closed + # The audio actually covered must begin at or before the requested slice + # start — erring early is safe, erring late loses speech. + assert rec.audio_start_epoch <= onset - PRE_ROLL_SECONDS + 1e-6 @pytest.mark.asyncio 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) - # End halfway through a chunk interval. 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 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) - 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) - 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 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 - instant a call ends the newest captured chunk is OLDER than the end epoch. - Slicing immediately cuts the last word off. stop_recording must wait for it. + A tgid_change close pads past a control-channel timestamp that is ~now, so + the audio it asks for has not been captured yet. Slicing immediately would + 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) async def late_tail(): await asyncio.sleep(0.15) 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()) 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 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), \ "a tail wait must be observable in the field logs" - assert index # sanity: the pre-roll fill actually ran @pytest.mark.asyncio @@ -245,6 +332,10 @@ async def test_tail_wait_is_bounded_and_warns_when_audio_never_arrives(recorder, @pytest.mark.asyncio 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) 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 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 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) 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 any("BUFFER CLAMP" in r.message for r in caplog.records) @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) assert await recorder.stop_recording(end_epoch=T0 + 2.0) is None + assert encodes == [], "nothing to encode means no encoder subprocess" @pytest.mark.asyncio async def test_start_epoch_omitted_falls_back_to_now(recorder): now = time.time() - fill(recorder, now - 5.0, now) + ingest(recorder, now - 5.0, now) await recorder.start_recording("call-1") 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 # --------------------------------------------------------------------------- -async def _recorded(recorder, end_offset: float = 3.0): - ingest(recorder, T0, T0 + 10.0) - await recorder.start_recording("call-1", start_epoch=T0 + 1.0) - return await recorder.stop_recording(end_epoch=T0 + end_offset) +async def _recorded(recorder, lead_silence=1.0, voice=2.0, tail_silence=1.0): + start = T0 + ingest(recorder, start, start + lead_silence, chunk=QUIET) + 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 @@ -306,12 +448,12 @@ async def test_trimming_is_off_when_the_setting_is_off(recorder, monkeypatch): monkeypatch.setattr(settings, "trim_silence", False) called = False - async def _never(*args, **kwargs): + def _never(*args, **kwargs): nonlocal called 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) 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) - async def _trim(path, **kwargs): - return TrimResult(path=path, lead=1.9, tail=0.4, duration_before=3.3, - duration_after=1.0, applied=True) + rec = await _recorded(recorder, lead_silence=1.0, voice=2.0, tail_silence=1.5) - 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.lead_trimmed == pytest.approx(1.9) - assert rec.tail_trimmed == pytest.approx(0.4) - # Untrimmed slice was [T0+0.75, T0+3.0]; the audio now starts 1.9s later and - # ends 0.4s earlier, which is exactly what downstream needs to map an audio - # offset back to wall clock. - 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 - 0.4, abs=CHUNK_INTERVAL) + assert rec.lead_trimmed > 0.0 and rec.tail_trimmed > 0.0 + guard = settings.trim_silence_guard_seconds + # Slice began at T0+0.25; speech begins at T0+1.0, so the audio now starts + # one guard margin before the speech. + assert rec.audio_start_epoch == pytest.approx(T0 + 1.0 - guard, abs=3 * CHUNK_INTERVAL) + assert rec.audio_end_epoch == pytest.approx(T0 + 3.0 + guard, abs=3 * CHUNK_INTERVAL) + assert rec.audio_end_epoch > rec.audio_start_epoch @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) - seen = {} - - 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) + ingest(recorder, T0, T0 + 5.0, chunk=QUIET) + await recorder.start_recording("call-1", start_epoch=T0 + 1.0) 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.all_silence is True 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) @@ -369,7 +501,7 @@ async def test_all_silence_recording_is_dropped_and_logged(recorder, monkeypatch @pytest.mark.asyncio 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-2", start_epoch=T0 + 2.0) is False assert recorder.is_recording @@ -381,6 +513,21 @@ async def test_stop_without_start_is_a_noop(recorder): 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 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 # --------------------------------------------------------------------------- -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() joined = " ".join(cmd) assert "-f pulse" in joined 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 - # writing, which would destroy the ring buffer's timestamp resolution. - assert "-flush_packets" in cmd - assert cmd[-1] == "-" and cmd[-2] == "mp3", "must emit MP3 on stdout for /upload" + assert cmd[-1] == "-" and cmd[-2] == "s16le", "capture must emit raw PCM on stdout" + assert "mp3" not in joined, "MP3 now happens once at save time, not in the capture" + assert "-ar" in cmd and str(pcm.SAMPLE_RATE) in cmd + assert "-ac" in cmd and str(pcm.CHANNELS) in cmd -def test_memory_ceiling_covers_the_longest_allowed_call(): - """The cap must bound RAM without ever being able to truncate a legal call.""" - bytes_per_second = 16_000 // 8 - assert MAX_RECORDING_BYTES >= MAX_RECORDING_SECONDS * bytes_per_second +def test_read_chunk_is_finer_than_the_pre_roll(recorder): + """ + Chunk size is both the ring buffer's timestamp resolution and the window + 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() assert _log_levels(caplog) == ["WARNING"] - assert MAX_RECORDING_BYTES <= 8 * 1024 * 1024, "must stay small enough for a Pi" diff --git a/drb-edge-node/tests/test_metadata_watcher.py b/drb-edge-node/tests/test_metadata_watcher.py index 65e8b86..e240fce 100644 --- a/drb-edge-node/tests/test_metadata_watcher.py +++ b/drb-edge-node/tests/test_metadata_watcher.py @@ -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 -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. +TWO MODES, both covered here: + + 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 from unittest.mock import AsyncMock, patch from app.config import settings +from app.internal.call_recorder import AudioActivity from app.internal.metadata_watcher import ( + ATTRIBUTION_LOOKAHEAD_SECONDS, + ATTRIBUTION_LOOKBACK_SECONDS, + MAX_SEGMENT_SECONDS, MetadataWatcher, OP25_OFFLINE_GRACE, ) @@ -37,6 +52,7 @@ def clock(): @pytest.fixture def watcher(clock): + """Console fallback mode: no audio provider wired, capture assumed down.""" w = MetadataWatcher() w._clock = clock w.on_call_start = AsyncMock() @@ -44,6 +60,58 @@ def watcher(clock): 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): """One OP25 call_log entry (see tk_p25.log_call).""" 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 @@ -578,3 +651,499 @@ async def test_end_never_precedes_start(watcher, clock): payload = watcher.on_call_end.call_args[0][0] 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) diff --git a/drb-edge-node/tests/test_pcm.py b/drb-edge-node/tests/test_pcm.py new file mode 100644 index 0000000..c7b58b7 --- /dev/null +++ b/drb-edge-node/tests/test_pcm.py @@ -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)