Compare commits
9 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| d6dfe5a293 | |||
| 085fcdf1a1 | |||
| f1de157d69 | |||
| ceb2836371 | |||
| 7c4a3f2f20 | |||
| b0a8ed2a5a | |||
| efdbe7d803 | |||
| 9addce7716 | |||
| cc9af6ff26 |
@@ -16,12 +16,66 @@ C2_URL=http://localhost:8888
|
|||||||
# API key is provisioned automatically via MQTT after admin approves the node
|
# API key is provisioned automatically via MQTT after admin approves the node
|
||||||
|
|
||||||
# Icecast (local container — usually no need to change)
|
# Icecast (local container — usually no need to change)
|
||||||
|
# Live listening only. Call recording and Discord voice use PulseAudio instead.
|
||||||
ICECAST_SOURCE_PASSWORD=hackme
|
ICECAST_SOURCE_PASSWORD=hackme
|
||||||
ICECAST_ADMIN_PASSWORD=admin
|
ICECAST_ADMIN_PASSWORD=admin
|
||||||
ICECAST_HOST=localhost
|
ICECAST_HOST=localhost
|
||||||
ICECAST_PORT=8000
|
ICECAST_PORT=8000
|
||||||
ICECAST_MOUNT=/radio
|
ICECAST_MOUNT=/radio
|
||||||
|
|
||||||
|
# PulseAudio capture (usually no need to change)
|
||||||
|
# Monitor of the drb_sink null sink that Liquidsoap writes into.
|
||||||
|
PULSE_SOURCE=drb_sink.monitor
|
||||||
|
# Seconds to wait for the shared PulseAudio socket before giving up and retrying.
|
||||||
|
PULSE_WAIT_TIMEOUT=30
|
||||||
|
|
||||||
|
# --- 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 container (usually no need to change)
|
||||||
OP25_API_URL=http://localhost:8001
|
OP25_API_URL=http://localhost:8001
|
||||||
OP25_TERMINAL_URL=http://localhost:8081
|
OP25_TERMINAL_URL=http://localhost:8081
|
||||||
|
|||||||
@@ -8,9 +8,9 @@ setup:
|
|||||||
test:
|
test:
|
||||||
docker compose run --no-deps --rm edge-node pytest -v
|
docker compose run --no-deps --rm edge-node pytest -v
|
||||||
|
|
||||||
# Build all images locally and start.
|
# Build all images locally and start (dev mode with local code mounted).
|
||||||
up:
|
up:
|
||||||
docker compose up -d
|
docker compose up -d --build
|
||||||
|
|
||||||
# Pull pre-built images from the registry and start (no local build).
|
# Pull pre-built images from the registry and start (no local build).
|
||||||
# Requires IMAGE_REGISTRY, DOCKER_ORG, DOCKER_REPO set in .env.
|
# Requires IMAGE_REGISTRY, DOCKER_ORG, DOCKER_REPO set in .env.
|
||||||
@@ -21,6 +21,12 @@ up-prebuilt:
|
|||||||
pull:
|
pull:
|
||||||
docker compose pull
|
docker compose pull
|
||||||
|
|
||||||
|
# Helper to pull the latest git commits and rebuild/restart the dev stack.
|
||||||
|
update-git:
|
||||||
|
git pull
|
||||||
|
docker compose build
|
||||||
|
docker compose up -d
|
||||||
|
|
||||||
down:
|
down:
|
||||||
docker compose down
|
docker compose down
|
||||||
|
|
||||||
|
|||||||
@@ -5,6 +5,7 @@ RUN apt-get update && apt-get install -y \
|
|||||||
libopus0 \
|
libopus0 \
|
||||||
libopus-dev \
|
libopus-dev \
|
||||||
libpulse0 \
|
libpulse0 \
|
||||||
|
pulseaudio-utils \
|
||||||
&& rm -rf /var/lib/apt/lists/*
|
&& rm -rf /var/lib/apt/lists/*
|
||||||
|
|
||||||
WORKDIR /app
|
WORKDIR /app
|
||||||
@@ -14,5 +15,8 @@ RUN pip install uv && uv pip install --system --no-cache-dir -r requirements.txt
|
|||||||
|
|
||||||
COPY app/ ./app/
|
COPY app/ ./app/
|
||||||
COPY tests/ ./tests/
|
COPY tests/ ./tests/
|
||||||
|
# Without this the container runs pytest with asyncio_mode defaulting to strict,
|
||||||
|
# so unmarked async tests error out even though they pass locally.
|
||||||
|
COPY pytest.ini .
|
||||||
|
|
||||||
CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "80", "--reload"]
|
CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "80", "--reload"]
|
||||||
|
|||||||
@@ -18,12 +18,100 @@ class Settings(BaseSettings):
|
|||||||
# C2 server (audio upload destination); None disables upload
|
# C2 server (audio upload destination); None disables upload
|
||||||
c2_url: Optional[str] = None
|
c2_url: Optional[str] = None
|
||||||
|
|
||||||
# Local Icecast
|
# Local Icecast — live listening only (frontend / mobile).
|
||||||
|
# NOT used for call recording or Discord voice: it lags 1s and drifts to 100s+.
|
||||||
icecast_host: str = "localhost"
|
icecast_host: str = "localhost"
|
||||||
icecast_port: int = 8000
|
icecast_port: int = 8000
|
||||||
icecast_mount: str = "/radio"
|
icecast_mount: str = "/radio"
|
||||||
icecast_source_password: str = "hackme"
|
icecast_source_password: str = "hackme"
|
||||||
|
|
||||||
|
# PulseAudio — the low-latency path used for call recording and Discord voice.
|
||||||
|
# Liquidsoap (op25 container) writes into the `drb_sink` null sink; we capture
|
||||||
|
# its monitor. Addressed explicitly rather than via "default" because the op25
|
||||||
|
# entrypoint starts pulseaudio with -n and never applies system.pa's
|
||||||
|
# `set-default-source` line.
|
||||||
|
pulse_source: str = "drb_sink.monitor"
|
||||||
|
# Bounded wait for the shared PulseAudio socket before launching FFmpeg.
|
||||||
|
pulse_wait_timeout: float = 30.0
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# 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 container
|
||||||
op25_api_url: str = "http://localhost:8001"
|
op25_api_url: str = "http://localhost:8001"
|
||||||
op25_terminal_url: str = "http://localhost:8081"
|
op25_terminal_url: str = "http://localhost:8081"
|
||||||
@@ -32,6 +120,9 @@ class Settings(BaseSettings):
|
|||||||
config_path: str = "/configs"
|
config_path: str = "/configs"
|
||||||
recordings_path: str = "/recordings"
|
recordings_path: str = "/recordings"
|
||||||
|
|
||||||
|
# Offline call buffer — how many call_end events to keep while disconnected
|
||||||
|
offline_call_buffer_size: int = 35
|
||||||
|
|
||||||
class Config:
|
class Config:
|
||||||
env_file = ".env"
|
env_file = ".env"
|
||||||
|
|
||||||
|
|||||||
@@ -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,55 +1,312 @@
|
|||||||
|
"""
|
||||||
|
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.
|
||||||
|
|
||||||
|
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
|
||||||
|
stack for frontend/mobile live listening; it is not an accuracy path.
|
||||||
|
|
||||||
|
CLOCK DOMAIN: chunks are stamped with time.time(), the host wall clock. OP25's
|
||||||
|
call_log timestamps are time.time() from inside the op25 container. All client
|
||||||
|
containers run network_mode: host and share the host kernel clock, so the two are
|
||||||
|
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 asyncio
|
||||||
import time
|
import time
|
||||||
from collections import deque
|
from collections import deque
|
||||||
|
from dataclasses import dataclass, field
|
||||||
from datetime import datetime, timezone
|
from datetime import datetime, timezone
|
||||||
from pathlib import Path
|
from pathlib import Path
|
||||||
from typing import Optional
|
from typing import List, Optional, Tuple
|
||||||
|
|
||||||
import httpx
|
import httpx
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
from app.internal import credentials
|
from app.internal import audio_trim, credentials, pcm, pulse
|
||||||
from app.internal.logger import logger
|
from app.internal.logger import logger
|
||||||
|
|
||||||
MAX_RECORDING_SECONDS = 600 # safety cap; drop call if it runs this long
|
# Safety cap on a single recording; mirrors MAX_SEGMENT_SECONDS in metadata_watcher.
|
||||||
PRE_BUFFER_SECONDS = 1.0 # seconds of audio to include before call_start
|
MAX_RECORDING_SECONDS = 600
|
||||||
RING_BUFFER_SECONDS = 60 # how much history to keep when no call is active
|
|
||||||
READ_CHUNK_BYTES = 4096 # bytes per httpx read
|
# 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 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
|
||||||
|
|
||||||
|
# ~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 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 = 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:
|
class CallRecorder:
|
||||||
"""
|
"""Continuous PulseAudio capture: ring buffer for pre-roll, accumulator per call."""
|
||||||
Maintains a persistent HTTP connection to the Icecast stream and buffers
|
|
||||||
the raw MP3 bytes in a ring buffer. When a call starts we note the
|
|
||||||
monotonic clock; when it ends we slice the buffer and write the file.
|
|
||||||
|
|
||||||
This approach eliminates per-call FFmpeg startup latency, which was
|
|
||||||
causing empty recordings for calls shorter than ~1–2 s.
|
|
||||||
"""
|
|
||||||
|
|
||||||
def __init__(self):
|
def __init__(self):
|
||||||
self._recordings_dir = Path(settings.recordings_path)
|
self._recordings_dir = Path(settings.recordings_path)
|
||||||
|
|
||||||
# Ring buffer: deque of (monotonic_time, bytes_chunk)
|
# Ring buffer: deque of (wall_clock_epoch_at_arrival, pcm_bytes).
|
||||||
self._buffer: deque[tuple[float, bytes]] = deque()
|
# Pre-roll only — see the module docstring.
|
||||||
|
self._buffer: deque[Tuple[float, bytes]] = deque()
|
||||||
self._buffer_bytes: int = 0
|
self._buffer_bytes: int = 0
|
||||||
|
|
||||||
self._stream_task: Optional[asyncio.Task] = None
|
self._stream_task: Optional[asyncio.Task] = None
|
||||||
|
self._proc: Optional[asyncio.subprocess.Process] = None
|
||||||
|
self._capturing: bool = False
|
||||||
|
|
||||||
# Active call state
|
# Voice activity, tracked continuously — not only while recording.
|
||||||
self._call_id: Optional[str] = None
|
self._last_voice_epoch: Optional[float] = None
|
||||||
self._call_start_mono: 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
|
# Lifecycle
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
async def start(self) -> None:
|
async def start(self) -> None:
|
||||||
"""Start the persistent stream buffer. Call once from app lifespan."""
|
"""Start the persistent capture. Call once from app lifespan."""
|
||||||
self._stream_task = asyncio.create_task(self._stream_loop())
|
self._stream_task = asyncio.create_task(self._capture_loop())
|
||||||
logger.info("Stream ring-buffer started.")
|
logger.info("PulseAudio ring-buffer starting.")
|
||||||
|
|
||||||
async def stop(self) -> None:
|
async def stop(self) -> None:
|
||||||
"""Cancel the stream reader."""
|
|
||||||
if self._stream_task:
|
if self._stream_task:
|
||||||
self._stream_task.cancel()
|
self._stream_task.cancel()
|
||||||
try:
|
try:
|
||||||
@@ -57,111 +314,415 @@ class CallRecorder:
|
|||||||
except asyncio.CancelledError:
|
except asyncio.CancelledError:
|
||||||
pass
|
pass
|
||||||
self._stream_task = None
|
self._stream_task = None
|
||||||
|
await self._terminate_proc()
|
||||||
|
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
# Stream reader
|
# Capture
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
async def _stream_loop(self) -> None:
|
def _ffmpeg_command(self) -> List[str]:
|
||||||
stream_url = (
|
return [
|
||||||
f"http://{settings.icecast_host}:{settings.icecast_port}"
|
"ffmpeg",
|
||||||
f"{settings.icecast_mount}"
|
"-hide_banner", "-nostdin", "-nostats",
|
||||||
)
|
"-loglevel", "warning",
|
||||||
timeout = httpx.Timeout(connect=10.0, read=None, write=10.0, pool=10.0)
|
"-f", "pulse", "-i", settings.pulse_source,
|
||||||
|
"-ac", str(pcm.CHANNELS),
|
||||||
|
"-ar", MP3_SAMPLE_RATE,
|
||||||
|
# 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:
|
||||||
|
backoff = RESTART_BACKOFF_MIN
|
||||||
while True:
|
while True:
|
||||||
try:
|
try:
|
||||||
async with httpx.AsyncClient(timeout=timeout) as client:
|
# The original bug this path was abandoned for: FFmpeg was launched
|
||||||
async with client.stream("GET", stream_url) as response:
|
# with -f pulse before the shared socket existed, failed instantly,
|
||||||
response.raise_for_status()
|
# and never recovered. Wait for it, bounded, every time.
|
||||||
logger.info(f"Stream buffer connected to {stream_url}")
|
if not await pulse.wait_until_ready():
|
||||||
async for chunk in response.aiter_bytes(READ_CHUNK_BYTES):
|
await asyncio.sleep(backoff)
|
||||||
self._ingest(chunk)
|
backoff = min(backoff * 2, RESTART_BACKOFF_MAX)
|
||||||
|
continue
|
||||||
|
|
||||||
|
await self._run_capture()
|
||||||
|
self._log_capture_exit()
|
||||||
except asyncio.CancelledError:
|
except asyncio.CancelledError:
|
||||||
|
await self._terminate_proc()
|
||||||
raise
|
raise
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
logger.warning(f"Stream buffer disconnected ({e}) — retrying in 3 s")
|
logger.warning(f"PulseAudio capture error ({e}) — restarting.")
|
||||||
await asyncio.sleep(3)
|
|
||||||
|
self._capturing = False
|
||||||
|
await asyncio.sleep(backoff)
|
||||||
|
backoff = min(backoff * 2, RESTART_BACKOFF_MAX)
|
||||||
|
|
||||||
|
async def _run_capture(self) -> None:
|
||||||
|
cmd = self._ffmpeg_command()
|
||||||
|
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,
|
||||||
|
stderr=asyncio.subprocess.PIPE,
|
||||||
|
)
|
||||||
|
self._proc = proc
|
||||||
|
stderr_task = asyncio.create_task(self._drain_stderr(proc))
|
||||||
|
try:
|
||||||
|
assert proc.stdout is not None
|
||||||
|
while True:
|
||||||
|
# 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
|
||||||
|
logger.info("PulseAudio capture is producing audio.")
|
||||||
|
self._ingest(chunk)
|
||||||
|
finally:
|
||||||
|
self._capturing = False
|
||||||
|
# _drain_stderr swallows its own CancelledError, so it finishes cleanly
|
||||||
|
# and never needs awaiting here.
|
||||||
|
stderr_task.cancel()
|
||||||
|
await self._terminate_proc()
|
||||||
|
|
||||||
|
async def _drain_stderr(self, proc: asyncio.subprocess.Process) -> None:
|
||||||
|
"""Surface FFmpeg's diagnostics instead of letting the pipe fill and block."""
|
||||||
|
if proc.stderr is None:
|
||||||
|
return
|
||||||
|
try:
|
||||||
|
while True:
|
||||||
|
line = await proc.stderr.readline()
|
||||||
|
if not line:
|
||||||
|
return
|
||||||
|
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:
|
||||||
|
return
|
||||||
|
try:
|
||||||
|
# Synchronous, so the signal lands even if we are being cancelled and
|
||||||
|
# the reap below never gets to run.
|
||||||
|
proc.terminate()
|
||||||
|
except Exception:
|
||||||
|
return
|
||||||
|
try:
|
||||||
|
await asyncio.wait_for(proc.wait(), timeout=5)
|
||||||
|
except asyncio.TimeoutError:
|
||||||
|
try:
|
||||||
|
proc.kill()
|
||||||
|
except Exception:
|
||||||
|
pass
|
||||||
|
except asyncio.CancelledError:
|
||||||
|
raise
|
||||||
|
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:
|
def _ingest(self, chunk: bytes) -> None:
|
||||||
"""Append a chunk and trim stale data from the front of the buffer."""
|
"""Append a chunk to the ring buffer and, if recording, the accumulator."""
|
||||||
now = time.monotonic()
|
now = time.time()
|
||||||
|
self._note_voice(chunk, now)
|
||||||
|
|
||||||
self._buffer.append((now, chunk))
|
self._buffer.append((now, chunk))
|
||||||
self._buffer_bytes += len(chunk)
|
self._buffer_bytes += len(chunk)
|
||||||
|
|
||||||
# During a call, never trim data newer than (call_start - pre_buffer).
|
# The ring buffer serves pre-roll only, so it is trimmed to a fixed
|
||||||
# Between calls, keep a rolling RING_BUFFER_SECONDS window.
|
# window unconditionally — an open recording no longer pins it, because
|
||||||
if self._call_start_mono is not None:
|
# the accumulator owns that audio.
|
||||||
keep_from = self._call_start_mono - PRE_BUFFER_SECONDS
|
keep_from = now - RING_BUFFER_SECONDS
|
||||||
else:
|
while self._buffer and self._buffer[0][0] < keep_from:
|
||||||
keep_from = now - RING_BUFFER_SECONDS
|
_, old = self._buffer.popleft()
|
||||||
|
|
||||||
while self._buffer:
|
|
||||||
ts, old = self._buffer[0]
|
|
||||||
if ts >= keep_from:
|
|
||||||
break
|
|
||||||
self._buffer.popleft()
|
|
||||||
self._buffer_bytes -= len(old)
|
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)
|
||||||
|
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
# Call recording API (same interface as before)
|
# Recording API
|
||||||
# ------------------------------------------------------------------
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
async def start_recording(self, call_id: str) -> bool:
|
async def start_recording(self, call_id: str, start_epoch: Optional[float] = None) -> bool:
|
||||||
if self._call_id:
|
"""
|
||||||
logger.warning("Recording already active — ignoring start.")
|
Open a recording. `start_epoch` is the detected voice onset (host wall
|
||||||
|
clock, same clock as the chunk stamps); the slice begins
|
||||||
|
PRE_ROLL_SECONDS before it. Omit it only when no onset is available —
|
||||||
|
then we fall back to "now", losing the pre-roll's precision.
|
||||||
|
"""
|
||||||
|
if self._active is not None:
|
||||||
|
logger.warning(f"Recording already active ({self._active.call_id}) — ignoring start for {call_id}.")
|
||||||
return False
|
return False
|
||||||
self._call_id = call_id
|
|
||||||
self._call_start_mono = time.monotonic()
|
call_start = start_epoch if start_epoch else time.time()
|
||||||
logger.info(f"Recording started (ring-buffer): {call_id}")
|
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 slice_start < oldest:
|
||||||
|
# Pre-roll predates the buffer: node just started, capture restarted,
|
||||||
|
# or the onset is far in the past. Clamp and say so LOUDLY — this is
|
||||||
|
# silent audio loss otherwise.
|
||||||
|
clamped = oldest - slice_start
|
||||||
|
logger.warning(
|
||||||
|
f"BUFFER CLAMP: pre-roll for call {call_id} predates buffered audio by "
|
||||||
|
f"{clamped:.2f}s — recording starts at the buffer head and that audio is lost."
|
||||||
|
)
|
||||||
|
|
||||||
|
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
|
return True
|
||||||
|
|
||||||
async def stop_recording(self) -> Optional[Path]:
|
async def discard_recording(self) -> None:
|
||||||
if not self._call_id:
|
"""
|
||||||
|
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
|
return None
|
||||||
|
|
||||||
call_id = self._call_id
|
call_id = active.call_id
|
||||||
call_start = self._call_start_mono
|
slice_start = active.slice_start
|
||||||
self._call_id = None
|
|
||||||
self._call_start_mono = None
|
|
||||||
|
|
||||||
# Slice: everything from (call_start - pre_buffer) to now
|
end = end_epoch if end_epoch else time.time()
|
||||||
cutoff = (call_start - PRE_BUFFER_SECONDS) if call_start else 0.0
|
end = min(end, active.call_start + MAX_RECORDING_SECONDS)
|
||||||
chunks = [chunk for ts, chunk in self._buffer if ts >= cutoff]
|
|
||||||
|
|
||||||
# Safety cap: if the call ran very long, truncate to MAX_RECORDING_SECONDS
|
# The accumulator keeps filling during this wait — that is the point.
|
||||||
if call_start is not None:
|
await self._await_tail(end, call_id)
|
||||||
cap_cutoff = call_start + MAX_RECORDING_SECONDS
|
self._active = None
|
||||||
now = time.monotonic()
|
|
||||||
if now > cap_cutoff:
|
|
||||||
# Approximate: trim chunks that arrived after the cap
|
|
||||||
cap_keep_until = call_start + MAX_RECORDING_SECONDS
|
|
||||||
chunks = [
|
|
||||||
chunk for ts, chunk in self._buffer
|
|
||||||
if cutoff <= ts <= cap_keep_until
|
|
||||||
]
|
|
||||||
|
|
||||||
if not chunks:
|
parts: List[bytes] = []
|
||||||
|
total = 0
|
||||||
|
last_ts = slice_start
|
||||||
|
for ts, chunk in active.chunks:
|
||||||
|
if ts < slice_start:
|
||||||
|
continue
|
||||||
|
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 parts:
|
||||||
logger.warning(
|
logger.warning(
|
||||||
f"No buffered audio for call {call_id} — "
|
f"No buffered audio for call {call_id} "
|
||||||
"stream may not have been connected yet."
|
f"(window {slice_start:.3f}–{end:.3f}) — PulseAudio capture may be down."
|
||||||
)
|
)
|
||||||
return None
|
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)
|
self._recordings_dir.mkdir(parents=True, exist_ok=True)
|
||||||
ts_str = datetime.now(timezone.utc).strftime("%Y%m%d_%H%M%S")
|
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 = self._recordings_dir / f"{ts_str}_{recording.call_id}.mp3"
|
||||||
|
|
||||||
data = b"".join(chunks)
|
if not await encode_mp3(audio, output_path):
|
||||||
output_path.write_bytes(data)
|
output_path.unlink(missing_ok=True)
|
||||||
|
return None
|
||||||
|
|
||||||
size = output_path.stat().st_size
|
size = output_path.stat().st_size if output_path.exists() else 0
|
||||||
if size > 0:
|
if size <= 0:
|
||||||
logger.info(f"Recording saved: {output_path.name} ({size} bytes)")
|
output_path.unlink(missing_ok=True)
|
||||||
return output_path
|
logger.warning(f"Recording for call {recording.call_id} produced an empty file.")
|
||||||
|
return None
|
||||||
|
|
||||||
output_path.unlink(missing_ok=True)
|
recording.path = output_path
|
||||||
logger.warning(f"Recording for call {call_id} produced an empty file.")
|
logger.info(
|
||||||
return None
|
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)
|
# Upload (unchanged interface)
|
||||||
@@ -174,6 +735,8 @@ class CallRecorder:
|
|||||||
talkgroup_id: Optional[int] = None,
|
talkgroup_id: Optional[int] = None,
|
||||||
talkgroup_name: Optional[str] = None,
|
talkgroup_name: Optional[str] = None,
|
||||||
system_id: Optional[str] = None,
|
system_id: Optional[str] = None,
|
||||||
|
audio_start_epoch: Optional[float] = None,
|
||||||
|
audio_end_epoch: Optional[float] = None,
|
||||||
) -> Optional[str]:
|
) -> Optional[str]:
|
||||||
if not settings.c2_url:
|
if not settings.c2_url:
|
||||||
logger.info("No C2_URL configured — skipping upload.")
|
logger.info("No C2_URL configured — skipping upload.")
|
||||||
@@ -190,6 +753,13 @@ class CallRecorder:
|
|||||||
form["talkgroup_name"] = talkgroup_name
|
form["talkgroup_name"] = talkgroup_name
|
||||||
if system_id:
|
if system_id:
|
||||||
form["system_id"] = 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:
|
try:
|
||||||
async with httpx.AsyncClient(timeout=120) as client:
|
async with httpx.AsyncClient(timeout=120) as client:
|
||||||
@@ -213,9 +783,24 @@ class CallRecorder:
|
|||||||
except Exception:
|
except Exception:
|
||||||
pass
|
pass
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# State
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
@property
|
@property
|
||||||
def is_recording(self) -> bool:
|
def is_recording(self) -> bool:
|
||||||
return self._call_id is not None
|
return self._active is not None
|
||||||
|
|
||||||
|
@property
|
||||||
|
def is_capturing(self) -> bool:
|
||||||
|
"""True when FFmpeg is alive and audio is actually arriving."""
|
||||||
|
return self._capturing
|
||||||
|
|
||||||
|
@property
|
||||||
|
def buffered_seconds(self) -> float:
|
||||||
|
if len(self._buffer) < 2:
|
||||||
|
return 0.0
|
||||||
|
return self._buffer[-1][0] - self._buffer[0][0]
|
||||||
|
|
||||||
|
|
||||||
call_recorder = CallRecorder()
|
call_recorder = CallRecorder()
|
||||||
|
|||||||
@@ -2,11 +2,14 @@ import asyncio
|
|||||||
from typing import Optional
|
from typing import Optional
|
||||||
import discord
|
import discord
|
||||||
from discord.ext import commands
|
from discord.ext import commands
|
||||||
|
from app.config import settings
|
||||||
|
from app.internal import pulse
|
||||||
from app.internal.logger import logger
|
from app.internal.logger import logger
|
||||||
|
|
||||||
BOT_READY_TIMEOUT = 15 # seconds to wait for Discord bot to become ready
|
BOT_READY_TIMEOUT = 15 # seconds to wait for Discord bot to become ready
|
||||||
WATCHDOG_INTERVAL = 30 # seconds between voice-connection health checks
|
WATCHDOG_INTERVAL = 30 # seconds between voice-connection health checks
|
||||||
REJOIN_DELAY = 5 # seconds to wait before attempting a rejoin
|
REJOIN_DELAY = 5 # seconds to wait before attempting a rejoin
|
||||||
|
STREAM_RETRY_DELAY = 5 # seconds to back off before re-arming the audio source
|
||||||
|
|
||||||
|
|
||||||
class RadioBot:
|
class RadioBot:
|
||||||
@@ -47,6 +50,10 @@ class RadioBot:
|
|||||||
# Remember where we are so the watchdog can rejoin if we drop
|
# Remember where we are so the watchdog can rejoin if we drop
|
||||||
self._guild_id = guild_id
|
self._guild_id = guild_id
|
||||||
self._channel_id = channel_id
|
self._channel_id = channel_id
|
||||||
|
# Bounded wait for the shared PulseAudio socket. Historically FFmpeg was
|
||||||
|
# launched before the op25 container had created it, failed instantly,
|
||||||
|
# and the bot sat silently connected forever.
|
||||||
|
await pulse.wait_until_ready()
|
||||||
self._play_stream()
|
self._play_stream()
|
||||||
if system_name:
|
if system_name:
|
||||||
await self._bot.change_presence(
|
await self._bot.change_presence(
|
||||||
@@ -108,19 +115,48 @@ class RadioBot:
|
|||||||
self._ready_event = None
|
self._ready_event = None
|
||||||
|
|
||||||
def _play_stream(self):
|
def _play_stream(self):
|
||||||
|
"""
|
||||||
|
Feed Discord voice straight from the PulseAudio monitor.
|
||||||
|
|
||||||
|
Icecast is NOT used here: it lags ~1 s at connect and drifts to 100 s+,
|
||||||
|
which is unusable for live listening. Icecast remains the frontend/mobile
|
||||||
|
listening path only.
|
||||||
|
"""
|
||||||
if not self._voice_client:
|
if not self._voice_client:
|
||||||
return
|
return
|
||||||
from app.config import settings
|
|
||||||
stream_url = f"http://{settings.icecast_host}:{settings.icecast_port}{settings.icecast_mount}"
|
if not pulse.is_ready():
|
||||||
|
logger.error(
|
||||||
|
f"PulseAudio socket {pulse.socket_path()} missing — "
|
||||||
|
f"cannot start Discord audio; retrying in {STREAM_RETRY_DELAY}s."
|
||||||
|
)
|
||||||
|
self._schedule_restart()
|
||||||
|
return
|
||||||
|
|
||||||
|
# before_options land ahead of -i, so this becomes:
|
||||||
|
# ffmpeg -f pulse -i drb_sink.monitor …
|
||||||
source = discord.FFmpegPCMAudio(
|
source = discord.FFmpegPCMAudio(
|
||||||
stream_url,
|
settings.pulse_source,
|
||||||
before_options="-reconnect 1 -reconnect_streamed 1 -reconnect_delay_max 5",
|
before_options="-f pulse",
|
||||||
)
|
)
|
||||||
self._voice_client.play(
|
self._voice_client.play(
|
||||||
discord.PCMVolumeTransformer(source, volume=1.0),
|
discord.PCMVolumeTransformer(source, volume=1.0),
|
||||||
after=self._on_stream_end,
|
after=self._on_stream_end,
|
||||||
)
|
)
|
||||||
|
|
||||||
|
def _schedule_restart(self, delay: float = STREAM_RETRY_DELAY):
|
||||||
|
"""Re-arm the audio source after a delay — safe to call from any thread."""
|
||||||
|
if not self._loop:
|
||||||
|
return
|
||||||
|
|
||||||
|
async def _delayed_restart():
|
||||||
|
await asyncio.sleep(delay)
|
||||||
|
vc = self._voice_client
|
||||||
|
if vc and vc.is_connected() and not vc.is_playing():
|
||||||
|
self._play_stream()
|
||||||
|
|
||||||
|
self._loop.call_soon_threadsafe(lambda: asyncio.ensure_future(_delayed_restart()))
|
||||||
|
|
||||||
def _on_stream_end(self, error):
|
def _on_stream_end(self, error):
|
||||||
if error:
|
if error:
|
||||||
logger.error(f"Stream ended with error: {error}")
|
logger.error(f"Stream ended with error: {error}")
|
||||||
@@ -128,12 +164,9 @@ class RadioBot:
|
|||||||
if not (self._loop and vc and vc.is_connected() and not vc.is_playing()):
|
if not (self._loop and vc and vc.is_connected() and not vc.is_playing()):
|
||||||
return
|
return
|
||||||
if error:
|
if error:
|
||||||
# Back off before retrying — prevents tight loop when PulseAudio is unavailable
|
# Back off before retrying — prevents a tight loop when PulseAudio is
|
||||||
async def _delayed_restart():
|
# unavailable (FFmpeg exits immediately in that case).
|
||||||
await asyncio.sleep(5)
|
self._schedule_restart()
|
||||||
if self._voice_client and self._voice_client.is_connected() and not self._voice_client.is_playing():
|
|
||||||
self._play_stream()
|
|
||||||
self._loop.call_soon_threadsafe(lambda: asyncio.ensure_future(_delayed_restart()))
|
|
||||||
else:
|
else:
|
||||||
self._loop.call_soon_threadsafe(self._play_stream)
|
self._loop.call_soon_threadsafe(self._play_stream)
|
||||||
|
|
||||||
@@ -232,6 +265,9 @@ class RadioBot:
|
|||||||
else:
|
else:
|
||||||
self._voice_client = await vc.connect()
|
self._voice_client = await vc.connect()
|
||||||
self._channel_id = vc.id
|
self._channel_id = vc.id
|
||||||
|
# A fresh connect() has no audio source attached yet.
|
||||||
|
if not self._voice_client.is_playing():
|
||||||
|
self._play_stream()
|
||||||
await message.reply(f"Joined {vc.name}.")
|
await message.reply(f"Joined {vc.name}.")
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
logger.error(f"joinme failed: {e}")
|
logger.error(f"joinme failed: {e}")
|
||||||
|
|||||||
@@ -7,4 +7,12 @@ logging.basicConfig(
|
|||||||
handlers=[logging.StreamHandler(sys.stdout)],
|
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")
|
logger = logging.getLogger("drb-edge-node")
|
||||||
|
|||||||
@@ -1,38 +1,274 @@
|
|||||||
|
"""
|
||||||
|
Call segmentation: AUDIO decides the boundaries, the CONSOLE decides the label.
|
||||||
|
|
||||||
|
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.
|
||||||
|
|
||||||
|
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:
|
||||||
|
|
||||||
|
* 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 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 chunk timestamps are the same clock, with the caveat that they
|
||||||
|
are ARRIVAL times and therefore lag the moment of speech by the pipeline
|
||||||
|
latency. Comparisons between two audio timestamps are exact; comparisons between
|
||||||
|
audio and console timestamps carry that lag, which is what _tail_pad() covers.
|
||||||
|
"""
|
||||||
import asyncio
|
import asyncio
|
||||||
|
import time
|
||||||
import uuid
|
import uuid
|
||||||
|
from collections import deque
|
||||||
|
from dataclasses import dataclass, field
|
||||||
from datetime import datetime, timezone
|
from datetime import datetime, timezone
|
||||||
from typing import Optional, Callable, Awaitable
|
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.op25_client import op25_client
|
||||||
from app.internal.logger import logger
|
from app.internal.logger import logger
|
||||||
|
|
||||||
CallbackFn = Callable[[dict], Awaitable[None]]
|
CallbackFn = Callable[[dict], Awaitable[None]]
|
||||||
|
ActivityFn = Callable[[], AudioActivity]
|
||||||
|
|
||||||
HANG_THRESHOLD = 2 # polls before declaring a call ended (0.5s poll → 1s hang time)
|
# 500 ms. Do NOT lower: audio boundaries come from the recorder's own chunk
|
||||||
POLL_INTERVAL = 0.5 # seconds
|
# 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. Applies in
|
||||||
|
# both modes: without the console there is no attribution, and unattributed
|
||||||
|
# audio is discarded anyway.
|
||||||
|
OP25_OFFLINE_GRACE = 3.0
|
||||||
|
|
||||||
|
# Hard ceiling on a single segment; mirrors MAX_RECORDING_SECONDS in call_recorder
|
||||||
|
# so a talkgroup that never goes quiet cannot produce an unbounded recording. 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"."""
|
||||||
|
if value is None:
|
||||||
|
return None
|
||||||
|
try:
|
||||||
|
number = int(value)
|
||||||
|
except (TypeError, ValueError):
|
||||||
|
return None
|
||||||
|
return number if number > 0 else None
|
||||||
|
|
||||||
|
|
||||||
|
def _as_float(value: Any) -> Optional[float]:
|
||||||
|
try:
|
||||||
|
return float(value)
|
||||||
|
except (TypeError, ValueError):
|
||||||
|
return None
|
||||||
|
|
||||||
|
|
||||||
|
def _iso(epoch: Optional[float]) -> Optional[str]:
|
||||||
|
if epoch is None:
|
||||||
|
return None
|
||||||
|
return datetime.fromtimestamp(epoch, timezone.utc).isoformat()
|
||||||
|
|
||||||
|
|
||||||
|
@dataclass(frozen=True)
|
||||||
|
class ConsoleEvent:
|
||||||
|
"""One thing the OP25 console said, kept so a closing segment can ask about it."""
|
||||||
|
|
||||||
|
epoch: float
|
||||||
|
tgid: int
|
||||||
|
name: str = ""
|
||||||
|
freq: Any = None
|
||||||
|
rid: Optional[int] = None
|
||||||
|
# True for a `call_log` grant, False for an active `channel_update` row.
|
||||||
|
is_grant: bool = False
|
||||||
|
|
||||||
|
|
||||||
|
@dataclass
|
||||||
|
class Attribution:
|
||||||
|
"""Who a stretch of audio belonged to, and how confident we are."""
|
||||||
|
|
||||||
|
tgid: int
|
||||||
|
name: str = ""
|
||||||
|
freq: Any = None
|
||||||
|
rid: Optional[int] = None
|
||||||
|
grants: int = 0
|
||||||
|
# Observations that fall strictly inside the audio window (vs only inside
|
||||||
|
# the tolerance band around it).
|
||||||
|
overlap: int = 0
|
||||||
|
nearby: int = 0
|
||||||
|
competing: List[int] = field(default_factory=list)
|
||||||
|
|
||||||
|
|
||||||
class MetadataWatcher:
|
class MetadataWatcher:
|
||||||
def __init__(self):
|
def __init__(self):
|
||||||
self._running = False
|
self._running = False
|
||||||
|
|
||||||
|
# Open segment state
|
||||||
|
self._active_call_id: Optional[str] = None
|
||||||
self._current_tgid: Optional[int] = None
|
self._current_tgid: Optional[int] = None
|
||||||
self._current_tgid_name: Optional[str] = None
|
self._current_tgid_name: Optional[str] = None
|
||||||
self._hang_counter: int = 0
|
self._current_freq: Any = None
|
||||||
self._active_call_id: Optional[str] = None
|
self._current_srcaddr: Optional[int] = None
|
||||||
self._call_started_at: Optional[datetime] = None
|
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 (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()
|
# Set these before calling start()
|
||||||
self.on_call_start: Optional[CallbackFn] = None
|
self.on_call_start: Optional[CallbackFn] = None
|
||||||
self.on_call_end: Optional[CallbackFn] = None
|
self.on_call_end: Optional[CallbackFn] = None
|
||||||
|
# Supplies the audio-activity snapshot. None (or a snapshot reporting
|
||||||
|
# capturing=False) puts the watcher in console fallback mode.
|
||||||
|
self.audio_activity: Optional[ActivityFn] = None
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# Lifecycle
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
async def start(self):
|
async def start(self):
|
||||||
self._running = True
|
self._running = True
|
||||||
|
self._last_ok_poll = self._clock()
|
||||||
asyncio.create_task(self._poll_loop())
|
asyncio.create_task(self._poll_loop())
|
||||||
logger.info("Metadata watcher started.")
|
logger.info("Metadata watcher started (audio-driven segmentation, console attribution).")
|
||||||
|
|
||||||
async def stop(self):
|
async def stop(self):
|
||||||
self._running = False
|
self._running = False
|
||||||
if self._active_call_id:
|
if self._active_call_id:
|
||||||
await self._end_call()
|
await self._close_segment(self._clock(), reason="shutdown")
|
||||||
|
|
||||||
async def _poll_loop(self):
|
async def _poll_loop(self):
|
||||||
while self._running:
|
while self._running:
|
||||||
@@ -42,79 +278,610 @@ class MetadataWatcher:
|
|||||||
logger.warning(f"Metadata poll error: {e}")
|
logger.warning(f"Metadata poll error: {e}")
|
||||||
await asyncio.sleep(POLL_INTERVAL)
|
await asyncio.sleep(POLL_INTERVAL)
|
||||||
|
|
||||||
async def _tick(self):
|
# ------------------------------------------------------------------
|
||||||
status = await op25_client.get_terminal_status()
|
# One poll
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
if not status:
|
async def _tick(self):
|
||||||
# OP25 not responding — hang-out any active call
|
now = self._clock()
|
||||||
if self._active_call_id:
|
update = await op25_client.poll_terminal()
|
||||||
self._hang_counter += 1
|
|
||||||
if self._hang_counter >= HANG_THRESHOLD:
|
if update is None:
|
||||||
await self._end_call()
|
# OP25 unreachable. Don't kill an open segment on a single blip.
|
||||||
|
if self._active_call_id and (now - self._last_ok_poll) >= OP25_OFFLINE_GRACE:
|
||||||
|
await self._close_segment(now, reason="op25_unreachable")
|
||||||
return
|
return
|
||||||
|
|
||||||
# OP25 terminal returns either a list of channels or a single dict
|
self._last_ok_poll = now
|
||||||
channels = status if isinstance(status, list) else [status]
|
self._record_console(update, now)
|
||||||
active_tgid: Optional[int] = None
|
|
||||||
active_meta: dict = {}
|
|
||||||
|
|
||||||
for ch in channels:
|
activity = self._snapshot()
|
||||||
tgid = ch.get("tgid") or ch.get("tg_id")
|
if activity is None or not activity.capturing:
|
||||||
if tgid and str(tgid) not in ("0", "", "None"):
|
await self._console_tick(update, now)
|
||||||
active_tgid = int(tgid)
|
return
|
||||||
active_meta = ch
|
|
||||||
break
|
|
||||||
|
|
||||||
if active_tgid:
|
await self._audio_tick(update, activity, now)
|
||||||
self._hang_counter = 0
|
|
||||||
if self._current_tgid != active_tgid:
|
|
||||||
# Talkgroup changed — close previous call and open a new one
|
|
||||||
if self._active_call_id:
|
|
||||||
await self._end_call()
|
|
||||||
self._current_tgid = active_tgid
|
|
||||||
await self._start_call(active_tgid, active_meta)
|
|
||||||
else:
|
|
||||||
# No active talkgroup
|
|
||||||
if self._active_call_id:
|
|
||||||
self._hang_counter += 1
|
|
||||||
if self._hang_counter >= HANG_THRESHOLD:
|
|
||||||
await self._end_call()
|
|
||||||
|
|
||||||
async def _start_call(self, tgid: int, meta: dict):
|
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
|
||||||
|
# already attributed to the new segment by the time we scan channels.
|
||||||
|
# Sorted defensively: multi-receiver setups append per receiver.
|
||||||
|
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 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
|
||||||
|
|
||||||
|
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_from_console(entry, tgid, started_at, now)
|
||||||
|
return
|
||||||
|
|
||||||
|
if tgid == self._current_tgid:
|
||||||
|
self._transmissions += 1
|
||||||
|
self._tx_active = True
|
||||||
|
self._last_tx_end = None
|
||||||
|
self._last_activity = now
|
||||||
|
self._refresh_meta_from_log(entry)
|
||||||
|
return
|
||||||
|
|
||||||
|
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:
|
||||||
|
return
|
||||||
|
|
||||||
|
tx_active = False
|
||||||
|
foreign_active_tgid: Optional[int] = None
|
||||||
|
|
||||||
|
for channel in channels:
|
||||||
|
srcaddr = _as_int(channel.get("srcaddr"))
|
||||||
|
chan_tgid = _as_int(channel.get("tgid"))
|
||||||
|
if srcaddr is None:
|
||||||
|
continue
|
||||||
|
if chan_tgid == self._current_tgid:
|
||||||
|
tx_active = True
|
||||||
|
self._current_srcaddr = srcaddr
|
||||||
|
self._refresh_meta_from_channel(channel)
|
||||||
|
elif chan_tgid is not None:
|
||||||
|
foreign_active_tgid = chan_tgid
|
||||||
|
|
||||||
|
if tx_active:
|
||||||
|
self._tx_active = True
|
||||||
|
self._last_tx_end = None
|
||||||
|
self._last_activity = now
|
||||||
|
elif self._tx_active:
|
||||||
|
# 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
|
||||||
|
|
||||||
|
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 + _tail_pad(), reason="tgid_change_unlogged")
|
||||||
|
return
|
||||||
|
|
||||||
|
if (now - self._last_activity) >= settings.call_idle_timeout:
|
||||||
|
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
|
||||||
|
|
||||||
|
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 — 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
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
|
def _refresh_meta_from_log(self, entry: Dict[str, Any]) -> None:
|
||||||
|
if not self._current_tgid_name:
|
||||||
|
self._current_tgid_name = entry.get("tgtag") or ""
|
||||||
|
if entry.get("freq"):
|
||||||
|
self._current_freq = entry.get("freq")
|
||||||
|
rid = _as_int(entry.get("rid"))
|
||||||
|
if rid is not None:
|
||||||
|
self._current_srcaddr = rid
|
||||||
|
|
||||||
|
def _refresh_meta_from_channel(self, channel: Dict[str, Any]) -> None:
|
||||||
|
if not self._current_tgid_name:
|
||||||
|
self._current_tgid_name = channel.get("tag") or ""
|
||||||
|
if not self._current_freq and channel.get("freq"):
|
||||||
|
self._current_freq = channel.get("freq")
|
||||||
|
|
||||||
|
async def _open_segment(
|
||||||
|
self,
|
||||||
|
started_at: float,
|
||||||
|
now: float,
|
||||||
|
tgid: Optional[int],
|
||||||
|
tgid_name: str,
|
||||||
|
freq: Any,
|
||||||
|
srcaddr: Optional[int],
|
||||||
|
audio_driven: bool,
|
||||||
|
transmissions: int = 1,
|
||||||
|
) -> None:
|
||||||
self._active_call_id = str(uuid.uuid4())
|
self._active_call_id = str(uuid.uuid4())
|
||||||
self._call_started_at = datetime.now(timezone.utc)
|
self._current_tgid = tgid
|
||||||
self._current_tgid_name = meta.get("tag") or meta.get("tgid_tag") or ""
|
self._current_tgid_name = tgid_name
|
||||||
|
self._current_freq = freq
|
||||||
|
self._current_srcaddr = srcaddr
|
||||||
|
self._started_at = started_at
|
||||||
|
self._transmissions = max(1, transmissions)
|
||||||
|
self._audio_driven = audio_driven
|
||||||
|
|
||||||
|
# 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 = {
|
payload = {
|
||||||
"call_id": self._active_call_id,
|
"call_id": self._active_call_id,
|
||||||
"tgid": tgid,
|
"tgid": tgid,
|
||||||
"tgid_name": self._current_tgid_name,
|
"tgid_name": tgid_name,
|
||||||
"freq": meta.get("freq"),
|
"freq": freq,
|
||||||
"srcaddr": meta.get("srcaddr"),
|
"srcaddr": srcaddr,
|
||||||
"started_at": self._call_started_at.isoformat(),
|
"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",
|
||||||
}
|
}
|
||||||
logger.info(f"Call start: tgid={tgid} id={self._active_call_id}")
|
source = "audio onset" if audio_driven else "op25 grant"
|
||||||
|
logger.info(
|
||||||
|
f"Call start: tgid={tgid} id={self._active_call_id} "
|
||||||
|
f"({source} t={started_at:.3f}, detected {now - started_at:+.2f}s later)"
|
||||||
|
)
|
||||||
if self.on_call_start:
|
if self.on_call_start:
|
||||||
await self.on_call_start(payload)
|
await self.on_call_start(payload)
|
||||||
|
|
||||||
async def _end_call(self):
|
async def _close_segment(self, end_epoch: float, reason: str) -> None:
|
||||||
if not self._active_call_id:
|
if not self._active_call_id:
|
||||||
return
|
return
|
||||||
|
|
||||||
|
started_at = self._started_at
|
||||||
|
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 = {
|
payload = {
|
||||||
"call_id": self._active_call_id,
|
"call_id": self._active_call_id,
|
||||||
"tgid": self._current_tgid,
|
"tgid": self._current_tgid,
|
||||||
"tgid_name": self._current_tgid_name or "",
|
"tgid_name": self._current_tgid_name or "",
|
||||||
"started_at": self._call_started_at.isoformat() if self._call_started_at else None,
|
"freq": self._current_freq,
|
||||||
"ended_at": datetime.now(timezone.utc).isoformat(),
|
"srcaddr": self._current_srcaddr,
|
||||||
|
"started_at": _iso(started_at),
|
||||||
|
"started_at_epoch": started_at,
|
||||||
|
"ended_at": _iso(end_epoch),
|
||||||
|
"ended_at_epoch": end_epoch,
|
||||||
|
"transmissions": self._transmissions,
|
||||||
|
"end_reason": reason,
|
||||||
|
"attributed": attributed,
|
||||||
|
"driver": "audio" if self._audio_driven else "console",
|
||||||
}
|
}
|
||||||
logger.info(f"Call end: id={self._active_call_id}")
|
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"
|
||||||
|
)
|
||||||
|
|
||||||
|
# Clear state before awaiting so a re-entrant tick can't see a half-closed
|
||||||
|
# segment (and so an immediately-following _open_segment is clean).
|
||||||
self._active_call_id = None
|
self._active_call_id = None
|
||||||
self._current_tgid = None
|
self._current_tgid = None
|
||||||
self._current_tgid_name = None
|
self._current_tgid_name = None
|
||||||
self._hang_counter = 0
|
self._current_freq = None
|
||||||
self._call_started_at = None
|
self._current_srcaddr = None
|
||||||
|
self._started_at = None
|
||||||
|
self._transmissions = 0
|
||||||
|
self._tx_active = False
|
||||||
|
self._last_tx_end = None
|
||||||
|
self._audio_driven = False
|
||||||
|
|
||||||
if self.on_call_end:
|
if self.on_call_end:
|
||||||
await self.on_call_end(payload)
|
await self.on_call_end(payload)
|
||||||
|
|
||||||
|
def _resolve_attribution(self, start: float, end: float) -> None:
|
||||||
|
"""
|
||||||
|
Last chance to label an audio-driven segment, run at close.
|
||||||
|
|
||||||
|
Only ADOPTS a talkgroup when the segment still has none. A tgid we
|
||||||
|
already hold came from a grant or a channel row — the console stating
|
||||||
|
outright who was transmitting — and an inference over a window is not
|
||||||
|
allowed to overrule a direct statement. This matters because the window
|
||||||
|
deliberately extends past the audio (ATTRIBUTION_LOOKAHEAD_SECONDS, and
|
||||||
|
the tail pad on a split), so a neighbouring call's console activity can
|
||||||
|
legitimately fall inside it.
|
||||||
|
|
||||||
|
A disagreement is still worth knowing about, so it is logged: it means
|
||||||
|
two talkgroups' console activity overlaps one recording, i.e. the split
|
||||||
|
logic should have fired and did not.
|
||||||
|
"""
|
||||||
|
found = self._attribute(start, end)
|
||||||
|
if found is None:
|
||||||
|
return
|
||||||
|
|
||||||
|
if self._current_tgid is None:
|
||||||
|
logger.info(
|
||||||
|
f"Attributed {self._active_call_id} at close to tgid {found.tgid} "
|
||||||
|
f"(overlap {found.overlap}, grants {found.grants}, nearby {found.nearby})."
|
||||||
|
)
|
||||||
|
self._current_tgid = found.tgid
|
||||||
|
if found.name:
|
||||||
|
self._current_tgid_name = found.name
|
||||||
|
if found.freq is not None and not self._current_freq:
|
||||||
|
self._current_freq = found.freq
|
||||||
|
if found.rid is not None and self._current_srcaddr is None:
|
||||||
|
self._current_srcaddr = found.rid
|
||||||
|
self._transmissions = max(self._transmissions, found.grants)
|
||||||
|
return
|
||||||
|
|
||||||
|
others = sorted(set(found.competing) | ({found.tgid} if found.tgid != self._current_tgid else set()))
|
||||||
|
others = [tgid for tgid in others if tgid != self._current_tgid]
|
||||||
|
if others:
|
||||||
|
logger.warning(
|
||||||
|
f"Segment {self._active_call_id} (tgid {self._current_tgid}) overlaps console "
|
||||||
|
f"activity for {others} as well — the split logic should have fired and did not. "
|
||||||
|
"Keeping the talkgroup the console stated directly."
|
||||||
|
)
|
||||||
|
if not self._current_tgid_name and found.tgid == self._current_tgid and found.name:
|
||||||
|
self._current_tgid_name = found.name
|
||||||
|
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
# Public state (consumed by routers/api.py, main.py and the dashboards)
|
||||||
|
# ------------------------------------------------------------------
|
||||||
|
|
||||||
@property
|
@property
|
||||||
def active_call_id(self) -> Optional[str]:
|
def active_call_id(self) -> Optional[str]:
|
||||||
return self._active_call_id
|
return self._active_call_id
|
||||||
@@ -131,5 +898,10 @@ class MetadataWatcher:
|
|||||||
def is_active(self) -> bool:
|
def is_active(self) -> bool:
|
||||||
return self._active_call_id is not None
|
return self._active_call_id is not None
|
||||||
|
|
||||||
|
@property
|
||||||
|
def unattributed_segments(self) -> int:
|
||||||
|
"""Orphan-audio segments discarded since start. Surfaced on /api/status."""
|
||||||
|
return self._unattributed_segments
|
||||||
|
|
||||||
|
|
||||||
metadata_watcher = MetadataWatcher()
|
metadata_watcher = MetadataWatcher()
|
||||||
|
|||||||
@@ -1,6 +1,7 @@
|
|||||||
import asyncio
|
import asyncio
|
||||||
import json
|
import json
|
||||||
from datetime import datetime, timezone
|
from datetime import datetime, timezone
|
||||||
|
from collections import deque
|
||||||
from typing import Optional, Callable, Awaitable, Dict, Any
|
from typing import Optional, Callable, Awaitable, Dict, Any
|
||||||
import paho.mqtt.client as mqtt
|
import paho.mqtt.client as mqtt
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
@@ -23,6 +24,8 @@ class MQTTManager:
|
|||||||
self.on_config_push: Optional[ConfigCallback] = None
|
self.on_config_push: Optional[ConfigCallback] = None
|
||||||
self.on_api_key: Optional[ApiKeyCallback] = None
|
self.on_api_key: Optional[ApiKeyCallback] = None
|
||||||
|
|
||||||
|
self._offline_buffer = deque(maxlen=settings.offline_call_buffer_size)
|
||||||
|
|
||||||
nid = settings.node_id
|
nid = settings.node_id
|
||||||
self._t_checkin = f"nodes/{nid}/checkin"
|
self._t_checkin = f"nodes/{nid}/checkin"
|
||||||
self._t_status = f"nodes/{nid}/status"
|
self._t_status = f"nodes/{nid}/status"
|
||||||
@@ -64,6 +67,7 @@ class MQTTManager:
|
|||||||
logger.info("MQTT connected.")
|
logger.info("MQTT connected.")
|
||||||
asyncio.run_coroutine_threadsafe(self._publish_checkin(), self._loop)
|
asyncio.run_coroutine_threadsafe(self._publish_checkin(), self._loop)
|
||||||
asyncio.run_coroutine_threadsafe(self._maybe_request_key(), self._loop)
|
asyncio.run_coroutine_threadsafe(self._maybe_request_key(), self._loop)
|
||||||
|
asyncio.run_coroutine_threadsafe(self._flush_offline_buffer(), self._loop)
|
||||||
else:
|
else:
|
||||||
logger.error(f"MQTT connect refused: {reason_code}")
|
logger.error(f"MQTT connect refused: {reason_code}")
|
||||||
|
|
||||||
@@ -130,7 +134,23 @@ class MQTTManager:
|
|||||||
"timestamp": datetime.now(timezone.utc).isoformat(),
|
"timestamp": datetime.now(timezone.utc).isoformat(),
|
||||||
**data,
|
**data,
|
||||||
}
|
}
|
||||||
self._publish(self._t_metadata, payload, qos=1)
|
if not self._connected:
|
||||||
|
if event_type == "call_end":
|
||||||
|
self._offline_buffer.append((self._t_metadata, payload))
|
||||||
|
logger.warning(f"MQTT offline. Buffered call_end event for {data.get('call_id')}")
|
||||||
|
else:
|
||||||
|
logger.debug(f"MQTT offline. Dropping metadata event: {event_type}")
|
||||||
|
else:
|
||||||
|
self._publish(self._t_metadata, payload, qos=1)
|
||||||
|
|
||||||
|
async def _flush_offline_buffer(self):
|
||||||
|
if not self._offline_buffer:
|
||||||
|
return
|
||||||
|
count = len(self._offline_buffer)
|
||||||
|
logger.info(f"Relaying {count} buffered call_end events from offline queue.")
|
||||||
|
while self._offline_buffer:
|
||||||
|
topic, payload = self._offline_buffer.popleft()
|
||||||
|
self._publish(topic, payload, qos=1)
|
||||||
|
|
||||||
async def _maybe_request_key(self):
|
async def _maybe_request_key(self):
|
||||||
"""After connecting, wait for any retained api_key message to arrive.
|
"""After connecting, wait for any retained api_key message to arrive.
|
||||||
|
|||||||
@@ -1,8 +1,34 @@
|
|||||||
import httpx
|
import httpx
|
||||||
from typing import Optional, Dict, Any
|
from dataclasses import dataclass, field
|
||||||
|
from typing import Optional, Dict, Any, List
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
from app.internal.logger import logger
|
from app.internal.logger import logger
|
||||||
|
|
||||||
|
# The OP25 HTTP terminal answers a single "update" command with a LIST of
|
||||||
|
# messages, each tagged with a `json_type`. We care about two of them:
|
||||||
|
#
|
||||||
|
# channel_update — current receiver state. `channels` holds the channel ids and
|
||||||
|
# each id is also a top-level key holding that channel's dict
|
||||||
|
# (freq/tgid/tag/srcaddr/svcopts/hold_tgid/…).
|
||||||
|
#
|
||||||
|
# call_log — an EVENT QUEUE, not a snapshot. `log` holds entries appended
|
||||||
|
# by tk_p25.log_call() at channel-grant time, each stamped with
|
||||||
|
# OP25's own time.time(). get_call_log() DRAINS the deque, so
|
||||||
|
# every entry is delivered exactly once and a missed poll loses
|
||||||
|
# it forever. The deque is capped at CALL_LOG_MAX_LEN = 10, so
|
||||||
|
# the consumer must keep up.
|
||||||
|
#
|
||||||
|
# Everything else (trunk_update, rx_update, terminal_config, …) is ignored.
|
||||||
|
TERMINAL_UPDATE_COMMAND = [{"command": "update", "arg1": 0, "arg2": 0}]
|
||||||
|
|
||||||
|
|
||||||
|
@dataclass
|
||||||
|
class TerminalUpdate:
|
||||||
|
"""One decoded poll of the OP25 HTTP terminal."""
|
||||||
|
|
||||||
|
channels: List[Dict[str, Any]] = field(default_factory=list)
|
||||||
|
call_log: List[Dict[str, Any]] = field(default_factory=list)
|
||||||
|
|
||||||
|
|
||||||
class OP25Client:
|
class OP25Client:
|
||||||
def __init__(self):
|
def __init__(self):
|
||||||
@@ -49,24 +75,67 @@ class OP25Client:
|
|||||||
logger.error(f"OP25 generate-config failed: {e}")
|
logger.error(f"OP25 generate-config failed: {e}")
|
||||||
return False
|
return False
|
||||||
|
|
||||||
async def get_terminal_status(self) -> Optional[Any]:
|
async def poll_terminal(self) -> Optional[TerminalUpdate]:
|
||||||
"""Poll the OP25 HTTP terminal for current call metadata."""
|
"""
|
||||||
|
Poll the OP25 HTTP terminal once and decode every message we understand.
|
||||||
|
|
||||||
|
Returns None only when OP25 is unreachable / returned garbage — callers
|
||||||
|
use that to distinguish "no traffic" from "no OP25".
|
||||||
|
"""
|
||||||
try:
|
try:
|
||||||
async with httpx.AsyncClient(timeout=3) as client:
|
async with httpx.AsyncClient(timeout=3) as client:
|
||||||
r = await client.post(
|
r = await client.post(self.terminal_url, json=TERMINAL_UPDATE_COMMAND)
|
||||||
self.terminal_url,
|
|
||||||
json=[{"command": "update", "arg1": 0, "arg2": 0}],
|
|
||||||
)
|
|
||||||
r.raise_for_status()
|
r.raise_for_status()
|
||||||
messages = r.json()
|
return parse_terminal_messages(r.json())
|
||||||
for msg in messages:
|
|
||||||
if msg.get("json_type") == "channel_update":
|
|
||||||
channels = msg.get("channels", [])
|
|
||||||
if channels:
|
|
||||||
return msg.get(str(channels[0]), {})
|
|
||||||
return None
|
|
||||||
except Exception:
|
except Exception:
|
||||||
return None
|
return None
|
||||||
|
|
||||||
|
async def get_terminal_status(self) -> Optional[Dict[str, Any]]:
|
||||||
|
"""
|
||||||
|
Compatibility shim: the first channel's state dict, as this used to return.
|
||||||
|
|
||||||
|
Prefer poll_terminal() — this discards the call_log, which is the only
|
||||||
|
source of exact call-start timestamps.
|
||||||
|
"""
|
||||||
|
update = await self.poll_terminal()
|
||||||
|
if not update or not update.channels:
|
||||||
|
return None
|
||||||
|
return update.channels[0]
|
||||||
|
|
||||||
|
|
||||||
|
def parse_terminal_messages(messages: Any) -> TerminalUpdate:
|
||||||
|
"""
|
||||||
|
Decode an OP25 terminal response into channel state + call-log events.
|
||||||
|
|
||||||
|
Deliberately permissive: the response may be a bare dict instead of a list,
|
||||||
|
may contain json_type values we have never seen, and individual entries may
|
||||||
|
be malformed. Anything unrecognised is skipped rather than raising, because
|
||||||
|
dropping a whole poll would drop call_log events that are never re-sent.
|
||||||
|
"""
|
||||||
|
update = TerminalUpdate()
|
||||||
|
|
||||||
|
if isinstance(messages, dict):
|
||||||
|
messages = [messages]
|
||||||
|
if not isinstance(messages, list):
|
||||||
|
return update
|
||||||
|
|
||||||
|
for msg in messages:
|
||||||
|
if not isinstance(msg, dict):
|
||||||
|
continue
|
||||||
|
json_type = msg.get("json_type")
|
||||||
|
|
||||||
|
if json_type == "channel_update":
|
||||||
|
for chan_id in msg.get("channels") or []:
|
||||||
|
channel = msg.get(str(chan_id))
|
||||||
|
if isinstance(channel, dict):
|
||||||
|
update.channels.append(channel)
|
||||||
|
|
||||||
|
elif json_type == "call_log":
|
||||||
|
for entry in msg.get("log") or []:
|
||||||
|
if isinstance(entry, dict):
|
||||||
|
update.call_log.append(entry)
|
||||||
|
|
||||||
|
return update
|
||||||
|
|
||||||
|
|
||||||
op25_client = OP25Client()
|
op25_client = OP25Client()
|
||||||
|
|||||||
@@ -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
|
||||||
@@ -0,0 +1,141 @@
|
|||||||
|
"""
|
||||||
|
PulseAudio readiness helpers.
|
||||||
|
|
||||||
|
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 (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
|
||||||
|
instead. That means the `set-default-source drb_sink.monitor` line in system.pa
|
||||||
|
is NOT applied at runtime, so `-i default` is unreliable. Always address the
|
||||||
|
monitor explicitly via settings.pulse_source (default "drb_sink.monitor").
|
||||||
|
"""
|
||||||
|
import asyncio
|
||||||
|
import os
|
||||||
|
import shutil
|
||||||
|
import subprocess
|
||||||
|
from typing import Optional
|
||||||
|
|
||||||
|
from app.config import settings
|
||||||
|
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)."""
|
||||||
|
server = os.environ.get("PULSE_SERVER", "")
|
||||||
|
if server.startswith("unix:"):
|
||||||
|
candidate = server[len("unix:"):].strip()
|
||||||
|
if candidate:
|
||||||
|
return candidate
|
||||||
|
return DEFAULT_SOCKET_PATH
|
||||||
|
|
||||||
|
|
||||||
|
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 a PulseAudio daemon actually answers, or `timeout` seconds
|
||||||
|
elapse.
|
||||||
|
|
||||||
|
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 await asyncio.to_thread(_daemon_responds):
|
||||||
|
return True
|
||||||
|
|
||||||
|
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 await asyncio.to_thread(_daemon_responds):
|
||||||
|
logger.info(f"PulseAudio daemon live after {waited:.1f}s.")
|
||||||
|
return True
|
||||||
|
|
||||||
|
logger.error(
|
||||||
|
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
|
import asyncio
|
||||||
from contextlib import asynccontextmanager
|
from contextlib import asynccontextmanager
|
||||||
|
from datetime import datetime, timezone
|
||||||
|
from typing import Optional
|
||||||
|
|
||||||
from fastapi import FastAPI
|
from fastapi import FastAPI
|
||||||
from app.config import settings
|
from app.config import settings
|
||||||
from app.models import SystemConfig
|
from app.models import SystemConfig
|
||||||
@@ -20,34 +23,119 @@ from app.routers import api, ui
|
|||||||
# Event handlers wired up at startup
|
# 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):
|
async def on_call_start(data: dict):
|
||||||
radio_bot.start_stream()
|
radio_bot.start_stream()
|
||||||
await mqtt_manager.publish_status("recording")
|
await mqtt_manager.publish_status("recording")
|
||||||
await mqtt_manager.publish_metadata("call_start", data)
|
# started_at_epoch is the detected voice onset (or, in console fallback mode,
|
||||||
await call_recorder.start_recording(data["call_id"])
|
# 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):
|
async def on_call_end(data: dict):
|
||||||
radio_bot.stop_stream()
|
radio_bot.stop_stream()
|
||||||
file_path = await call_recorder.stop_recording()
|
call_id = data["call_id"]
|
||||||
if file_path:
|
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()
|
node_cfg = load_node_config()
|
||||||
audio_url = await call_recorder.upload_recording(
|
audio_url = await call_recorder.upload_recording(
|
||||||
file_path,
|
recording.path,
|
||||||
data["call_id"],
|
data["call_id"],
|
||||||
talkgroup_id=data.get("tgid"),
|
talkgroup_id=data.get("tgid"),
|
||||||
talkgroup_name=data.get("tgid_name"),
|
talkgroup_name=data.get("tgid_name"),
|
||||||
system_id=node_cfg.assigned_system_id,
|
system_id=node_cfg.assigned_system_id,
|
||||||
|
audio_start_epoch=recording.audio_start_epoch,
|
||||||
|
audio_end_epoch=recording.audio_end_epoch,
|
||||||
)
|
)
|
||||||
if audio_url:
|
if audio_url:
|
||||||
data["audio_url"] = audio_url
|
data["audio_url"] = audio_url
|
||||||
else:
|
else:
|
||||||
logger.error(f"Audio upload failed for call {data['call_id']}. Verify C2_URL and Node API Key.")
|
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:
|
else:
|
||||||
logger.warning(
|
logger.warning(
|
||||||
f"No recording file generated for call {data['call_id']} "
|
f"No recording file generated for call {data['call_id']} "
|
||||||
"— call may have been too short or Icecast unreachable."
|
"— 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_metadata("call_end", data)
|
||||||
await mqtt_manager.publish_status("online")
|
await mqtt_manager.publish_status("online")
|
||||||
|
|
||||||
@@ -184,6 +272,10 @@ async def lifespan(app: FastAPI):
|
|||||||
# Wire callbacks
|
# Wire callbacks
|
||||||
metadata_watcher.on_call_start = on_call_start
|
metadata_watcher.on_call_start = on_call_start
|
||||||
metadata_watcher.on_call_end = on_call_end
|
metadata_watcher.on_call_end = on_call_end
|
||||||
|
# Segment boundaries come from the audio itself; this is how the watcher
|
||||||
|
# sees it. Without this the watcher falls back to control-channel
|
||||||
|
# segmentation, which is measurably wrong in both directions.
|
||||||
|
metadata_watcher.audio_activity = call_recorder.audio_activity
|
||||||
mqtt_manager.on_command = on_command
|
mqtt_manager.on_command = on_command
|
||||||
mqtt_manager.on_config_push = on_config_push
|
mqtt_manager.on_config_push = on_config_push
|
||||||
mqtt_manager.on_api_key = on_api_key
|
mqtt_manager.on_api_key = on_api_key
|
||||||
@@ -191,7 +283,7 @@ async def lifespan(app: FastAPI):
|
|||||||
# Start services (radio_bot starts on-demand when a discord_join command arrives)
|
# Start services (radio_bot starts on-demand when a discord_join command arrives)
|
||||||
await mqtt_manager.connect()
|
await mqtt_manager.connect()
|
||||||
await metadata_watcher.start()
|
await metadata_watcher.start()
|
||||||
await call_recorder.start() # persistent Icecast stream buffer
|
await call_recorder.start() # persistent PulseAudio ring buffer
|
||||||
|
|
||||||
# Start system caching in background
|
# Start system caching in background
|
||||||
from app.internal.system_cacher import fetch_and_cache_systems
|
from app.internal.system_cacher import fetch_and_cache_systems
|
||||||
|
|||||||
@@ -37,6 +37,7 @@ class NodeConfig(BaseModel):
|
|||||||
enforce_override_timeout: bool = True
|
enforce_override_timeout: bool = True
|
||||||
override_system_id: Optional[str] = None
|
override_system_id: Optional[str] = None
|
||||||
override_config: Optional[SystemConfig] = None
|
override_config: Optional[SystemConfig] = None
|
||||||
|
offline_call_buffer_size: int = 35 # max call_end events to buffer while MQTT is offline
|
||||||
|
|
||||||
|
|
||||||
class CallEvent(BaseModel):
|
class CallEvent(BaseModel):
|
||||||
|
|||||||
@@ -48,6 +48,17 @@ async def get_status():
|
|||||||
"assigned_system_id": node_cfg.assigned_system_id,
|
"assigned_system_id": node_cfg.assigned_system_id,
|
||||||
"system_name": system_name,
|
"system_name": system_name,
|
||||||
"is_recording": call_recorder.is_recording,
|
"is_recording": call_recorder.is_recording,
|
||||||
|
# Health of the PulseAudio capture that feeds every recording — the single
|
||||||
|
# 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": active_tgid,
|
||||||
"active_tgid_name": active_tgid_name,
|
"active_tgid_name": active_tgid_name,
|
||||||
"active_call_id": metadata_watcher.active_call_id,
|
"active_call_id": metadata_watcher.active_call_id,
|
||||||
|
|||||||
@@ -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)
|
||||||
@@ -0,0 +1,634 @@
|
|||||||
|
"""
|
||||||
|
Unit tests for the CallRecorder: PCM ring buffer, per-call accumulator, the
|
||||||
|
continuous voice-activity signal the segmenter reads, and the single encode.
|
||||||
|
|
||||||
|
No FFmpeg and no PulseAudio: chunks are pushed through _ingest() with a patched
|
||||||
|
clock, which is exactly what the capture loop does at runtime, 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
|
||||||
|
|
||||||
|
# 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 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 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
|
||||||
|
while ts < end:
|
||||||
|
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):
|
||||||
|
return [ts for ts, _ in recorder._buffer]
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Ring buffer trimming (pre-roll duty only)
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
def test_idle_buffer_keeps_only_the_rolling_window(recorder):
|
||||||
|
ingest(recorder, T0, T0 + RING_BUFFER_SECONDS + 20)
|
||||||
|
|
||||||
|
assert recorder.buffered_seconds <= RING_BUFFER_SECONDS + CHUNK_INTERVAL
|
||||||
|
newest = max(timestamps(recorder))
|
||||||
|
assert min(timestamps(recorder)) >= newest - RING_BUFFER_SECONDS
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_ring_buffer_is_trimmed_even_while_recording(recorder):
|
||||||
|
"""
|
||||||
|
The ring buffer serves PRE-ROLL only. An open recording must 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)
|
||||||
|
|
||||||
|
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)
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# 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
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Pre-roll and slicing
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
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=onset)
|
||||||
|
assert recorder._active.slice_start == pytest.approx(onset - PRE_ROLL_SECONDS)
|
||||||
|
|
||||||
|
rec = await recorder.stop_recording(end_epoch=onset + 2.0)
|
||||||
|
assert rec is not None and rec.path is not None and rec.path.exists()
|
||||||
|
|
||||||
|
first_ts = 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):
|
||||||
|
ingest(recorder, T0, T0 + 10.0)
|
||||||
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
|
||||||
|
rec = await recorder.stop_recording(end_epoch=T0 + 3.05)
|
||||||
|
|
||||||
|
# The chunk covering the end instant must be kept, so the captured audio
|
||||||
|
# reaches past the requested end rather than stopping short of it.
|
||||||
|
assert rec.audio_end_epoch >= T0 + 3.05
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_max_recording_seconds_caps_the_slice(recorder):
|
||||||
|
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
|
||||||
|
rec = await recorder.stop_recording(end_epoch=T0 + 8.0)
|
||||||
|
|
||||||
|
assert rec is not None and rec.path is not None and rec.path.stat().st_size > 0
|
||||||
|
assert rec.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, 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()
|
||||||
|
ingest(recorder, now - 5.0, now)
|
||||||
|
|
||||||
|
await recorder.start_recording("call-1")
|
||||||
|
assert recorder._active.slice_start == pytest.approx(now - PRE_ROLL_SECONDS, abs=1.0)
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Encode — exactly once, at save time
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_audio_is_encoded_exactly_once_per_call(recorder, encodes, monkeypatch):
|
||||||
|
"""
|
||||||
|
The old pipeline captured MP3 and then re-encoded it to trim, so every
|
||||||
|
upload was double-encoded. Capture is PCM now and MP3 happens once, after
|
||||||
|
trimming, at save time.
|
||||||
|
"""
|
||||||
|
monkeypatch.setattr(settings, "trim_silence", True)
|
||||||
|
ingest(recorder, T0, T0 + 1.0, chunk=QUIET)
|
||||||
|
ingest(recorder, T0 + 1.0, T0 + 3.0, chunk=VOICE)
|
||||||
|
ingest(recorder, T0 + 3.0, T0 + 6.0, chunk=QUIET)
|
||||||
|
|
||||||
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
rec = await recorder.stop_recording(end_epoch=T0 + 6.0)
|
||||||
|
|
||||||
|
assert rec is not None and rec.path is not None
|
||||||
|
assert len(encodes) == 1, "exactly one encode per recording"
|
||||||
|
encoded_audio, encoded_path = encodes[0]
|
||||||
|
assert encoded_path == rec.path
|
||||||
|
# What was encoded is the TRIMMED audio, not the raw slice.
|
||||||
|
assert pcm.seconds(len(encoded_audio)) < 5.0
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_a_failed_encode_leaves_no_file_and_no_recording(recorder, monkeypatch):
|
||||||
|
async def _fail(audio, path):
|
||||||
|
return False
|
||||||
|
|
||||||
|
monkeypatch.setattr(recorder_mod, "encode_mp3", _fail)
|
||||||
|
ingest(recorder, T0, T0 + 5.0)
|
||||||
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
|
||||||
|
assert await recorder.stop_recording(end_epoch=T0 + 3.0) is None
|
||||||
|
assert list(recorder._recordings_dir.glob("*.mp3")) == []
|
||||||
|
|
||||||
|
|
||||||
|
def test_encoder_command_contract_matches_what_c2_expects():
|
||||||
|
"""
|
||||||
|
/upload has always received mono MP3 at 22050 Hz / 16 kbps, and Whisper
|
||||||
|
consumes it downstream. The single encode must not quietly change that.
|
||||||
|
"""
|
||||||
|
assert recorder_mod.MP3_SAMPLE_RATE == str(pcm.SAMPLE_RATE) == "22050"
|
||||||
|
assert recorder_mod.MP3_BITRATE == "16k"
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Silence trimming and timing metadata
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
async def _recorded(recorder, 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)
|
||||||
|
|
||||||
|
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
# Recording lifecycle
|
||||||
|
# ---------------------------------------------------------------------------
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_second_start_is_rejected_while_recording(recorder):
|
||||||
|
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
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_stop_without_start_is_a_noop(recorder):
|
||||||
|
assert await recorder.stop_recording() is None
|
||||||
|
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.
|
||||||
|
"""
|
||||||
|
ingest(recorder, T0, T0 + 10.0)
|
||||||
|
split = T0 + 5.0
|
||||||
|
|
||||||
|
await recorder.start_recording("call-1", start_epoch=T0 + 1.0)
|
||||||
|
first = await recorder.stop_recording(end_epoch=split)
|
||||||
|
|
||||||
|
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.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_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'"
|
||||||
|
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"]
|
||||||
File diff suppressed because it is too large
Load Diff
@@ -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,32 +1,65 @@
|
|||||||
#!/bin/bash
|
#!/bin/bash
|
||||||
|
|
||||||
# --- Start PulseAudio Daemon ---
|
PULSE_SOCKET=/run/pulse/native
|
||||||
# -n: skip default config (load modules inline — avoids system.pa parsing issues)
|
PULSE_PIDFILE=/run/pulse/pid
|
||||||
# --system: run as system-wide daemon
|
|
||||||
# --log-target=stderr: makes errors visible in Docker logs
|
mkdir -p /run/pulse
|
||||||
# &: background so this script continues; output still captured by Docker
|
chmod 777 /run/pulse
|
||||||
echo "Starting PulseAudio daemon..."
|
|
||||||
mkdir -p /run/pulse
|
# Returns 0 (true) only when a PulseAudio daemon actually answers on
|
||||||
chmod 777 /run/pulse
|
# $PULSE_SOCKET. A socket/pid FILE existing proves nothing by itself — that
|
||||||
pulseaudio --exit-idle-time=-1 -n --system \
|
# is exactly the bug this script works around (see stale-state check below).
|
||||||
--load="module-native-protocol-unix socket=/run/pulse/native auth-anonymous=1" \
|
pulse_daemon_alive() {
|
||||||
--load="module-null-sink sink_name=drb_sink sink_properties=device.description=DRB-Sink" \
|
PULSE_SERVER="unix:${PULSE_SOCKET}" timeout 2 pactl info >/dev/null 2>&1
|
||||||
--log-target=stderr &
|
}
|
||||||
|
|
||||||
# Wait for the socket to actually exist before continuing
|
# --- Clear stale PulseAudio state left behind by a killed daemon ---
|
||||||
echo "Waiting for PulseAudio socket..."
|
# The `pulse_socket` named volume survives container recreation, but the
|
||||||
for i in $(seq 1 20); do
|
# PulseAudio process that owned it does not. If the previous container was
|
||||||
if [ -S /run/pulse/native ]; then
|
# recreated (not gracefully stopped), its pid file and native socket are
|
||||||
echo "PulseAudio socket ready."
|
# still sitting in the volume; pulseaudio's pid.c sees the pid file and
|
||||||
break
|
# refuses to start ("Daemon already running") even though nothing is
|
||||||
fi
|
# listening. Only remove these when nothing actually answers on the socket —
|
||||||
sleep 0.5
|
# never delete a socket a live daemon is using.
|
||||||
done
|
if [ -S "$PULSE_SOCKET" ] || [ -f "$PULSE_PIDFILE" ]; then
|
||||||
if [ ! -S /run/pulse/native ]; then
|
if pulse_daemon_alive; then
|
||||||
echo "WARNING: PulseAudio socket not found after 10s — edge-node audio will fail."
|
echo "PulseAudio daemon already alive and responding at ${PULSE_SOCKET} — leaving state as-is."
|
||||||
fi
|
else
|
||||||
ls -la /run/pulse/
|
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"
|
||||||
# --- Execute the main command (uvicorn) ---
|
fi
|
||||||
echo "Starting FastAPI application..."
|
fi
|
||||||
exec "$@"
|
|
||||||
|
# --- 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..."
|
||||||
|
pulseaudio --exit-idle-time=-1 -n --system \
|
||||||
|
--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 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 pulse_daemon_alive; then
|
||||||
|
echo "PulseAudio daemon is live (pactl info succeeded)."
|
||||||
|
PULSE_LIVE=1
|
||||||
|
break
|
||||||
|
fi
|
||||||
|
sleep 0.5
|
||||||
|
done
|
||||||
|
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/
|
||||||
|
|
||||||
|
# --- Execute the main command (uvicorn) ---
|
||||||
|
echo "Starting FastAPI application..."
|
||||||
|
exec "$@"
|
||||||
|
|||||||
Reference in New Issue
Block a user