Compare commits
6 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| d6dfe5a293 | |||
| 085fcdf1a1 | |||
| f1de157d69 | |||
| ceb2836371 | |||
| 7c4a3f2f20 | |||
| b0a8ed2a5a |
+45
-2
@@ -29,10 +29,53 @@ 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.
|
||||
# --- 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 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. 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 (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
|
||||
|
||||
# OP25 container (usually no need to change)
|
||||
OP25_API_URL=http://localhost:8001
|
||||
OP25_TERMINAL_URL=http://localhost:8081
|
||||
|
||||
@@ -5,6 +5,7 @@ RUN apt-get update && apt-get install -y \
|
||||
libopus0 \
|
||||
libopus-dev \
|
||||
libpulse0 \
|
||||
pulseaudio-utils \
|
||||
&& rm -rf /var/lib/apt/lists/*
|
||||
|
||||
WORKDIR /app
|
||||
@@ -14,5 +15,8 @@ RUN pip install uv && uv pip install --system --no-cache-dir -r requirements.txt
|
||||
|
||||
COPY app/ ./app/
|
||||
COPY tests/ ./tests/
|
||||
# Without this the container runs pytest with asyncio_mode defaulting to strict,
|
||||
# so unmarked async tests error out even though they pass locally.
|
||||
COPY pytest.ini .
|
||||
|
||||
CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "80", "--reload"]
|
||||
|
||||
@@ -34,11 +34,84 @@ 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
|
||||
#
|
||||
# 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 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).
|
||||
#
|
||||
# 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:
|
||||
#
|
||||
# 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. 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
|
||||
# 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
|
||||
|
||||
# OP25 container
|
||||
op25_api_url: str = "http://localhost:8001"
|
||||
op25_terminal_url: str = "http://localhost:8081"
|
||||
|
||||
@@ -0,0 +1,212 @@
|
||||
"""
|
||||
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; 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 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.
|
||||
|
||||
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.
|
||||
"""
|
||||
from dataclasses import dataclass
|
||||
from typing import Optional, Tuple
|
||||
|
||||
from app.config import settings
|
||||
from app.internal import pcm
|
||||
from app.internal.logger import logger
|
||||
|
||||
# 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
|
||||
|
||||
# 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."""
|
||||
|
||||
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
|
||||
|
||||
|
||||
def _window_bytes() -> int:
|
||||
return max(pcm.FRAME_BYTES, pcm.byte_offset(ANALYSIS_WINDOW_SECONDS))
|
||||
|
||||
|
||||
def first_signal_offset(
|
||||
audio: bytes,
|
||||
threshold_db: float,
|
||||
limit_seconds: float = MAX_SCAN_SECONDS,
|
||||
) -> Optional[int]:
|
||||
"""
|
||||
Byte offset of the first window carrying signal, scanning forward.
|
||||
|
||||
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.
|
||||
"""
|
||||
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 last_signal_offset(
|
||||
audio: bytes,
|
||||
threshold_db: float,
|
||||
limit_seconds: float = MAX_SCAN_SECONDS,
|
||||
) -> Optional[int]:
|
||||
"""
|
||||
Byte offset of the END of the last window carrying signal, scanning back.
|
||||
|
||||
Returns the offset one past the last signal-bearing window, so it can be
|
||||
used directly as a slice bound.
|
||||
"""
|
||||
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 keep_window(
|
||||
first_signal: Optional[int],
|
||||
last_signal: Optional[int],
|
||||
total_bytes: int,
|
||||
guard_bytes: int,
|
||||
) -> Tuple[int, int]:
|
||||
"""
|
||||
Turn detected signal bounds into the byte range to keep.
|
||||
|
||||
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.
|
||||
"""
|
||||
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
|
||||
|
||||
|
||||
def trim_pcm(
|
||||
audio: bytes,
|
||||
threshold_db: Optional[float] = None,
|
||||
guard: Optional[float] = None,
|
||||
) -> Tuple[bytes, TrimResult]:
|
||||
"""
|
||||
Return (kept_audio, result). Never raises and never returns empty audio.
|
||||
|
||||
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
|
||||
|
||||
total = pcm.align(len(audio))
|
||||
duration = pcm.seconds(total)
|
||||
if total <= 0:
|
||||
return audio, TrimResult()
|
||||
|
||||
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"Recording is entirely silence ({duration:.2f}s, threshold {threshold:.1f}dBFS RMS) — "
|
||||
"no speech detected."
|
||||
)
|
||||
return audio, TrimResult(duration_before=duration, duration_after=duration, all_silence=True)
|
||||
|
||||
last = last_signal_offset(audio, threshold)
|
||||
guard_bytes = pcm.byte_offset(margin)
|
||||
keep_start, keep_end = keep_window(first, last, total, guard_bytes)
|
||||
|
||||
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)
|
||||
|
||||
kept = audio[keep_start:keep_end]
|
||||
after = pcm.seconds(len(kept))
|
||||
logger.info(
|
||||
f"Trimmed recording: -{lead:.2f}s lead, -{tail:.2f}s tail "
|
||||
f"({duration:.2f}s -> {after:.2f}s, threshold {threshold:.1f}dBFS RMS)"
|
||||
)
|
||||
return kept, TrimResult(
|
||||
lead=lead,
|
||||
tail=tail,
|
||||
duration_before=duration,
|
||||
duration_after=after,
|
||||
applied=True,
|
||||
)
|
||||
@@ -1,12 +1,42 @@
|
||||
"""
|
||||
Continuous PulseAudio ring buffer + per-call slicing.
|
||||
Continuous PulseAudio capture: a ring buffer for PRE-ROLL, a per-call
|
||||
accumulator for the call itself, and the voice-activity signal that decides
|
||||
where calls begin and end.
|
||||
|
||||
The ring-buffer design is deliberate and load-bearing: a persistent capture
|
||||
process runs for the lifetime of the node and every call is cut out of the
|
||||
buffer after the fact. Spawning FFmpeg per call used to lose the first 1-2 s to
|
||||
process startup, which meant short transmissions produced empty files. Nothing
|
||||
about that changes here — only the INPUT changes, from an HTTP GET on Icecast to
|
||||
a PulseAudio monitor capture.
|
||||
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 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
|
||||
closed by stop_recording(). Call length is therefore bounded by
|
||||
MAX_RECORDING_SECONDS alone — NOT by the ring buffer size. The
|
||||
old design sliced the finished call back out of the ring buffer,
|
||||
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
|
||||
@@ -19,60 +49,236 @@ 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
|
||||
from collections import deque
|
||||
from dataclasses import dataclass, field
|
||||
from datetime import datetime, timezone
|
||||
from pathlib import Path
|
||||
from typing import List, Optional, Tuple
|
||||
|
||||
import httpx
|
||||
from app.config import settings
|
||||
from app.internal import 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.
|
||||
#
|
||||
# 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 when no call is active. 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, so there is no reason to trim it closer. The buffer is what makes
|
||||
# detection latency harmless: however late we notice, we seek back to OP25's
|
||||
# exact timestamp.
|
||||
# Rolling history kept for PRE-ROLL ONLY. Budget for the worst realistic
|
||||
# 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)
|
||||
|
||||
# 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 → 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.
|
||||
#
|
||||
# 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
|
||||
|
||||
# Backoff bounds for restarting a dead capture process.
|
||||
RESTART_BACKOFF_MIN = 1.0
|
||||
RESTART_BACKOFF_MAX = 15.0
|
||||
|
||||
# Substrings looked for in FFmpeg's stderr to classify why capture exited.
|
||||
# "No such process" is what FFmpeg's pulse input prints when the daemon is up
|
||||
# but the named source does not exist — a real PULSE_SOURCE misconfiguration,
|
||||
# not a startup race. This is exactly the failure mode that hid unnoticed
|
||||
# behind a generic "restarting" log in the April outage: silently retrying
|
||||
# forever against a wrong source name looks identical to a normal startup
|
||||
# wait unless it is logged differently.
|
||||
_SOURCE_MISSING_MARKERS = ("no such process", "no such device")
|
||||
# "Connection refused"/"Connection failure" is what the pulse client library
|
||||
# prints when nothing is listening on the socket at all — expected while the
|
||||
# op25 container's daemon is still coming up.
|
||||
_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 # 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
|
||||
# Seconds of requested pre-roll that were not in the buffer at open time.
|
||||
clamped_seconds: float = 0.0
|
||||
# True once the byte ceiling was hit and audio started being dropped.
|
||||
truncated_by_cap: bool = False
|
||||
|
||||
|
||||
@dataclass
|
||||
class Recording:
|
||||
"""
|
||||
A finished recording plus the timing metadata needed to map audio position
|
||||
back to wall clock.
|
||||
|
||||
`started_at`/`ended_at` upstream keep meaning the CALL's bounds. These are
|
||||
the AUDIO's bounds, which differ once silence is trimmed:
|
||||
|
||||
wall_clock_of(audio_offset_t) == audio_start_epoch + t
|
||||
|
||||
Bounds are accurate to ±one capture chunk (~46 ms).
|
||||
"""
|
||||
|
||||
call_id: str
|
||||
path: Optional[Path]
|
||||
audio_start_epoch: float
|
||||
audio_end_epoch: float
|
||||
lead_trimmed: float = 0.0
|
||||
tail_trimmed: float = 0.0
|
||||
clamped_seconds: float = 0.0
|
||||
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 into a ring buffer, sliced per call."""
|
||||
"""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
|
||||
|
||||
@@ -80,10 +286,16 @@ class CallRecorder:
|
||||
self._proc: Optional[asyncio.subprocess.Process] = None
|
||||
self._capturing: bool = False
|
||||
|
||||
# Active recording state
|
||||
self._call_id: Optional[str] = None
|
||||
self._call_start: Optional[float] = None # OP25 grant epoch
|
||||
self._slice_start: Optional[float] = None # _call_start - PRE_ROLL_SECONDS
|
||||
# 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
|
||||
|
||||
# Last few lines of the most recent FFmpeg stderr, used to classify
|
||||
# why a capture process exited (see _classify_capture_exit).
|
||||
self._last_stderr_lines: deque[str] = deque(maxlen=10)
|
||||
|
||||
# ------------------------------------------------------------------
|
||||
# Lifecycle
|
||||
@@ -114,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:
|
||||
@@ -137,7 +347,7 @@ class CallRecorder:
|
||||
continue
|
||||
|
||||
await self._run_capture()
|
||||
logger.warning("PulseAudio capture process exited — restarting.")
|
||||
self._log_capture_exit()
|
||||
except asyncio.CancelledError:
|
||||
await self._terminate_proc()
|
||||
raise
|
||||
@@ -150,7 +360,8 @@ 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,
|
||||
stdout=asyncio.subprocess.PIPE,
|
||||
@@ -161,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
|
||||
@@ -184,12 +401,48 @@ class CallRecorder:
|
||||
line = await proc.stderr.readline()
|
||||
if not line:
|
||||
return
|
||||
logger.warning(f"ffmpeg(pulse): {line.decode(errors='replace').strip()}")
|
||||
text = line.decode(errors="replace").strip()
|
||||
self._last_stderr_lines.append(text)
|
||||
logger.warning(f"ffmpeg(pulse): {text}")
|
||||
except asyncio.CancelledError:
|
||||
return
|
||||
except Exception:
|
||||
return
|
||||
|
||||
def _log_capture_exit(self) -> None:
|
||||
"""
|
||||
Log why the just-finished capture process exited, distinguishing the
|
||||
two failure modes that matter operationally instead of one generic
|
||||
"restarting" line for both:
|
||||
|
||||
- no daemon / connection refused: infrastructure isn't up yet. This
|
||||
is expected during startup/op25 restarts, so it stays at INFO —
|
||||
the retry loop above already handles it.
|
||||
- daemon up but the named source is missing: almost always a real
|
||||
PULSE_SOURCE misconfiguration. This gets a loud, distinct ERROR
|
||||
naming the configured source, because silently retrying forever
|
||||
against a wrong source name is exactly how this hid in the past.
|
||||
"""
|
||||
text = " ".join(self._last_stderr_lines).lower()
|
||||
|
||||
if any(marker in text for marker in _SOURCE_MISSING_MARKERS):
|
||||
logger.error(
|
||||
f"PulseAudio capture exited: source '{settings.pulse_source}' does not exist on the "
|
||||
"daemon (FFmpeg reported 'No such process'). This looks like a real PULSE_SOURCE "
|
||||
"misconfiguration or a missing drb_sink — retrying will not fix it by itself. "
|
||||
"Restarting anyway."
|
||||
)
|
||||
return
|
||||
|
||||
if any(marker in text for marker in _NO_DAEMON_MARKERS):
|
||||
logger.info(
|
||||
"PulseAudio capture exited: daemon not accepting connections — "
|
||||
"infrastructure still coming up, restarting."
|
||||
)
|
||||
return
|
||||
|
||||
logger.warning("PulseAudio capture process exited — restarting.")
|
||||
|
||||
async def _terminate_proc(self) -> None:
|
||||
proc, self._proc = self._proc, None
|
||||
if proc is None or proc.returncode is not None:
|
||||
@@ -212,110 +465,265 @@ 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 and trim stale audio off the front of the buffer."""
|
||||
"""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)
|
||||
|
||||
# While recording, never trim anything the current slice still needs — but
|
||||
# keep a hard ceiling so a recording that somehow never closes can't grow
|
||||
# the buffer without bound.
|
||||
if self._slice_start is not None:
|
||||
keep_from = max(
|
||||
self._slice_start,
|
||||
now - (MAX_RECORDING_SECONDS + RING_BUFFER_SECONDS),
|
||||
)
|
||||
else:
|
||||
# The ring buffer serves pre-roll only, so it is trimmed to a fixed
|
||||
# window unconditionally — an open recording no longer pins it, because
|
||||
# the accumulator owns that audio.
|
||||
keep_from = now - RING_BUFFER_SECONDS
|
||||
|
||||
while self._buffer and self._buffer[0][0] < keep_from:
|
||||
_, old = self._buffer.popleft()
|
||||
self._buffer_bytes -= len(old)
|
||||
|
||||
active = self._active
|
||||
if active is None:
|
||||
return
|
||||
|
||||
if active.total_bytes + len(chunk) > MAX_RECORDING_BYTES:
|
||||
if not active.truncated_by_cap:
|
||||
active.truncated_by_cap = True
|
||||
logger.warning(
|
||||
f"Recording {active.call_id} hit the {MAX_RECORDING_BYTES} byte memory ceiling "
|
||||
f"after {now - active.slice_start:.1f}s — further audio is being dropped."
|
||||
)
|
||||
return
|
||||
|
||||
active.chunks.append((now, chunk))
|
||||
active.total_bytes += len(chunk)
|
||||
|
||||
# ------------------------------------------------------------------
|
||||
# Recording API
|
||||
# ------------------------------------------------------------------
|
||||
|
||||
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._call_id:
|
||||
logger.warning(f"Recording already active ({self._call_id}) — ignoring start for {call_id}.")
|
||||
if self._active is not None:
|
||||
logger.warning(f"Recording already active ({self._active.call_id}) — ignoring start for {call_id}.")
|
||||
return False
|
||||
|
||||
self._call_id = call_id
|
||||
self._call_start = start_epoch if start_epoch else time.time()
|
||||
self._slice_start = self._call_start - PRE_ROLL_SECONDS
|
||||
call_start = start_epoch if start_epoch else time.time()
|
||||
slice_start = call_start - PRE_ROLL_SECONDS
|
||||
|
||||
if not self._capturing:
|
||||
logger.warning(f"Recording {call_id} opened while PulseAudio capture is down — audio may be missing.")
|
||||
|
||||
# Seed the accumulator with the pre-roll already sitting in the ring
|
||||
# buffer. No await between reading the buffer and publishing _active, so
|
||||
# the capture task cannot slip a chunk in between and double-count it.
|
||||
clamped = 0.0
|
||||
oldest = self._buffer[0][0] if self._buffer else None
|
||||
if oldest is not None and self._slice_start < oldest:
|
||||
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.
|
||||
# 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"Pre-roll for call {call_id} predates buffered audio by "
|
||||
f"{oldest - self._slice_start:.2f}s — recording starts at the buffer head."
|
||||
f"BUFFER CLAMP: pre-roll for call {call_id} predates buffered audio by "
|
||||
f"{clamped:.2f}s — recording starts at the buffer head and that audio is lost."
|
||||
)
|
||||
|
||||
logger.info(f"Recording started: {call_id} (slice from {self._slice_start:.3f})")
|
||||
seeded = [(ts, chunk) for ts, chunk in self._buffer if ts >= slice_start]
|
||||
self._active = _ActiveRecording(
|
||||
call_id=call_id,
|
||||
call_start=call_start,
|
||||
slice_start=slice_start,
|
||||
chunks=seeded,
|
||||
total_bytes=sum(len(c) for _, c in seeded),
|
||||
clamped_seconds=clamped,
|
||||
)
|
||||
|
||||
logger.info(f"Recording started: {call_id} (slice from {slice_start:.3f})")
|
||||
return True
|
||||
|
||||
async def stop_recording(self, end_epoch: Optional[float] = None) -> Optional[Path]:
|
||||
"""Close the recording and write the slice. `end_epoch` is host wall clock."""
|
||||
if not self._call_id:
|
||||
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, 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. 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:
|
||||
return None
|
||||
|
||||
call_id = self._call_id
|
||||
call_start = self._call_start
|
||||
slice_start = self._slice_start
|
||||
self._call_id = None
|
||||
self._call_start = None
|
||||
self._slice_start = None
|
||||
call_id = active.call_id
|
||||
slice_start = active.slice_start
|
||||
|
||||
end = end_epoch if end_epoch else time.time()
|
||||
if call_start is not None:
|
||||
end = min(end, call_start + MAX_RECORDING_SECONDS)
|
||||
if slice_start is None:
|
||||
return None
|
||||
end = min(end, active.call_start + MAX_RECORDING_SECONDS)
|
||||
|
||||
chunks: List[bytes] = []
|
||||
for ts, chunk in self._buffer:
|
||||
# The accumulator keeps filling during this wait — that is the point.
|
||||
await self._await_tail(end, call_id)
|
||||
self._active = None
|
||||
|
||||
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."
|
||||
)
|
||||
return None
|
||||
|
||||
if last_ts < end - TAIL_WAIT_POLL_SECONDS:
|
||||
logger.warning(
|
||||
f"BUFFER CLAMP: call {call_id} ends {end - last_ts:.2f}s after the newest captured "
|
||||
"audio — the tail is short. Capture may be stalled or restarting."
|
||||
)
|
||||
|
||||
raw = b"".join(parts)
|
||||
recording = Recording(
|
||||
call_id=call_id,
|
||||
path=None,
|
||||
audio_start_epoch=slice_start,
|
||||
audio_end_epoch=slice_start + pcm.seconds(len(raw)),
|
||||
clamped_seconds=active.clamped_seconds,
|
||||
)
|
||||
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}_{call_id}.mp3"
|
||||
|
||||
output_path.write_bytes(b"".join(chunks))
|
||||
|
||||
size = output_path.stat().st_size
|
||||
if size > 0:
|
||||
logger.info(f"Recording saved: {output_path.name} ({size} bytes, {end - slice_start:.2f}s window)")
|
||||
return output_path
|
||||
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)
|
||||
logger.warning(f"Recording for call {call_id} produced an empty file.")
|
||||
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:
|
||||
"""
|
||||
Block until captured audio reaches `end`, or the bounded timeout expires.
|
||||
|
||||
Returns seconds waited. Logs whenever a wait was actually needed so the
|
||||
real pipeline latency is observable in the field.
|
||||
"""
|
||||
if not self._buffer:
|
||||
return 0.0
|
||||
if self._buffer[-1][0] >= end:
|
||||
return 0.0
|
||||
|
||||
started = time.monotonic()
|
||||
deadline = started + TAIL_WAIT_TIMEOUT_SECONDS
|
||||
while time.monotonic() < deadline:
|
||||
await asyncio.sleep(TAIL_WAIT_POLL_SECONDS)
|
||||
if self._buffer and self._buffer[-1][0] >= end:
|
||||
waited = time.monotonic() - started
|
||||
logger.info(f"Waited {waited:.2f}s for the tail of call {call_id} to reach the buffer.")
|
||||
return waited
|
||||
if not self._capturing:
|
||||
break # capture died mid-wait; nothing more is coming
|
||||
|
||||
waited = time.monotonic() - started
|
||||
newest = self._buffer[-1][0] if self._buffer else end
|
||||
logger.warning(
|
||||
f"Tail wait for call {call_id} gave up after {waited:.2f}s — captured audio is still "
|
||||
f"{max(0.0, end - newest):.2f}s short of the call end. Tail may be clipped."
|
||||
)
|
||||
return waited
|
||||
|
||||
# ------------------------------------------------------------------
|
||||
# Upload (unchanged interface)
|
||||
# ------------------------------------------------------------------
|
||||
@@ -327,6 +735,8 @@ class CallRecorder:
|
||||
talkgroup_id: Optional[int] = None,
|
||||
talkgroup_name: Optional[str] = None,
|
||||
system_id: Optional[str] = None,
|
||||
audio_start_epoch: Optional[float] = None,
|
||||
audio_end_epoch: Optional[float] = None,
|
||||
) -> Optional[str]:
|
||||
if not settings.c2_url:
|
||||
logger.info("No C2_URL configured — skipping upload.")
|
||||
@@ -343,6 +753,13 @@ class CallRecorder:
|
||||
form["talkgroup_name"] = talkgroup_name
|
||||
if system_id:
|
||||
form["system_id"] = system_id
|
||||
# Where this audio really sits on the wall clock once silence is trimmed.
|
||||
# C2 does not declare these Form fields yet, so FastAPI ignores them —
|
||||
# they cost nothing and are here for when playback/correlation want them.
|
||||
if audio_start_epoch is not None:
|
||||
form["audio_start_epoch"] = f"{audio_start_epoch:.3f}"
|
||||
if audio_end_epoch is not None:
|
||||
form["audio_end_epoch"] = f"{audio_end_epoch:.3f}"
|
||||
|
||||
try:
|
||||
async with httpx.AsyncClient(timeout=120) as client:
|
||||
@@ -372,7 +789,7 @@ class CallRecorder:
|
||||
|
||||
@property
|
||||
def is_recording(self) -> bool:
|
||||
return self._call_id is not None
|
||||
return self._active is not None
|
||||
|
||||
@property
|
||||
def is_capturing(self) -> bool:
|
||||
|
||||
@@ -7,4 +7,12 @@ logging.basicConfig(
|
||||
handlers=[logging.StreamHandler(sys.stdout)],
|
||||
)
|
||||
|
||||
# The metadata watcher polls the OP25 terminal twice a second and httpx logs
|
||||
# every one of those requests at INFO ("HTTP Request: POST http://... 200 OK").
|
||||
# That is ~170k lines/day of pure noise which buries real events and makes field
|
||||
# log-reading useless. WARNING keeps genuine transport failures visible.
|
||||
# httpcore is the transport layer underneath httpx and is just as chatty.
|
||||
for _noisy in ("httpx", "httpcore"):
|
||||
logging.getLogger(_noisy).setLevel(logging.WARNING)
|
||||
|
||||
logger = logging.getLogger("drb-edge-node")
|
||||
|
||||
@@ -1,60 +1,163 @@
|
||||
"""
|
||||
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
|
||||
|
||||
# Audio kept after the observed end of the last transmission, so the srcaddr edge
|
||||
# (up to one poll late) never clips the tail.
|
||||
TAIL_PAD_SECONDS = 0.5
|
||||
|
||||
# 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 past a CONSOLE-DERIVED segment boundary, to cover the fact that
|
||||
buffered audio lags control-channel timestamps.
|
||||
|
||||
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:
|
||||
|
||||
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.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.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
|
||||
|
||||
|
||||
def _as_int(value: Any) -> Optional[int]:
|
||||
"""Coerce an OP25 field to a positive int, or None. Rejects 0/""/"None"."""
|
||||
@@ -80,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
|
||||
@@ -90,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
|
||||
@@ -114,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
|
||||
@@ -144,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
|
||||
@@ -152,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
|
||||
@@ -180,11 +627,8 @@ class MetadataWatcher:
|
||||
self._refresh_meta_from_log(entry)
|
||||
return
|
||||
|
||||
# SPLIT: different talkgroup. The new grant's OP25 timestamp is the most
|
||||
# precise end available for the outgoing segment — the new call's audio
|
||||
# starts exactly there, so no tail pad.
|
||||
await self._close_segment(started_at, reason="tgid_change")
|
||||
await self._open_segment(entry, tgid, started_at, now)
|
||||
await self._close_segment(started_at + _tail_pad(), reason="tgid_change")
|
||||
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:
|
||||
@@ -210,32 +654,36 @@ 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 — "
|
||||
f"closing segment for tgid {self._current_tgid} (call_log event likely dropped)."
|
||||
)
|
||||
await self._close_segment(now, reason="tgid_change_unlogged")
|
||||
await self._close_segment(now + _tail_pad(), reason="tgid_change_unlogged")
|
||||
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.
|
||||
end = (self._last_tx_end + TAIL_PAD_SECONDS) if self._last_tx_end is not None else now
|
||||
if self._last_tx_end is not None:
|
||||
measured_idle = now - self._last_tx_end
|
||||
end = self._last_tx_end + _tail_pad()
|
||||
logger.info(
|
||||
f"Idle timeout for tgid {self._current_tgid}: measured control-channel idle "
|
||||
f"{measured_idle:.2f}s (threshold {settings.call_idle_timeout:.2f}s, "
|
||||
f"tail pad {_tail_pad():.2f}s)."
|
||||
)
|
||||
else:
|
||||
end = now
|
||||
logger.info(
|
||||
f"Idle timeout for tgid {self._current_tgid}: no srcaddr end edge observed, "
|
||||
f"idle {now - self._last_activity:.2f}s measured from last activity."
|
||||
)
|
||||
await self._close_segment(min(end, now), reason="idle_timeout")
|
||||
return
|
||||
|
||||
@@ -243,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
|
||||
# ------------------------------------------------------------------
|
||||
@@ -262,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)
|
||||
@@ -303,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,
|
||||
@@ -315,8 +792,25 @@ 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
|
||||
|
||||
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"
|
||||
@@ -333,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)
|
||||
# ------------------------------------------------------------------
|
||||
@@ -357,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()
|
||||
|
||||
@@ -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
|
||||
@@ -5,11 +5,24 @@ The PulseAudio daemon lives in the `op25` container and exposes its native
|
||||
socket on the shared `pulse_socket` docker volume (mounted at /run/pulse in
|
||||
both containers, with PULSE_SERVER=unix:/run/pulse/native).
|
||||
|
||||
`op25-container/docker-entrypoint.sh` waits up to ~10 s for that socket before
|
||||
starting its own app, but the edge-node historically had *no* equivalent wait:
|
||||
FFmpeg would be launched with `-f pulse` before the socket existed, fail
|
||||
instantly, and the audio path would stay dead for the lifetime of the process.
|
||||
This module is the missing wait.
|
||||
`op25-container/docker-entrypoint.sh` waits (bounded) for that daemon to
|
||||
actually answer before starting its own app, and the edge-node needs the same
|
||||
guarantee before launching FFmpeg: FFmpeg with `-f pulse` fails instantly if
|
||||
nothing is listening, and used to stay dead for the lifetime of the process.
|
||||
This module is the wait.
|
||||
|
||||
HISTORY / WHY THIS CHECKS LIVENESS, NOT FILE EXISTENCE: the `pulse_socket`
|
||||
named volume survives container recreation, but the daemon process that
|
||||
created the socket does not. Observed on live hardware: a stale
|
||||
`/run/pulse/native` socket file and `/run/pulse/pid` from a killed daemon
|
||||
were still in the volume after `docker compose up -d --build` recreated the
|
||||
containers. PulseAudio refused to start ("Daemon already running") because of
|
||||
the stale pid file, so nothing was actually listening on the socket — but the
|
||||
socket *file* still existed. An earlier version of this module (and of the
|
||||
op25 entrypoint) only checked `stat.S_ISSOCK` on the path, so it reported
|
||||
"ready" against a dead daemon, FFmpeg launched anyway, and immediately failed
|
||||
with "No such process" in a tight restart loop. Readiness here means "a
|
||||
PulseAudio connection actually succeeds," never "a file exists at this path."
|
||||
|
||||
NOTE on the source name: the op25 entrypoint starts pulseaudio with `-n`, which
|
||||
skips /etc/pulse/system.pa entirely and loads modules from the command line
|
||||
@@ -19,7 +32,8 @@ monitor explicitly via settings.pulse_source (default "drb_sink.monitor").
|
||||
"""
|
||||
import asyncio
|
||||
import os
|
||||
import stat
|
||||
import shutil
|
||||
import subprocess
|
||||
from typing import Optional
|
||||
|
||||
from app.config import settings
|
||||
@@ -28,6 +42,14 @@ from app.internal.logger import logger
|
||||
DEFAULT_SOCKET_PATH = "/run/pulse/native"
|
||||
POLL_INTERVAL = 0.5
|
||||
|
||||
# Bounded timeout for a single `pactl info` liveness probe. Kept short: this
|
||||
# runs synchronously on the calling thread (see is_ready()), and callers of
|
||||
# is_ready() include a sync code path inside the Discord voice bot, so a slow
|
||||
# probe would stall its event loop. wait_until_ready() runs probes off-thread
|
||||
# via asyncio.to_thread and can afford this bound comfortably within its own
|
||||
# much larger PULSE_WAIT_TIMEOUT.
|
||||
PROBE_TIMEOUT_SECONDS = 1.5
|
||||
|
||||
|
||||
def socket_path() -> str:
|
||||
"""Resolve the PulseAudio socket path from PULSE_SERVER (`unix:/path` form)."""
|
||||
@@ -39,38 +61,81 @@ def socket_path() -> str:
|
||||
return DEFAULT_SOCKET_PATH
|
||||
|
||||
|
||||
def is_ready() -> bool:
|
||||
"""True when the PulseAudio native socket exists and really is a socket."""
|
||||
try:
|
||||
return stat.S_ISSOCK(os.stat(socket_path()).st_mode)
|
||||
except OSError:
|
||||
def _probe_env(path: str) -> dict:
|
||||
env = dict(os.environ)
|
||||
env["PULSE_SERVER"] = f"unix:{path}"
|
||||
return env
|
||||
|
||||
|
||||
def _daemon_responds() -> bool:
|
||||
"""
|
||||
True only when a PulseAudio daemon actually answers on the configured
|
||||
socket. Shells out to `pactl info` (from `pulseaudio-utils`, installed
|
||||
alongside `libpulse0` in the edge-node image) rather than re-implementing
|
||||
the native protocol handshake in Python — this container has no other use
|
||||
for talking to PulseAudio directly, so a subprocess call is the smallest
|
||||
correct implementation.
|
||||
|
||||
Deliberately does NOT check `os.path.exists`/`stat.S_ISSOCK` first: a
|
||||
stale socket file from a killed daemon passes that check and always did,
|
||||
which is the exact defect this function replaces.
|
||||
"""
|
||||
path = socket_path()
|
||||
pactl = shutil.which("pactl")
|
||||
if pactl is None:
|
||||
logger.error("pactl not found in PATH — cannot verify PulseAudio liveness.")
|
||||
return False
|
||||
try:
|
||||
result = subprocess.run(
|
||||
[pactl, "info"],
|
||||
env=_probe_env(path),
|
||||
stdout=subprocess.DEVNULL,
|
||||
stderr=subprocess.DEVNULL,
|
||||
timeout=PROBE_TIMEOUT_SECONDS,
|
||||
)
|
||||
return result.returncode == 0
|
||||
except (subprocess.TimeoutExpired, OSError):
|
||||
return False
|
||||
|
||||
|
||||
def is_ready() -> bool:
|
||||
"""
|
||||
True when a PulseAudio daemon is alive and answering right now.
|
||||
|
||||
Synchronous and bounded by PROBE_TIMEOUT_SECONDS — used from a sync call
|
||||
site (discord_radio._play_stream). Prefer `wait_until_ready()` from async
|
||||
code so the probe doesn't block the event loop.
|
||||
"""
|
||||
return _daemon_responds()
|
||||
|
||||
|
||||
async def wait_until_ready(timeout: Optional[float] = None) -> bool:
|
||||
"""
|
||||
Block until the PulseAudio socket appears, or `timeout` seconds elapse.
|
||||
Block until a PulseAudio daemon actually answers, or `timeout` seconds
|
||||
elapse.
|
||||
|
||||
Bounded on purpose — never hang the caller forever. Returns True if the
|
||||
socket is present, False on timeout (caller decides whether to retry).
|
||||
Bounded on purpose — never hang the caller forever. Returns True once a
|
||||
live connection succeeds, False on timeout (caller decides whether to
|
||||
retry). Each probe runs via asyncio.to_thread so the subprocess call never
|
||||
blocks the event loop.
|
||||
"""
|
||||
limit = settings.pulse_wait_timeout if timeout is None else timeout
|
||||
path = socket_path()
|
||||
|
||||
if is_ready():
|
||||
if await asyncio.to_thread(_daemon_responds):
|
||||
return True
|
||||
|
||||
logger.info(f"Waiting up to {limit:.0f}s for PulseAudio socket at {path}…")
|
||||
logger.info(f"Waiting up to {limit:.0f}s for a live PulseAudio daemon at {path}…")
|
||||
waited = 0.0
|
||||
while waited < limit:
|
||||
await asyncio.sleep(POLL_INTERVAL)
|
||||
waited += POLL_INTERVAL
|
||||
if is_ready():
|
||||
logger.info(f"PulseAudio socket ready after {waited:.1f}s.")
|
||||
if await asyncio.to_thread(_daemon_responds):
|
||||
logger.info(f"PulseAudio daemon live after {waited:.1f}s.")
|
||||
return True
|
||||
|
||||
logger.error(
|
||||
f"PulseAudio socket {path} not present after {limit:.0f}s — "
|
||||
"is the op25 container running? Audio capture will retry."
|
||||
f"PulseAudio daemon at {path} not responding after {limit:.0f}s — "
|
||||
"is the op25 container's daemon actually up? Audio capture will retry."
|
||||
)
|
||||
return False
|
||||
|
||||
@@ -1,5 +1,8 @@
|
||||
import asyncio
|
||||
from contextlib import asynccontextmanager
|
||||
from datetime import datetime, timezone
|
||||
from typing import Optional
|
||||
|
||||
from fastapi import FastAPI
|
||||
from app.config import settings
|
||||
from app.models import SystemConfig
|
||||
@@ -20,41 +23,119 @@ from app.routers import api, ui
|
||||
# Event handlers wired up at startup
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def _iso(epoch: Optional[float]) -> Optional[str]:
|
||||
"""Epoch → UTC ISO-8601, matching metadata_watcher's timestamp format."""
|
||||
if epoch is None:
|
||||
return None
|
||||
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()
|
||||
file_path = await call_recorder.stop_recording(end_epoch=data.get("ended_at_epoch"))
|
||||
if file_path:
|
||||
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:
|
||||
# Silence trimming shortens the audio, so the audio's own bounds no
|
||||
# longer equal the call's. `started_at`/`ended_at` keep meaning the CALL
|
||||
# (what OP25 observed on the control channel) — these extra fields carry
|
||||
# the AUDIO's wall-clock bounds so playback, correlation and incident
|
||||
# timelines can still map an audio offset back to real time:
|
||||
# wall_clock_of(audio_offset_t) == audio_start_epoch + t
|
||||
data["audio_start_at"] = _iso(recording.audio_start_epoch)
|
||||
data["audio_end_at"] = _iso(recording.audio_end_epoch)
|
||||
data["audio_start_epoch"] = recording.audio_start_epoch
|
||||
data["audio_end_epoch"] = recording.audio_end_epoch
|
||||
data["audio_lead_trimmed"] = round(recording.lead_trimmed, 3)
|
||||
data["audio_tail_trimmed"] = round(recording.tail_trimmed, 3)
|
||||
if recording.clamped_seconds:
|
||||
data["audio_clamped_seconds"] = round(recording.clamped_seconds, 3)
|
||||
|
||||
if recording is not None and recording.path is not None:
|
||||
node_cfg = load_node_config()
|
||||
audio_url = await call_recorder.upload_recording(
|
||||
file_path,
|
||||
recording.path,
|
||||
data["call_id"],
|
||||
talkgroup_id=data.get("tgid"),
|
||||
talkgroup_name=data.get("tgid_name"),
|
||||
system_id=node_cfg.assigned_system_id,
|
||||
audio_start_epoch=recording.audio_start_epoch,
|
||||
audio_end_epoch=recording.audio_end_epoch,
|
||||
)
|
||||
if audio_url:
|
||||
data["audio_url"] = audio_url
|
||||
else:
|
||||
logger.error(f"Audio upload failed for call {data['call_id']}. Verify C2_URL and Node API Key.")
|
||||
elif recording is not None and recording.all_silence:
|
||||
# Explicit policy: an all-silence recording is not uploaded. It has no
|
||||
# transcript value and silence is what makes Whisper invent text.
|
||||
data["audio_skipped"] = "all_silence"
|
||||
logger.warning(f"Call {data['call_id']} was pure silence — no upload. Investigate the audio path.")
|
||||
else:
|
||||
logger.warning(
|
||||
f"No recording file generated for call {data['call_id']} "
|
||||
"— 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")
|
||||
|
||||
@@ -191,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
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -0,0 +1,218 @@
|
||||
"""
|
||||
Unit tests for silence trimming, now a byte-offset slice of raw PCM.
|
||||
|
||||
`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,
|
||||
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 speech(seconds: float) -> bytes:
|
||||
count = int(pcm.SAMPLE_RATE * seconds)
|
||||
return array("h", [SPEECH_LEVEL, -SPEECH_LEVEL] * (count // 2)).tobytes()
|
||||
|
||||
|
||||
def silence(seconds: float, level: int = FLOOR_LEVEL) -> bytes:
|
||||
count = int(pcm.SAMPLE_RATE * seconds)
|
||||
return array("h", [level, -level] * (count // 2)).tobytes()
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# keep_window — the pure decision
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
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_guard_margin_never_runs_past_the_buffer_bounds():
|
||||
total = pcm.byte_offset(4.0)
|
||||
start, end = keep_window(
|
||||
first_signal=pcm.byte_offset(0.10),
|
||||
last_signal=pcm.byte_offset(3.95),
|
||||
total_bytes=total,
|
||||
guard_bytes=pcm.byte_offset(1.0),
|
||||
)
|
||||
assert (start, end) == (0, total)
|
||||
|
||||
|
||||
def test_keep_window_offsets_are_sample_aligned():
|
||||
start, end = keep_window(3, 9, 21, 1)
|
||||
assert start % pcm.FRAME_BYTES == 0
|
||||
assert end % pcm.FRAME_BYTES == 0
|
||||
|
||||
|
||||
def test_no_signal_found_keeps_everything():
|
||||
total = pcm.byte_offset(6.0)
|
||||
assert keep_window(None, None, total, pcm.byte_offset(GUARD)) == (0, total)
|
||||
|
||||
|
||||
def test_an_inverted_window_degrades_to_keeping_everything():
|
||||
"""Never return an empty slice, whatever the inputs say."""
|
||||
total = pcm.byte_offset(4.0)
|
||||
assert keep_window(pcm.byte_offset(3.0), pcm.byte_offset(0.5), total, 0) == (0, total)
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Scanning
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def test_first_and_last_signal_are_found_in_a_realistic_recording():
|
||||
audio = silence(1.85) + speech(2.35) + silence(0.34)
|
||||
threshold = -40.0
|
||||
|
||||
first = first_signal_offset(audio, threshold)
|
||||
last = last_signal_offset(audio, threshold)
|
||||
|
||||
assert pcm.seconds(first) == pytest.approx(1.85, abs=audio_trim.ANALYSIS_WINDOW_SECONDS)
|
||||
assert pcm.seconds(last) == pytest.approx(4.20, abs=audio_trim.ANALYSIS_WINDOW_SECONDS)
|
||||
|
||||
|
||||
def test_internal_pauses_are_not_treated_as_the_tail():
|
||||
"""Trimming the middle out of a conversation would be unrecoverable."""
|
||||
audio = silence(1.9) + speech(3.1) + silence(2.5) + speech(4.5)
|
||||
last = last_signal_offset(audio, -40.0)
|
||||
assert pcm.seconds(last) == pytest.approx(12.0, abs=audio_trim.ANALYSIS_WINDOW_SECONDS)
|
||||
|
||||
|
||||
def test_all_silence_returns_no_signal_offset():
|
||||
assert first_signal_offset(silence(4.0), -40.0) is None
|
||||
assert last_signal_offset(silence(4.0), -40.0) is None
|
||||
|
||||
|
||||
def test_the_scan_is_bounded_so_a_long_buffer_cannot_stall_the_upload():
|
||||
"""The per-sample loop is the only unbounded cost; it must have a ceiling."""
|
||||
audio = silence(2.0)
|
||||
assert first_signal_offset(audio, -40.0, limit_seconds=0.5) is None
|
||||
assert first_signal_offset(speech(0.1) + silence(1.9), -40.0, limit_seconds=0.5) == 0
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# trim_pcm — end to end over synthesised audio
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def test_leading_and_trailing_silence_are_trimmed_to_the_guard_margin():
|
||||
audio = silence(1.85) + speech(2.35) + silence(0.34)
|
||||
kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||
|
||||
assert result.applied and not result.all_silence
|
||||
assert result.lead == pytest.approx(1.85 - GUARD, abs=0.05)
|
||||
assert result.tail == pytest.approx(0.34 - GUARD, abs=0.05)
|
||||
assert pcm.seconds(len(kept)) == pytest.approx(result.duration_after, abs=0.001)
|
||||
assert result.duration_after < result.duration_before
|
||||
|
||||
|
||||
def test_the_guard_margin_never_eats_into_speech():
|
||||
audio = silence(2.0) + speech(1.0) + silence(2.0)
|
||||
kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||
|
||||
# Everything removed from the head must be silence, and the first sample of
|
||||
# real speech must survive.
|
||||
assert result.lead < 2.0
|
||||
assert pcm.seconds(len(kept)) > 1.0
|
||||
|
||||
|
||||
def test_measured_trailing_silence_is_reported_for_field_tuning():
|
||||
"""
|
||||
The recorder deliberately over-captures the tail (it closes only after the
|
||||
silence timeout has actually elapsed in the audio), so `tail` is how the
|
||||
real silence run reaches the logs.
|
||||
"""
|
||||
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_an_all_silence_buffer_is_reported_not_truncated_to_nothing():
|
||||
audio = silence(4.0)
|
||||
kept, result = trim_pcm(audio, threshold_db=-40.0, guard=GUARD)
|
||||
|
||||
assert result.all_silence
|
||||
assert not result.applied
|
||||
assert kept == audio, "an all-silence recording must not become zero-length"
|
||||
|
||||
|
||||
def test_digital_silence_at_the_measured_field_floor_is_detected():
|
||||
"""
|
||||
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_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 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():
|
||||
assert TrimResult(lead=1.9, tail=0.35).trimmed_seconds == pytest.approx(2.25)
|
||||
@@ -1,41 +1,93 @@
|
||||
"""
|
||||
Unit tests for the CallRecorder ring buffer and per-call slicing.
|
||||
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: the buffer is filled directly with timestamped
|
||||
chunks, which is exactly what _ingest() produces at runtime.
|
||||
No FFmpeg and no PulseAudio: chunks are pushed through _ingest() with a patched
|
||||
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
|
||||
|
||||
import pytest
|
||||
|
||||
from app.config import settings
|
||||
from app.internal import call_recorder as recorder_mod
|
||||
from app.internal import pcm
|
||||
from app.internal.call_recorder import (
|
||||
CallRecorder,
|
||||
MAX_RECORDING_BYTES,
|
||||
MAX_RECORDING_SECONDS,
|
||||
PRE_ROLL_SECONDS,
|
||||
RING_BUFFER_SECONDS,
|
||||
)
|
||||
|
||||
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):
|
||||
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
|
||||
r._capturing = True
|
||||
return r
|
||||
|
||||
|
||||
def fill(recorder, start: float, end: float, marker: bytes = b"A"):
|
||||
"""Append one chunk every CHUNK_INTERVAL seconds over [start, end)."""
|
||||
def ingest(recorder, start: float, end: float, chunk: bytes = VOICE) -> None:
|
||||
"""Feed one chunk every CHUNK_INTERVAL seconds over [start, end)."""
|
||||
stamps: List[float] = []
|
||||
ts = start
|
||||
index = 0
|
||||
while ts < end:
|
||||
recorder._buffer.append((ts, marker + str(index).encode() + b";"))
|
||||
index += 1
|
||||
stamps.append(ts)
|
||||
ts = round(ts + CHUNK_INTERVAL, 6)
|
||||
if not stamps:
|
||||
return
|
||||
with patch("app.internal.call_recorder.time.time", side_effect=stamps):
|
||||
for _ in stamps:
|
||||
recorder._ingest(chunk)
|
||||
|
||||
|
||||
def duration_of(path) -> float:
|
||||
return pcm.seconds(len(path.read_bytes()))
|
||||
|
||||
|
||||
def timestamps(recorder):
|
||||
@@ -43,29 +95,141 @@ def timestamps(recorder):
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Ring buffer trimming
|
||||
# Ring buffer trimming (pre-roll duty only)
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def test_idle_buffer_keeps_only_the_rolling_window(recorder):
|
||||
with patch("app.internal.call_recorder.time.time", return_value=T0):
|
||||
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_buffer_is_not_trimmed_below_the_active_slice(recorder):
|
||||
fill(recorder, T0, T0 + 5.0)
|
||||
async def test_ring_buffer_is_trimmed_even_while_recording(recorder):
|
||||
"""
|
||||
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.
|
||||
"""
|
||||
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)
|
||||
|
||||
# Ingest far past the normal rolling window; the slice start must survive.
|
||||
with patch("app.internal.call_recorder.time.time", return_value=T0 + RING_BUFFER_SECONDS + 10):
|
||||
recorder._ingest(b"z")
|
||||
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)
|
||||
|
||||
assert min(timestamps(recorder)) <= (T0 + 1.0) - PRE_ROLL_SECONDS + CHUNK_INTERVAL
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Call length must not be bounded by the ring buffer
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_call_longer_than_the_ring_buffer_is_captured_whole(recorder):
|
||||
call_length = RING_BUFFER_SECONDS * 2 + 5 # 65s against a 30s ring buffer
|
||||
grant = T0 + 1.0
|
||||
end = grant + call_length
|
||||
|
||||
ingest(recorder, T0, grant)
|
||||
await recorder.start_recording("call-long", start_epoch=grant)
|
||||
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
|
||||
|
||||
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
|
||||
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)
|
||||
|
||||
# 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",
|
||||
side_effect=lambda: T0 + next(ticks) * 0.1):
|
||||
for _ in range(needed):
|
||||
recorder._ingest(big)
|
||||
|
||||
assert recorder._active is not None
|
||||
assert recorder._active.total_bytes <= MAX_RECORDING_BYTES
|
||||
assert recorder._active.truncated_by_cap
|
||||
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
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
@@ -73,80 +237,262 @@ async def test_buffer_is_not_trimmed_below_the_active_slice(recorder):
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
@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._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)
|
||||
|
||||
path = await recorder.stop_recording(end_epoch=grant_time + 2.0)
|
||||
assert path is not None and path.exists()
|
||||
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()
|
||||
|
||||
# Reconstruct which chunks landed in the file.
|
||||
kept = path.read_bytes().decode().strip(";").split(";")
|
||||
first_index = int(kept[0][1:])
|
||||
first_ts = T0 + first_index * 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.
|
||||
path = await recorder.stop_recording(end_epoch=T0 + 3.05)
|
||||
kept = path.read_bytes().decode().strip(";").split(";")
|
||||
last_ts = T0 + int(kept[-1][1:]) * CHUNK_INTERVAL
|
||||
rec = await recorder.stop_recording(end_epoch=T0 + 3.05)
|
||||
|
||||
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_pre_roll_earlier_than_buffer_start_is_clamped(recorder, caplog):
|
||||
"""A grant older than anything buffered must still produce a file."""
|
||||
fill(recorder, T0 + 5.0, T0 + 10.0) # buffer only covers T0+5 onwards
|
||||
async def test_max_recording_seconds_caps_the_slice(recorder):
|
||||
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)
|
||||
|
||||
rec = await recorder.stop_recording(end_epoch=T0 + MAX_RECORDING_SECONDS + 50)
|
||||
|
||||
assert duration_of(rec.path) <= MAX_RECORDING_SECONDS + PRE_ROLL_SECONDS + CHUNK_INTERVAL
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# 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):
|
||||
"""
|
||||
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.
|
||||
"""
|
||||
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(block(SPEECH_LEVEL))
|
||||
|
||||
task = asyncio.create_task(late_tail())
|
||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||
rec = await recorder.stop_recording(end_epoch=T0 + 4.5)
|
||||
await task
|
||||
|
||||
assert rec is not None and rec.path is not None
|
||||
# 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"
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_tail_wait_is_bounded_and_warns_when_audio_never_arrives(recorder, caplog, monkeypatch):
|
||||
monkeypatch.setattr(recorder_mod, "TAIL_WAIT_TIMEOUT_SECONDS", 0.2)
|
||||
ingest(recorder, T0, T0 + 4.0)
|
||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||
|
||||
started = time.monotonic()
|
||||
with caplog.at_level("WARNING", logger="drb-edge-node"):
|
||||
rec = await recorder.stop_recording(end_epoch=T0 + 10.0)
|
||||
elapsed = time.monotonic() - started
|
||||
|
||||
assert elapsed < 2.0, "the wait must be bounded, never open-ended"
|
||||
assert rec is not None and rec.path is not None, "a short tail still beats no recording"
|
||||
messages = [r.message for r in caplog.records]
|
||||
assert any("Tail wait" in m and "gave up" in m for m in messages)
|
||||
assert any("BUFFER CLAMP" in m for m in messages), "silent truncation must be loud"
|
||||
|
||||
|
||||
@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)
|
||||
|
||||
started = time.monotonic()
|
||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||
await recorder.stop_recording(end_epoch=T0 + 3.0)
|
||||
assert (time.monotonic() - started) < 0.1
|
||||
assert not any("Waited" in r.message for r in caplog.records)
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Clamping must be loud
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_pre_roll_earlier_than_buffer_start_is_clamped_and_warned(recorder, caplog):
|
||||
"""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"):
|
||||
await recorder.start_recording("call-1", start_epoch=T0) # 5 s before the head
|
||||
path = await recorder.stop_recording(end_epoch=T0 + 8.0)
|
||||
rec = await recorder.stop_recording(end_epoch=T0 + 8.0)
|
||||
|
||||
assert path is not None and path.stat().st_size > 0
|
||||
kept = path.read_bytes().decode().strip(";").split(";")
|
||||
assert kept[0] == "A0", "slice should begin at the buffer head, not fail"
|
||||
assert rec is not None and rec.path is not None and rec.path.stat().st_size > 0
|
||||
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._slice_start == pytest.approx(now - PRE_ROLL_SECONDS, abs=1.0)
|
||||
assert recorder._active.slice_start == pytest.approx(now - PRE_ROLL_SECONDS, abs=1.0)
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Encode — exactly once, at save time
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_audio_is_encoded_exactly_once_per_call(recorder, encodes, monkeypatch):
|
||||
"""
|
||||
The old pipeline captured MP3 and then re-encoded it to trim, so every
|
||||
upload was double-encoded. Capture is PCM now and MP3 happens once, after
|
||||
trimming, at save time.
|
||||
"""
|
||||
monkeypatch.setattr(settings, "trim_silence", True)
|
||||
ingest(recorder, T0, T0 + 1.0, chunk=QUIET)
|
||||
ingest(recorder, T0 + 1.0, T0 + 3.0, chunk=VOICE)
|
||||
ingest(recorder, T0 + 3.0, T0 + 6.0, chunk=QUIET)
|
||||
|
||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||
rec = await recorder.stop_recording(end_epoch=T0 + 6.0)
|
||||
|
||||
assert rec is not None and rec.path is not None
|
||||
assert len(encodes) == 1, "exactly one encode per recording"
|
||||
encoded_audio, encoded_path = encodes[0]
|
||||
assert encoded_path == rec.path
|
||||
# What was encoded is the TRIMMED audio, not the raw slice.
|
||||
assert pcm.seconds(len(encoded_audio)) < 5.0
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_max_recording_seconds_caps_the_slice(recorder):
|
||||
fill(recorder, T0, T0 + MAX_RECORDING_SECONDS + 60, marker=b"A")
|
||||
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)
|
||||
|
||||
path = await recorder.stop_recording(end_epoch=T0 + MAX_RECORDING_SECONDS + 50)
|
||||
kept = path.read_bytes().decode().strip(";").split(";")
|
||||
last_ts = T0 + int(kept[-1][1:]) * CHUNK_INTERVAL
|
||||
assert await recorder.stop_recording(end_epoch=T0 + 3.0) is None
|
||||
assert list(recorder._recordings_dir.glob("*.mp3")) == []
|
||||
|
||||
assert last_ts <= T0 + 1.0 + MAX_RECORDING_SECONDS + CHUNK_INTERVAL
|
||||
|
||||
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, 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
|
||||
async def test_trimming_is_off_when_the_setting_is_off(recorder, monkeypatch):
|
||||
monkeypatch.setattr(settings, "trim_silence", False)
|
||||
called = False
|
||||
|
||||
def _never(*args, **kwargs):
|
||||
nonlocal called
|
||||
called = True
|
||||
return b"", None
|
||||
|
||||
monkeypatch.setattr(recorder_mod.audio_trim, "trim_pcm", _never)
|
||||
rec = await _recorded(recorder)
|
||||
assert rec is not None and not called
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_trim_shifts_the_audio_bounds_but_not_the_call_bounds(recorder, monkeypatch):
|
||||
"""
|
||||
Trimming changes audio duration, so the AUDIO's wall-clock bounds move.
|
||||
The call's own started_at/ended_at (owned by metadata_watcher) must not be
|
||||
redefined — the recorder only reports where the audio now sits.
|
||||
"""
|
||||
monkeypatch.setattr(settings, "trim_silence", True)
|
||||
|
||||
rec = await _recorded(recorder, lead_silence=1.0, voice=2.0, tail_silence=1.5)
|
||||
|
||||
assert rec is not None and rec.path is not None
|
||||
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, encodes):
|
||||
monkeypatch.setattr(settings, "trim_silence", True)
|
||||
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 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 encodes == [], "and must not be encoded either"
|
||||
assert any("no speech" in r.message for r in caplog.records)
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
@@ -155,7 +501,7 @@ async def test_max_recording_seconds_caps_the_slice(recorder):
|
||||
|
||||
@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
|
||||
@@ -167,13 +513,28 @@ 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):
|
||||
"""
|
||||
A tgid change closes one recording and opens the next at the same instant —
|
||||
the second must still find its pre-roll in the buffer.
|
||||
"""
|
||||
fill(recorder, T0, T0 + 10.0)
|
||||
ingest(recorder, T0, T0 + 10.0)
|
||||
split = T0 + 5.0
|
||||
|
||||
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||
@@ -182,22 +543,92 @@ async def test_split_then_immediate_restart_keeps_both_slices(recorder):
|
||||
await recorder.start_recording("call-2", start_epoch=split)
|
||||
second = await recorder.stop_recording(end_epoch=T0 + 8.0)
|
||||
|
||||
assert first is not None and first.stat().st_size > 0
|
||||
assert second is not None and second.stat().st_size > 0
|
||||
assert first != second
|
||||
assert first is not None and first.path.stat().st_size > 0
|
||||
assert second is not None and second.path.stat().st_size > 0
|
||||
assert first.path != second.path
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# 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_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
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Capture-exit classification — the two failure modes must be told apart
|
||||
# instead of both logging the same generic "restarting" line. This is what
|
||||
# let a wrong PULSE_SOURCE hide behind normal-looking startup retries before.
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def _log_levels(caplog, logger_name="drb-edge-node"):
|
||||
return [r.levelname for r in caplog.records if r.name == logger_name]
|
||||
|
||||
|
||||
def test_capture_exit_logs_error_when_source_missing(recorder, caplog):
|
||||
"""FFmpeg's pulse input prints 'No such process' when the daemon is up
|
||||
but the configured source name does not exist — a real misconfiguration,
|
||||
not a startup race, so this must stand out as an error naming the source."""
|
||||
recorder._last_stderr_lines.append(
|
||||
"[pulse @ 0x...] pa_stream_connect_record failed: No such process"
|
||||
)
|
||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||
recorder._log_capture_exit()
|
||||
|
||||
assert "ERROR" in _log_levels(caplog)
|
||||
error_messages = [r.message for r in caplog.records if r.levelname == "ERROR"]
|
||||
assert any(settings.pulse_source in m for m in error_messages)
|
||||
|
||||
|
||||
def test_capture_exit_logs_info_when_no_daemon(recorder, caplog):
|
||||
"""Connection refused means nothing is listening yet — expected during
|
||||
startup, so it must NOT be logged at the same severity as a real
|
||||
misconfiguration."""
|
||||
recorder._last_stderr_lines.append(
|
||||
"[pulse @ 0x...] pa_context_connect() failed: Connection refused"
|
||||
)
|
||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||
recorder._log_capture_exit()
|
||||
|
||||
levels = _log_levels(caplog)
|
||||
assert "ERROR" not in levels
|
||||
assert "INFO" in levels
|
||||
|
||||
|
||||
def test_capture_exit_falls_back_to_generic_warning(recorder, caplog):
|
||||
"""An FFmpeg failure that matches neither known marker keeps the original
|
||||
generic behavior rather than guessing."""
|
||||
recorder._last_stderr_lines.append("[pulse @ 0x...] some other unexpected failure")
|
||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||
recorder._log_capture_exit()
|
||||
|
||||
assert _log_levels(caplog) == ["WARNING"]
|
||||
|
||||
|
||||
def test_capture_exit_with_no_stderr_captured_is_generic_warning(recorder, caplog):
|
||||
"""No stderr at all (e.g. FFmpeg killed before printing anything) must not
|
||||
crash the classifier and must fall back to the generic message."""
|
||||
assert list(recorder._last_stderr_lines) == []
|
||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||
recorder._log_capture_exit()
|
||||
|
||||
assert _log_levels(caplog) == ["WARNING"]
|
||||
|
||||
@@ -1,17 +1,31 @@
|
||||
"""
|
||||
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,
|
||||
TAIL_PAD_SECONDS,
|
||||
OP25_OFFLINE_GRACE,
|
||||
)
|
||||
from app.internal.op25_client import TerminalUpdate, parse_terminal_messages
|
||||
@@ -38,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()
|
||||
@@ -45,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 {
|
||||
@@ -196,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
|
||||
@@ -229,10 +301,101 @@ async def test_srcaddr_edge_then_idle_timeout_ends_call(watcher, clock):
|
||||
assert payload["end_reason"] == "idle_timeout"
|
||||
# The audio ends at the last transmission plus a short pad, NOT at "now" —
|
||||
# otherwise every recording carries call_idle_timeout seconds of silence.
|
||||
assert payload["ended_at_epoch"] == pytest.approx(edge_time + TAIL_PAD_SECONDS)
|
||||
assert payload["ended_at_epoch"] == pytest.approx(edge_time + settings.call_tail_pad_seconds)
|
||||
assert payload["tgid"] == 1234
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_tail_pad_is_configurable_and_defaults_to_three_seconds(watcher, clock, monkeypatch):
|
||||
"""
|
||||
Field measurement showed the grant->speech offset runs ~0.84-1.62s, so a
|
||||
1.0s pad let short calls' windows close before voice audio even started
|
||||
(clipping mid-word). The default moved to 3.0 — and it has to be a
|
||||
setting, not a magic number, so it can be tuned per node without a code
|
||||
change (and so tests can prove it isn't hardcoded anywhere downstream).
|
||||
"""
|
||||
assert settings.call_tail_pad_seconds == 3.0
|
||||
|
||||
monkeypatch.setattr(settings, "call_tail_pad_seconds", 5.0)
|
||||
|
||||
await tick(watcher, update(
|
||||
call_log=[grant(1234, clock.now)],
|
||||
channels=[channel(tgid=1234, srcaddr=555)],
|
||||
))
|
||||
clock.advance(0.5)
|
||||
edge_time = clock.now
|
||||
await tick(watcher, update(channels=[channel(tgid=1234, srcaddr=0, hold_tgid=1234)]))
|
||||
|
||||
# Advance well past both the idle timeout AND the monkeypatched 5.0s pad so
|
||||
# the "now" cap in _handle_channels never masks the pad value under test.
|
||||
clock.advance(settings.call_idle_timeout + 6.0)
|
||||
await tick(watcher, update(channels=[channel()]))
|
||||
|
||||
payload = watcher.on_call_end.call_args[0][0]
|
||||
assert payload["ended_at_epoch"] == pytest.approx(edge_time + 5.0)
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_short_call_window_now_covers_delayed_voice_arrival(watcher, clock):
|
||||
"""
|
||||
Regression test for the truncation bug: a ~0.97s control-channel call
|
||||
(grant to srcaddr-drop) previously closed its window at
|
||||
last_tx_end + 1.0s pad, i.e. ~1.97s after the grant — but field
|
||||
measurement shows voice audio doesn't start until ~1.5s after the grant
|
||||
(0.84-1.62s measured), so the old window left as little as ~0.4s of
|
||||
captured speech and clipped it mid-word.
|
||||
|
||||
With the 3.0s default pad, the same short call's window must extend well
|
||||
past the ~1.5s point where voice actually starts.
|
||||
"""
|
||||
call_start = clock.now
|
||||
await tick(watcher, update(
|
||||
call_log=[grant(1234, call_start)],
|
||||
channels=[channel(tgid=1234, srcaddr=555)],
|
||||
))
|
||||
|
||||
# The control-channel call itself is short — under 1 second.
|
||||
clock.advance(0.97)
|
||||
edge_time = clock.now
|
||||
await tick(watcher, update(channels=[channel(tgid=1234, srcaddr=0, hold_tgid=1234)]))
|
||||
|
||||
clock.advance(settings.call_idle_timeout + 0.5)
|
||||
await tick(watcher, update(channels=[channel()]))
|
||||
|
||||
payload = watcher.on_call_end.call_args[0][0]
|
||||
assert payload["end_reason"] == "idle_timeout"
|
||||
|
||||
voice_arrival = call_start + 1.5 # measured grant->speech offset, typical case
|
||||
assert payload["ended_at_epoch"] == pytest.approx(edge_time + settings.call_tail_pad_seconds)
|
||||
assert payload["ended_at_epoch"] > voice_arrival, (
|
||||
"recording window must extend past the point voice audio actually arrives, "
|
||||
"not just past the control-channel call_log timestamps"
|
||||
)
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_idle_close_logs_the_measured_control_channel_idle(watcher, clock, caplog):
|
||||
"""
|
||||
The correct idle timeout can only be tuned from the CONTROL-CHANNEL idle, not
|
||||
from silence measured in the audio (which also contains the ~1.9s P25
|
||||
grant→speech delay). So the real measured value has to reach the log.
|
||||
"""
|
||||
await tick(watcher, update(
|
||||
call_log=[grant(1234, clock.now)],
|
||||
channels=[channel(tgid=1234, srcaddr=555)],
|
||||
))
|
||||
clock.advance(0.5)
|
||||
await tick(watcher, update(channels=[channel(tgid=1234, srcaddr=0, hold_tgid=1234)]))
|
||||
|
||||
with caplog.at_level("INFO", logger="drb-edge-node"):
|
||||
clock.advance(settings.call_idle_timeout + 0.25)
|
||||
await tick(watcher, update(channels=[channel()]))
|
||||
|
||||
idle_lines = [r.message for r in caplog.records if "measured control-channel idle" in r.message]
|
||||
assert idle_lines, "idle-timeout closes must log the measured idle for later tuning"
|
||||
assert "3.25s" in idle_lines[0]
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_ongoing_transmission_never_times_out(watcher, clock):
|
||||
await tick(watcher, update(
|
||||
@@ -362,9 +525,11 @@ async def test_different_tgid_grant_splits_recording(watcher, clock):
|
||||
assert ended["call_id"] == first_id
|
||||
assert ended["tgid"] == 1111
|
||||
assert ended["end_reason"] == "tgid_change"
|
||||
# The outgoing segment ends exactly where the new one begins — no tail pad,
|
||||
# or it would swallow the first moments of the new talkgroup.
|
||||
assert ended["ended_at_epoch"] == split_time
|
||||
# The outgoing segment is padded PAST where the new one begins. The buffered
|
||||
# audio lags control-channel timestamps by ~1.5s, so ending exactly at the
|
||||
# split cut the outgoing call's last words. The overlap is correct — the
|
||||
# audio stream really does hold one call's tail then the next call's start.
|
||||
assert ended["ended_at_epoch"] == split_time + settings.call_tail_pad_seconds
|
||||
assert watcher.on_call_start.call_args[0][0]["started_at_epoch"] == split_time
|
||||
|
||||
|
||||
@@ -392,7 +557,8 @@ async def test_multiple_call_log_entries_in_one_poll(watcher, clock):
|
||||
assert ended["tgid"] == 1111
|
||||
assert ended["transmissions"] == 2
|
||||
assert ended["started_at_epoch"] == t0
|
||||
assert ended["ended_at_epoch"] == t0 + 0.9
|
||||
# Split close is padded past the new grant — see the tgid_change test above.
|
||||
assert ended["ended_at_epoch"] == t0 + 0.9 + settings.call_tail_pad_seconds
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
@@ -485,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)
|
||||
|
||||
@@ -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)
|
||||
@@ -0,0 +1,141 @@
|
||||
"""
|
||||
Unit tests for PulseAudio readiness helpers (app.internal.pulse).
|
||||
|
||||
The whole point of this module is that readiness means "a PulseAudio
|
||||
connection actually succeeds," never "a socket file exists at this path" —
|
||||
that was the exact bug reproduced on live hardware: a killed daemon left its
|
||||
pid file and native socket behind in the shared `pulse_socket` volume, the
|
||||
old file-existence check reported "ready", and FFmpeg launched against a
|
||||
dead daemon.
|
||||
|
||||
No real PulseAudio daemon or `pactl` binary is required for these tests:
|
||||
`_daemon_responds` (the one function that actually shells out) is monkeypatched
|
||||
everywhere except the dedicated subprocess-layer tests, which fake out
|
||||
`shutil.which`/`subprocess.run` directly so the "stale file, dead daemon" case
|
||||
is proven at the layer that matters.
|
||||
"""
|
||||
import subprocess
|
||||
from unittest.mock import Mock
|
||||
|
||||
import pytest
|
||||
|
||||
from app.internal import pulse
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# socket_path()
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def test_socket_path_defaults_when_pulse_server_unset(monkeypatch):
|
||||
monkeypatch.delenv("PULSE_SERVER", raising=False)
|
||||
assert pulse.socket_path() == pulse.DEFAULT_SOCKET_PATH
|
||||
|
||||
|
||||
def test_socket_path_parses_unix_prefixed_pulse_server(monkeypatch):
|
||||
monkeypatch.setenv("PULSE_SERVER", "unix:/tmp/somewhere/native")
|
||||
assert pulse.socket_path() == "/tmp/somewhere/native"
|
||||
|
||||
|
||||
def test_socket_path_falls_back_on_malformed_pulse_server(monkeypatch):
|
||||
monkeypatch.setenv("PULSE_SERVER", "not-a-unix-uri")
|
||||
assert pulse.socket_path() == pulse.DEFAULT_SOCKET_PATH
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# is_ready() / wait_until_ready() against a monkeypatched probe
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def test_is_ready_true_when_daemon_responds(monkeypatch):
|
||||
monkeypatch.setattr(pulse, "_daemon_responds", lambda: True)
|
||||
assert pulse.is_ready() is True
|
||||
|
||||
|
||||
def test_is_ready_false_when_daemon_does_not_respond(monkeypatch):
|
||||
monkeypatch.setattr(pulse, "_daemon_responds", lambda: False)
|
||||
assert pulse.is_ready() is False
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_wait_until_ready_short_circuits_when_already_live(monkeypatch):
|
||||
calls = Mock(return_value=True)
|
||||
monkeypatch.setattr(pulse, "_daemon_responds", calls)
|
||||
assert await pulse.wait_until_ready(timeout=5) is True
|
||||
assert calls.call_count == 1
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_wait_until_ready_polls_until_daemon_comes_up(monkeypatch):
|
||||
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
||||
responses = iter([False, False, True])
|
||||
monkeypatch.setattr(pulse, "_daemon_responds", lambda: next(responses))
|
||||
assert await pulse.wait_until_ready(timeout=5) is True
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_wait_until_ready_times_out_when_daemon_never_responds(monkeypatch):
|
||||
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
||||
monkeypatch.setattr(pulse, "_daemon_responds", lambda: False)
|
||||
assert await pulse.wait_until_ready(timeout=0.05) is False
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_wait_until_ready_uses_settings_default_when_timeout_omitted(monkeypatch):
|
||||
monkeypatch.setattr(pulse.settings, "pulse_wait_timeout", 0.05)
|
||||
monkeypatch.setattr(pulse, "POLL_INTERVAL", 0.01)
|
||||
monkeypatch.setattr(pulse, "_daemon_responds", lambda: False)
|
||||
assert await pulse.wait_until_ready() is False
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# _daemon_responds() at the subprocess layer — proves a stale FILE is not
|
||||
# enough, which is the actual regression this module fixes.
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
def test_daemon_responds_false_when_pactl_missing(monkeypatch):
|
||||
monkeypatch.setattr(pulse.shutil, "which", lambda name: None)
|
||||
assert pulse._daemon_responds() is False
|
||||
|
||||
|
||||
def test_daemon_responds_false_on_probe_timeout(monkeypatch, tmp_path):
|
||||
monkeypatch.setattr(pulse.shutil, "which", lambda name: "/usr/bin/pactl")
|
||||
|
||||
def fake_run(*args, **kwargs):
|
||||
raise subprocess.TimeoutExpired(cmd="pactl", timeout=pulse.PROBE_TIMEOUT_SECONDS)
|
||||
|
||||
monkeypatch.setattr(pulse.subprocess, "run", fake_run)
|
||||
assert pulse._daemon_responds() is False
|
||||
|
||||
|
||||
def test_daemon_responds_false_when_stale_socket_file_exists_but_daemon_dead(monkeypatch, tmp_path):
|
||||
"""
|
||||
The regression, reproduced at the layer that matters: a plain FILE sits
|
||||
at the socket path (exactly what a killed daemon leaves behind), but
|
||||
`pactl info` against it fails (nonzero exit — connection refused). This
|
||||
must NOT be treated as ready.
|
||||
"""
|
||||
stale_socket = tmp_path / "native"
|
||||
stale_socket.write_bytes(b"") # a stale file, not a live socket
|
||||
monkeypatch.setenv("PULSE_SERVER", f"unix:{stale_socket}")
|
||||
|
||||
monkeypatch.setattr(pulse.shutil, "which", lambda name: "/usr/bin/pactl")
|
||||
monkeypatch.setattr(
|
||||
pulse.subprocess, "run",
|
||||
lambda *a, **k: subprocess.CompletedProcess(args=a, returncode=1),
|
||||
)
|
||||
|
||||
assert stale_socket.exists() # sanity: the old file-existence check would pass
|
||||
assert pulse._daemon_responds() is False
|
||||
|
||||
|
||||
def test_daemon_responds_true_when_pactl_succeeds(monkeypatch, tmp_path):
|
||||
live_socket = tmp_path / "native"
|
||||
live_socket.write_bytes(b"")
|
||||
monkeypatch.setenv("PULSE_SERVER", f"unix:{live_socket}")
|
||||
|
||||
monkeypatch.setattr(pulse.shutil, "which", lambda name: "/usr/bin/pactl")
|
||||
monkeypatch.setattr(
|
||||
pulse.subprocess, "run",
|
||||
lambda *a, **k: subprocess.CompletedProcess(args=a, returncode=0),
|
||||
)
|
||||
|
||||
assert pulse._daemon_responds() is True
|
||||
@@ -1,29 +1,62 @@
|
||||
#!/bin/bash
|
||||
|
||||
PULSE_SOCKET=/run/pulse/native
|
||||
PULSE_PIDFILE=/run/pulse/pid
|
||||
|
||||
mkdir -p /run/pulse
|
||||
chmod 777 /run/pulse
|
||||
|
||||
# Returns 0 (true) only when a PulseAudio daemon actually answers on
|
||||
# $PULSE_SOCKET. A socket/pid FILE existing proves nothing by itself — that
|
||||
# is exactly the bug this script works around (see stale-state check below).
|
||||
pulse_daemon_alive() {
|
||||
PULSE_SERVER="unix:${PULSE_SOCKET}" timeout 2 pactl info >/dev/null 2>&1
|
||||
}
|
||||
|
||||
# --- Clear stale PulseAudio state left behind by a killed daemon ---
|
||||
# The `pulse_socket` named volume survives container recreation, but the
|
||||
# PulseAudio process that owned it does not. If the previous container was
|
||||
# recreated (not gracefully stopped), its pid file and native socket are
|
||||
# still sitting in the volume; pulseaudio's pid.c sees the pid file and
|
||||
# refuses to start ("Daemon already running") even though nothing is
|
||||
# listening. Only remove these when nothing actually answers on the socket —
|
||||
# never delete a socket a live daemon is using.
|
||||
if [ -S "$PULSE_SOCKET" ] || [ -f "$PULSE_PIDFILE" ]; then
|
||||
if pulse_daemon_alive; then
|
||||
echo "PulseAudio daemon already alive and responding at ${PULSE_SOCKET} — leaving state as-is."
|
||||
else
|
||||
echo "STALE STATE: found ${PULSE_PIDFILE} / ${PULSE_SOCKET} from a previous container, but no daemon answers — clearing before start."
|
||||
rm -f "$PULSE_SOCKET" "$PULSE_PIDFILE"
|
||||
fi
|
||||
fi
|
||||
|
||||
# --- Start PulseAudio Daemon ---
|
||||
# -n: skip default config (load modules inline — avoids system.pa parsing issues)
|
||||
# --system: run as system-wide daemon
|
||||
# --log-target=stderr: makes errors visible in Docker logs
|
||||
# &: background so this script continues; output still captured by Docker
|
||||
echo "Starting PulseAudio daemon..."
|
||||
mkdir -p /run/pulse
|
||||
chmod 777 /run/pulse
|
||||
pulseaudio --exit-idle-time=-1 -n --system \
|
||||
--load="module-native-protocol-unix socket=/run/pulse/native auth-anonymous=1" \
|
||||
--load="module-native-protocol-unix socket=${PULSE_SOCKET} auth-anonymous=1" \
|
||||
--load="module-null-sink sink_name=drb_sink sink_properties=device.description=DRB-Sink" \
|
||||
--log-target=stderr &
|
||||
|
||||
# Wait for the socket to actually exist before continuing
|
||||
echo "Waiting for PulseAudio socket..."
|
||||
# Wait for the daemon to actually answer — NOT just for the socket file to
|
||||
# exist. A stale socket file from a killed daemon exists but nothing is
|
||||
# listening on it; a file-existence check reports "ready" against a dead
|
||||
# daemon, which is exactly how this class of bug slipped through before.
|
||||
echo "Waiting for PulseAudio to become live..."
|
||||
PULSE_LIVE=0
|
||||
for i in $(seq 1 20); do
|
||||
if [ -S /run/pulse/native ]; then
|
||||
echo "PulseAudio socket ready."
|
||||
if pulse_daemon_alive; then
|
||||
echo "PulseAudio daemon is live (pactl info succeeded)."
|
||||
PULSE_LIVE=1
|
||||
break
|
||||
fi
|
||||
sleep 0.5
|
||||
done
|
||||
if [ ! -S /run/pulse/native ]; then
|
||||
echo "WARNING: PulseAudio socket not found after 10s — edge-node audio will fail."
|
||||
if [ "$PULSE_LIVE" -ne 1 ]; then
|
||||
echo "WARNING: PulseAudio daemon not responding after 10s — edge-node audio will fail until it recovers."
|
||||
fi
|
||||
ls -la /run/pulse/
|
||||
|
||||
|
||||
Reference in New Issue
Block a user