Compare commits

...

9 Commits

Author SHA1 Message Date
Logan Cusano d6dfe5a293 Drive call boundaries from audio, use the console only for the label
CI / lint (push) Failing after 5s
CI / test (push) Successful in 36s
The control channel was wrong in both directions. Grants fire 0.84-1.62s
before anyone speaks, and srcaddr can drop to 0 while someone is still
talking - one recording came back "-1.61s lead, -0.00s tail", the trim
finding nothing to remove because the window had closed on live speech.
Confirmed by ear: the cut lands at a word boundary on an unfinished word.

Audio is ground truth for WHEN. The console remains the only source of
WHO, so it still supplies talkgroup, alias and rid.

  START  voice onset in the captured audio, with a 0.25s pre-roll that
         now covers only chunk quantisation and threshold ramp-up rather
         than a variable control-channel offset.
  STOP   call_silence_timeout seconds of silence heard in the audio.
  LABEL  resolved AT CLOSE from a bounded rolling history of console
         observations overlapping the window, +4s/-2s, because there is
         no guaranteed ordering between a grant and its audio.
  SPLIT  a console talkgroup change still forces a cut, since two calls
         with no silence between them would otherwise merge into one.

Capture now emits raw PCM instead of MP3. Silence detection becomes
integer arithmetic per chunk with no decode, trimming becomes a byte
offset slice rather than a second ffmpeg pass, and MP3 encoding happens
exactly once at save - uploads are no longer double-encoded.

Audio with no talkgroup anywhere in its window is discarded rather than
uploaded: an untagged call silently poisons incident correlation, which
is worse than losing the audio. Logged at ERROR and counted on
/api/status.

When capture produces no audio at all the old console state machine
still runs, so a node with a broken audio path keeps reporting radio
activity. That is now the only consumer of call_idle_timeout.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-06 18:19:45 -04:00
Logan Cusano 085fcdf1a1 Fix test suite: pad expectations, container pytest config, asyncio markers
CI / lint (push) Failing after 5s
CI / test (push) Successful in 19s
Three unrelated failures from `make test` on the node:

test_metadata_watcher: two tests asserted the old zero-pad tgid_change
contract. Both were off by exactly call_tail_pad_seconds, i.e. the code
was doing what f1de157 intended and the tests encoded the behaviour we
deliberately changed. Updated to expect the pad.

test_pulse: four async tests errored with "async def functions are not
natively supported". Root cause is not the tests - pytest.ini sets
asyncio_mode = auto but the Dockerfile only copies app/ and tests/, so
the container had no pytest config at all and fell back to strict mode.
That is also why these passed in a local venv and failed on the node.
Copy pytest.ini into the image, and add explicit @pytest.mark.asyncio so
the tests hold up regardless of how pytest is configured.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-05 00:14:05 -04:00
Logan Cusano f1de157d69 Pad the tgid_change closes so a talkgroup switch stops clipping the tail
CI / lint (push) Failing after 4s
CI / test (push) Failing after 22s
The tgid_change and tgid_change_unlogged paths closed the outgoing
segment with no tail pad, on the reasoning that the new grant's
timestamp is an exact, already-known boundary. That is exact only in
control-channel time. The buffered audio lags control timestamps by
~1.5s (measured 0.84-1.62s across seven field calls), so slicing there
cut roughly the outgoing call's last 1.5s of speech - recordings ending
mid-word with ~0s trailing silence.

Both paths now pad, and the recorder's bounded tail wait blocks until
that audio has actually been captured. TAIL_WAIT_TIMEOUT_SECONDS goes
2.0 -> 4.0 so it can satisfy the 3.0s pad instead of giving up and
warning on every talkgroup switch.

The incoming call's pre-roll is served from the ring buffer, so the
delay costs it nothing. The two slices overlapping in the underlying
audio is correct: the stream genuinely contains one call's tail and
then the next call's start.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-04 23:53:27 -04:00
Logan Cusano ceb2836371 Raise tail pad to 3s so short transmissions are not clipped
The recording window is anchored to OP25 control-channel timestamps, but
the buffered audio lags those by roughly 1.5s. Trim logs across seven
calls measured the offset at 0.84-1.62s, consistently present.

At a 1.0s pad a short call closed its window before the voice arrived:
a 0.97s control-channel call closed at T+1.97 while voice started around
T+1.5, capturing ~0.4s of speech and cutting mid-word. Confirmed by a
0.57s file whose final 0.10s measured -12.2dB against its own -18.2dB
average - clipped speech, not a tail - and by two short calls that
logged no trim at all because no trailing silence remained.

Being generous is free here: trim_silence already strips trailing
silence back to the guard margin before upload, so long calls are
unaffected while short ones gain the window they need. Over-capture
costs nothing; under-capture loses words permanently.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-04 22:34:17 -04:00
Logan Cusano 7c4a3f2f20 Make PulseAudio readiness mean a live connection, clear stale socket state
The pulse_socket named volume survives container recreation, so after a
compose recreate the previous container's /run/pulse/pid and native
socket were still present. PulseAudio read the stale pid file, decided a
daemon was already running, and refused to start:

    E: [pulseaudio] pid.c: Daemon already running.

The entrypoint still reported "PulseAudio socket ready" because it only
checked that the socket file existed - and a stale one did. Capture then
failed in a restart loop against a dead daemon.

Readiness in both the op25 entrypoint and drb-edge-node now means a
pactl probe actually succeeds. Stale pid/socket are removed only when
that probe fails, so a live daemon's socket is never deleted.

pulseaudio-utils was missing from the edge-node image (only libpulse0
was installed), so no pactl binary existed there at all - added.

Capture exits are now classified: a missing source logs at ERROR and
names the configured PULSE_SOURCE, rather than looking identical to
"daemon not up yet". Retrying forever against a wrong source name is how
the April PulseAudio failure stayed hidden.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-04 22:10:28 -04:00
Logan Cusano b0a8ed2a5a Fix tail truncation, decouple call length from buffer, trim silence
CI / lint (push) Failing after 4s
CI / test (push) Successful in 21s
Measured six recordings off a live P25 node and found two independent
defects causing lost audio at the end of calls:

- stop_recording() sliced the ring buffer immediately, so if the MP3
  muxer had not yet delivered the tail the file was silently short.
  Now waits (bounded, 2s) until buffered audio covers the end epoch.
- TGID-change closes used the new grant's epoch as the end with no pad
  at all, guaranteeing truncation on every split. Tail pad is now a
  setting, default raised 0.5s -> 1.0s.

The ring buffer also capped maximum call length: a call longer than the
buffer had its front silently clamped. The ring now serves the pre-roll
only, with a per-call accumulator for the rest, bounded at 4.8MB.
Clamping is loudly warned rather than silent.

Uploads averaged 63% silence, which inflates STT cost and is a known
Whisper hallucination trigger. Leading/trailing silence is now trimmed
conservatively (-40dB, 0.25s guard, internal pauses untouched).
started_at/ended_at still describe the call; new audio_* fields carry
the trimmed audio bounds so playback can map back to wall clock.
All-silence recordings are skipped and logged instead of uploaded.

Also: log measured control-channel idle on idle-timeout closes so
CALL_IDLE_TIMEOUT can be tuned from data, and quiet the httpx logger
which emitted ~170k lines/day of poll noise.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-04 21:39:36 -04:00
Logan Cusano efdbe7d803 Move recording and Discord voice to PulseAudio
CI / lint (push) Failing after 26s
CI / test (push) Successful in 41s
2026-08-04 19:53:45 -04:00
Logan Cusano 9addce7716 chore: Update Makefile targets for local building and git update shorthand 2026-07-13 00:16:50 -04:00
Logan Cusano cc9af6ff26 feat: Buffer offline call_end events and relay them upon MQTT reconnection 2026-07-13 00:16:24 -04:00
22 changed files with 4672 additions and 320 deletions
+54
View File
@@ -16,12 +16,66 @@ C2_URL=http://localhost:8888
# API key is provisioned automatically via MQTT after admin approves the node
# Icecast (local container — usually no need to change)
# Live listening only. Call recording and Discord voice use PulseAudio instead.
ICECAST_SOURCE_PASSWORD=hackme
ICECAST_ADMIN_PASSWORD=admin
ICECAST_HOST=localhost
ICECAST_PORT=8000
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_API_URL=http://localhost:8001
OP25_TERMINAL_URL=http://localhost:8081
+8 -2
View File
@@ -8,9 +8,9 @@ setup:
test:
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:
docker compose up -d
docker compose up -d --build
# Pull pre-built images from the registry and start (no local build).
# Requires IMAGE_REGISTRY, DOCKER_ORG, DOCKER_REPO set in .env.
@@ -21,6 +21,12 @@ up-prebuilt:
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:
docker compose down
+4
View File
@@ -5,6 +5,7 @@ RUN apt-get update && apt-get install -y \
libopus0 \
libopus-dev \
libpulse0 \
pulseaudio-utils \
&& rm -rf /var/lib/apt/lists/*
WORKDIR /app
@@ -14,5 +15,8 @@ RUN pip install uv && uv pip install --system --no-cache-dir -r requirements.txt
COPY app/ ./app/
COPY tests/ ./tests/
# Without this the container runs pytest with asyncio_mode defaulting to strict,
# so unmarked async tests error out even though they pass locally.
COPY pytest.ini .
CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "80", "--reload"]
+92 -1
View File
@@ -18,12 +18,100 @@ class Settings(BaseSettings):
# C2 server (audio upload destination); None disables upload
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_port: int = 8000
icecast_mount: str = "/radio"
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_api_url: str = "http://localhost:8001"
op25_terminal_url: str = "http://localhost:8081"
@@ -32,6 +120,9 @@ class Settings(BaseSettings):
config_path: str = "/configs"
recordings_path: str = "/recordings"
# Offline call buffer — how many call_end events to keep while disconnected
offline_call_buffer_size: int = 35
class Config:
env_file = ".env"
+212
View File
@@ -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,
)
+678 -93
View File
@@ -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 time
from collections import deque
from dataclasses import dataclass, field
from datetime import datetime, timezone
from pathlib import Path
from typing import Optional
from typing import List, Optional, Tuple
import httpx
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
MAX_RECORDING_SECONDS = 600 # safety cap; drop call if it runs this long
PRE_BUFFER_SECONDS = 1.0 # seconds of audio to include before call_start
RING_BUFFER_SECONDS = 60 # how much history to keep when no call is active
READ_CHUNK_BYTES = 4096 # bytes per httpx read
# Safety cap on a single recording; mirrors MAX_SEGMENT_SECONDS in metadata_watcher.
MAX_RECORDING_SECONDS = 600
# 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:
"""
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 ~12 s.
"""
"""Continuous PulseAudio capture: ring buffer for pre-roll, accumulator per call."""
def __init__(self):
self._recordings_dir = Path(settings.recordings_path)
# Ring buffer: deque of (monotonic_time, bytes_chunk)
self._buffer: deque[tuple[float, bytes]] = deque()
# Ring buffer: deque of (wall_clock_epoch_at_arrival, pcm_bytes).
# Pre-roll only — see the module docstring.
self._buffer: deque[Tuple[float, bytes]] = deque()
self._buffer_bytes: int = 0
self._stream_task: Optional[asyncio.Task] = None
self._proc: Optional[asyncio.subprocess.Process] = None
self._capturing: bool = False
# Active call state
self._call_id: Optional[str] = None
self._call_start_mono: Optional[float] = None
# Voice activity, tracked continuously — not only while recording.
self._last_voice_epoch: Optional[float] = None
self._voice_onset_epoch: Optional[float] = None
# Active recording state (None when idle)
self._active: Optional[_ActiveRecording] = None
# Last few lines of the most recent FFmpeg stderr, used to classify
# why a capture process exited (see _classify_capture_exit).
self._last_stderr_lines: deque[str] = deque(maxlen=10)
# ------------------------------------------------------------------
# Lifecycle
# ------------------------------------------------------------------
async def start(self) -> None:
"""Start the persistent stream buffer. Call once from app lifespan."""
self._stream_task = asyncio.create_task(self._stream_loop())
logger.info("Stream ring-buffer started.")
"""Start the persistent capture. Call once from app lifespan."""
self._stream_task = asyncio.create_task(self._capture_loop())
logger.info("PulseAudio ring-buffer starting.")
async def stop(self) -> None:
"""Cancel the stream reader."""
if self._stream_task:
self._stream_task.cancel()
try:
@@ -57,111 +314,415 @@ class CallRecorder:
except asyncio.CancelledError:
pass
self._stream_task = None
await self._terminate_proc()
# ------------------------------------------------------------------
# Stream reader
# Capture
# ------------------------------------------------------------------
async def _stream_loop(self) -> None:
stream_url = (
f"http://{settings.icecast_host}:{settings.icecast_port}"
f"{settings.icecast_mount}"
)
timeout = httpx.Timeout(connect=10.0, read=None, write=10.0, pool=10.0)
def _ffmpeg_command(self) -> List[str]:
return [
"ffmpeg",
"-hide_banner", "-nostdin", "-nostats",
"-loglevel", "warning",
"-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:
try:
async with httpx.AsyncClient(timeout=timeout) as client:
async with client.stream("GET", stream_url) as response:
response.raise_for_status()
logger.info(f"Stream buffer connected to {stream_url}")
async for chunk in response.aiter_bytes(READ_CHUNK_BYTES):
self._ingest(chunk)
# The original bug this path was abandoned for: FFmpeg was launched
# with -f pulse before the shared socket existed, failed instantly,
# and never recovered. Wait for it, bounded, every time.
if not await pulse.wait_until_ready():
await asyncio.sleep(backoff)
backoff = min(backoff * 2, RESTART_BACKOFF_MAX)
continue
await self._run_capture()
self._log_capture_exit()
except asyncio.CancelledError:
await self._terminate_proc()
raise
except Exception as e:
logger.warning(f"Stream buffer disconnected ({e}) — retrying in 3 s")
await asyncio.sleep(3)
logger.warning(f"PulseAudio capture error ({e}) — restarting.")
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:
"""Append a chunk and trim stale data from the front of the buffer."""
now = time.monotonic()
"""Append a chunk to the ring buffer and, if recording, the accumulator."""
now = time.time()
self._note_voice(chunk, now)
self._buffer.append((now, chunk))
self._buffer_bytes += len(chunk)
# During a call, never trim data newer than (call_start - pre_buffer).
# Between calls, keep a rolling RING_BUFFER_SECONDS window.
if self._call_start_mono is not None:
keep_from = self._call_start_mono - PRE_BUFFER_SECONDS
else:
keep_from = now - RING_BUFFER_SECONDS
while self._buffer:
ts, old = self._buffer[0]
if ts >= keep_from:
break
self._buffer.popleft()
# The ring buffer serves pre-roll only, so it is trimmed to a fixed
# window unconditionally — an open recording no longer pins it, because
# the accumulator owns that audio.
keep_from = now - RING_BUFFER_SECONDS
while self._buffer and self._buffer[0][0] < keep_from:
_, old = self._buffer.popleft()
self._buffer_bytes -= len(old)
active = self._active
if active is None:
return
if active.total_bytes + len(chunk) > MAX_RECORDING_BYTES:
if not active.truncated_by_cap:
active.truncated_by_cap = True
logger.warning(
f"Recording {active.call_id} hit the {MAX_RECORDING_BYTES} byte memory ceiling "
f"after {now - active.slice_start:.1f}s — further audio is being dropped."
)
return
active.chunks.append((now, chunk))
active.total_bytes += len(chunk)
# ------------------------------------------------------------------
# Call recording API (same interface as before)
# Recording API
# ------------------------------------------------------------------
async def start_recording(self, call_id: str) -> bool:
if self._call_id:
logger.warning("Recording already active — ignoring start.")
async def start_recording(self, call_id: str, start_epoch: Optional[float] = None) -> bool:
"""
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
self._call_id = call_id
self._call_start_mono = time.monotonic()
logger.info(f"Recording started (ring-buffer): {call_id}")
call_start = start_epoch if start_epoch else time.time()
slice_start = call_start - PRE_ROLL_SECONDS
if not self._capturing:
logger.warning(f"Recording {call_id} opened while PulseAudio capture is down — audio may be missing.")
# Seed the accumulator with the pre-roll already sitting in the ring
# buffer. No await between reading the buffer and publishing _active, so
# the capture task cannot slip a chunk in between and double-count it.
clamped = 0.0
oldest = self._buffer[0][0] if self._buffer else None
if oldest is not None and 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
async def stop_recording(self) -> Optional[Path]:
if not self._call_id:
async def discard_recording(self) -> None:
"""
Drop the open recording without writing anything.
Used when the segmenter decides the audio must not be kept — today only
the unattributed/orphan-audio path, where uploading would inject a call
with no talkgroup into correlation.
"""
active, self._active = self._active, None
if active is not None:
logger.info(f"Discarded buffered audio for {active.call_id} ({active.total_bytes} bytes).")
async def stop_recording(self, end_epoch: Optional[float] = None) -> Optional[Recording]:
"""
Close the recording, trim it, encode it once and write the file.
`end_epoch` is host wall clock.
Waits (bounded) for captured audio to actually cover `end_epoch` before
slicing — see TAIL_WAIT_TIMEOUT_SECONDS. An audio-driven close never
needs that wait, because its end epoch is derived from audio that is
already buffered; a control-channel-derived close (tgid_change) does.
Returns None only when there was no recording open or no audio at all.
"""
active = self._active
if active is None:
return None
call_id = self._call_id
call_start = self._call_start_mono
self._call_id = None
self._call_start_mono = None
call_id = active.call_id
slice_start = active.slice_start
# Slice: everything from (call_start - pre_buffer) to now
cutoff = (call_start - PRE_BUFFER_SECONDS) if call_start else 0.0
chunks = [chunk for ts, chunk in self._buffer if ts >= cutoff]
end = end_epoch if end_epoch else time.time()
end = min(end, active.call_start + MAX_RECORDING_SECONDS)
# Safety cap: if the call ran very long, truncate to MAX_RECORDING_SECONDS
if call_start is not None:
cap_cutoff = call_start + MAX_RECORDING_SECONDS
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
]
# The accumulator keeps filling during this wait — that is the point.
await self._await_tail(end, call_id)
self._active = None
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(
f"No buffered audio for call {call_id} "
"stream may not have been connected yet."
f"No buffered audio for call {call_id} "
f"(window {slice_start:.3f}{end:.3f}) — PulseAudio capture may be down."
)
return None
if last_ts < end - TAIL_WAIT_POLL_SECONDS:
logger.warning(
f"BUFFER CLAMP: call {call_id} ends {end - last_ts:.2f}s after the newest captured "
"audio — the tail is short. Capture may be stalled or restarting."
)
raw = b"".join(parts)
recording = Recording(
call_id=call_id,
path=None,
audio_start_epoch=slice_start,
audio_end_epoch=slice_start + pcm.seconds(len(raw)),
clamped_seconds=active.clamped_seconds,
)
return await self._finish(recording, raw)
async def _finish(self, recording: Recording, raw: bytes) -> Optional[Recording]:
"""Trim, encode exactly once, and write the MP3."""
audio = raw
if settings.trim_silence:
audio, result = audio_trim.trim_pcm(audio)
if result.all_silence:
logger.warning(
f"Call {recording.call_id} contains no speech at all — skipping upload. "
"Check squelch, the Liquidsoap output and the drb_sink monitor."
)
recording.all_silence = True
return recording
if result.applied:
recording.lead_trimmed = result.lead
recording.tail_trimmed = result.tail
# Wall clock of the trimmed audio's first and last sample.
recording.audio_start_epoch += result.lead
recording.audio_end_epoch -= result.tail
self._recordings_dir.mkdir(parents=True, exist_ok=True)
ts_str = datetime.now(timezone.utc).strftime("%Y%m%d_%H%M%S")
output_path = self._recordings_dir / f"{ts_str}_{call_id}.mp3"
output_path = self._recordings_dir / f"{ts_str}_{recording.call_id}.mp3"
data = b"".join(chunks)
output_path.write_bytes(data)
if not await encode_mp3(audio, output_path):
output_path.unlink(missing_ok=True)
return None
size = output_path.stat().st_size
if size > 0:
logger.info(f"Recording saved: {output_path.name} ({size} bytes)")
return output_path
size = output_path.stat().st_size if output_path.exists() else 0
if size <= 0:
output_path.unlink(missing_ok=True)
logger.warning(f"Recording for call {recording.call_id} produced an empty file.")
return None
output_path.unlink(missing_ok=True)
logger.warning(f"Recording for call {call_id} produced an empty file.")
return None
recording.path = output_path
logger.info(
f"Recording saved: {output_path.name} ({size} bytes, "
f"{pcm.seconds(len(audio)):.2f}s audio)"
)
return recording
async def _await_tail(self, end: float, call_id: str) -> float:
"""
Block until captured audio reaches `end`, or the bounded timeout expires.
Returns seconds waited. Logs whenever a wait was actually needed so the
real pipeline latency is observable in the field.
"""
if not self._buffer:
return 0.0
if self._buffer[-1][0] >= end:
return 0.0
started = time.monotonic()
deadline = started + TAIL_WAIT_TIMEOUT_SECONDS
while time.monotonic() < deadline:
await asyncio.sleep(TAIL_WAIT_POLL_SECONDS)
if self._buffer and self._buffer[-1][0] >= end:
waited = time.monotonic() - started
logger.info(f"Waited {waited:.2f}s for the tail of call {call_id} to reach the buffer.")
return waited
if not self._capturing:
break # capture died mid-wait; nothing more is coming
waited = time.monotonic() - started
newest = self._buffer[-1][0] if self._buffer else end
logger.warning(
f"Tail wait for call {call_id} gave up after {waited:.2f}s — captured audio is still "
f"{max(0.0, end - newest):.2f}s short of the call end. Tail may be clipped."
)
return waited
# ------------------------------------------------------------------
# Upload (unchanged interface)
@@ -174,6 +735,8 @@ class CallRecorder:
talkgroup_id: Optional[int] = None,
talkgroup_name: Optional[str] = None,
system_id: Optional[str] = None,
audio_start_epoch: Optional[float] = None,
audio_end_epoch: Optional[float] = None,
) -> Optional[str]:
if not settings.c2_url:
logger.info("No C2_URL configured — skipping upload.")
@@ -190,6 +753,13 @@ class CallRecorder:
form["talkgroup_name"] = talkgroup_name
if system_id:
form["system_id"] = system_id
# Where this audio really sits on the wall clock once silence is trimmed.
# C2 does not declare these Form fields yet, so FastAPI ignores them —
# they cost nothing and are here for when playback/correlation want them.
if audio_start_epoch is not None:
form["audio_start_epoch"] = f"{audio_start_epoch:.3f}"
if audio_end_epoch is not None:
form["audio_end_epoch"] = f"{audio_end_epoch:.3f}"
try:
async with httpx.AsyncClient(timeout=120) as client:
@@ -213,9 +783,24 @@ class CallRecorder:
except Exception:
pass
# ------------------------------------------------------------------
# State
# ------------------------------------------------------------------
@property
def is_recording(self) -> bool:
return self._call_id is not None
return self._active is not None
@property
def is_capturing(self) -> bool:
"""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()
+46 -10
View File
@@ -2,11 +2,14 @@ import asyncio
from typing import Optional
import discord
from discord.ext import commands
from app.config import settings
from app.internal import pulse
from app.internal.logger import logger
BOT_READY_TIMEOUT = 15 # seconds to wait for Discord bot to become ready
WATCHDOG_INTERVAL = 30 # seconds between voice-connection health checks
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:
@@ -47,6 +50,10 @@ class RadioBot:
# Remember where we are so the watchdog can rejoin if we drop
self._guild_id = guild_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()
if system_name:
await self._bot.change_presence(
@@ -108,19 +115,48 @@ class RadioBot:
self._ready_event = None
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:
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(
stream_url,
before_options="-reconnect 1 -reconnect_streamed 1 -reconnect_delay_max 5",
settings.pulse_source,
before_options="-f pulse",
)
self._voice_client.play(
discord.PCMVolumeTransformer(source, volume=1.0),
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):
if 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()):
return
if error:
# Back off before retrying — prevents tight loop when PulseAudio is unavailable
async def _delayed_restart():
await asyncio.sleep(5)
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()))
# Back off before retrying — prevents a tight loop when PulseAudio is
# unavailable (FFmpeg exits immediately in that case).
self._schedule_restart()
else:
self._loop.call_soon_threadsafe(self._play_stream)
@@ -232,6 +265,9 @@ class RadioBot:
else:
self._voice_client = await vc.connect()
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}.")
except Exception as e:
logger.error(f"joinme failed: {e}")
+8
View File
@@ -7,4 +7,12 @@ logging.basicConfig(
handlers=[logging.StreamHandler(sys.stdout)],
)
# The metadata watcher polls the OP25 terminal twice a second and httpx logs
# every one of those requests at INFO ("HTTP Request: POST http://... 200 OK").
# That is ~170k lines/day of pure noise which buries real events and makes field
# log-reading useless. WARNING keeps genuine transport failures visible.
# httpcore is the transport layer underneath httpx and is just as chatty.
for _noisy in ("httpx", "httpcore"):
logging.getLogger(_noisy).setLevel(logging.WARNING)
logger = logging.getLogger("drb-edge-node")
+826 -54
View File
@@ -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 time
import uuid
from collections import deque
from dataclasses import dataclass, field
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.logger import logger
CallbackFn = Callable[[dict], Awaitable[None]]
ActivityFn = Callable[[], AudioActivity]
HANG_THRESHOLD = 2 # polls before declaring a call ended (0.5s poll → 1s hang time)
POLL_INTERVAL = 0.5 # seconds
# 500 ms. Do NOT lower: audio boundaries come from the recorder's own chunk
# timestamps (~46 ms resolution), not from when this loop happens to notice
# them, and http_server.py's request handler has a ~200 ms blocking floor anyway.
POLL_INTERVAL = 0.5
# Seconds of unreachable OP25 before an open segment is force-closed. 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:
def __init__(self):
self._running = False
# Open segment state
self._active_call_id: Optional[str] = None
self._current_tgid: Optional[int] = None
self._current_tgid_name: Optional[str] = None
self._hang_counter: int = 0
self._active_call_id: Optional[str] = None
self._call_started_at: Optional[datetime] = None
self._current_freq: Any = None
self._current_srcaddr: Optional[int] = 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()
self.on_call_start: Optional[CallbackFn] = None
self.on_call_end: Optional[CallbackFn] = None
# Supplies the audio-activity snapshot. None (or a snapshot reporting
# capturing=False) puts the watcher in console fallback mode.
self.audio_activity: Optional[ActivityFn] = None
# ------------------------------------------------------------------
# Lifecycle
# ------------------------------------------------------------------
async def start(self):
self._running = True
self._last_ok_poll = self._clock()
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):
self._running = False
if self._active_call_id:
await self._end_call()
await self._close_segment(self._clock(), reason="shutdown")
async def _poll_loop(self):
while self._running:
@@ -42,79 +278,610 @@ class MetadataWatcher:
logger.warning(f"Metadata poll error: {e}")
await asyncio.sleep(POLL_INTERVAL)
async def _tick(self):
status = await op25_client.get_terminal_status()
# ------------------------------------------------------------------
# One poll
# ------------------------------------------------------------------
if not status:
# OP25 not responding — hang-out any active call
if self._active_call_id:
self._hang_counter += 1
if self._hang_counter >= HANG_THRESHOLD:
await self._end_call()
async def _tick(self):
now = self._clock()
update = await op25_client.poll_terminal()
if update is None:
# 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
# OP25 terminal returns either a list of channels or a single dict
channels = status if isinstance(status, list) else [status]
active_tgid: Optional[int] = None
active_meta: dict = {}
self._last_ok_poll = now
self._record_console(update, now)
for ch in channels:
tgid = ch.get("tgid") or ch.get("tg_id")
if tgid and str(tgid) not in ("0", "", "None"):
active_tgid = int(tgid)
active_meta = ch
break
activity = self._snapshot()
if activity is None or not activity.capturing:
await self._console_tick(update, now)
return
if active_tgid:
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()
await self._audio_tick(update, activity, now)
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._call_started_at = datetime.now(timezone.utc)
self._current_tgid_name = meta.get("tag") or meta.get("tgid_tag") or ""
self._current_tgid = tgid
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 = {
"call_id": self._active_call_id,
"tgid": tgid,
"tgid_name": self._current_tgid_name,
"freq": meta.get("freq"),
"srcaddr": meta.get("srcaddr"),
"started_at": self._call_started_at.isoformat(),
"tgid_name": tgid_name,
"freq": freq,
"srcaddr": srcaddr,
"started_at": _iso(started_at),
# Raw epoch for the recorder's ring-buffer slice — same clock domain.
"started_at_epoch": started_at,
"attributed": tgid is not None,
"driver": "audio" if audio_driven else "console",
}
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:
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:
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 = {
"call_id": self._active_call_id,
"tgid": self._current_tgid,
"tgid_name": self._current_tgid_name or "",
"started_at": self._call_started_at.isoformat() if self._call_started_at else None,
"ended_at": datetime.now(timezone.utc).isoformat(),
"freq": self._current_freq,
"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._current_tgid = None
self._current_tgid_name = None
self._hang_counter = 0
self._call_started_at = None
self._current_freq = 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:
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
def active_call_id(self) -> Optional[str]:
return self._active_call_id
@@ -131,5 +898,10 @@ class MetadataWatcher:
def is_active(self) -> bool:
return self._active_call_id is not None
@property
def unattributed_segments(self) -> int:
"""Orphan-audio segments discarded since start. Surfaced on /api/status."""
return self._unattributed_segments
metadata_watcher = MetadataWatcher()
+21 -1
View File
@@ -1,6 +1,7 @@
import asyncio
import json
from datetime import datetime, timezone
from collections import deque
from typing import Optional, Callable, Awaitable, Dict, Any
import paho.mqtt.client as mqtt
from app.config import settings
@@ -23,6 +24,8 @@ class MQTTManager:
self.on_config_push: Optional[ConfigCallback] = None
self.on_api_key: Optional[ApiKeyCallback] = None
self._offline_buffer = deque(maxlen=settings.offline_call_buffer_size)
nid = settings.node_id
self._t_checkin = f"nodes/{nid}/checkin"
self._t_status = f"nodes/{nid}/status"
@@ -64,6 +67,7 @@ class MQTTManager:
logger.info("MQTT connected.")
asyncio.run_coroutine_threadsafe(self._publish_checkin(), self._loop)
asyncio.run_coroutine_threadsafe(self._maybe_request_key(), self._loop)
asyncio.run_coroutine_threadsafe(self._flush_offline_buffer(), self._loop)
else:
logger.error(f"MQTT connect refused: {reason_code}")
@@ -130,7 +134,23 @@ class MQTTManager:
"timestamp": datetime.now(timezone.utc).isoformat(),
**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):
"""After connecting, wait for any retained api_key message to arrive.
+83 -14
View File
@@ -1,8 +1,34 @@
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.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:
def __init__(self):
@@ -49,24 +75,67 @@ class OP25Client:
logger.error(f"OP25 generate-config failed: {e}")
return False
async def get_terminal_status(self) -> Optional[Any]:
"""Poll the OP25 HTTP terminal for current call metadata."""
async def poll_terminal(self) -> Optional[TerminalUpdate]:
"""
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:
async with httpx.AsyncClient(timeout=3) as client:
r = await client.post(
self.terminal_url,
json=[{"command": "update", "arg1": 0, "arg2": 0}],
)
r = await client.post(self.terminal_url, json=TERMINAL_UPDATE_COMMAND)
r.raise_for_status()
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
return parse_terminal_messages(r.json())
except Exception:
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()
+131
View File
@@ -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
+141
View File
@@ -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
+99 -7
View File
@@ -1,5 +1,8 @@
import asyncio
from contextlib import asynccontextmanager
from datetime import datetime, timezone
from typing import Optional
from fastapi import FastAPI
from app.config import settings
from app.models import SystemConfig
@@ -20,34 +23,119 @@ from app.routers import api, ui
# Event handlers wired up at startup
# ---------------------------------------------------------------------------
def _iso(epoch: Optional[float]) -> Optional[str]:
"""Epoch → UTC ISO-8601, matching metadata_watcher's timestamp format."""
if epoch is None:
return None
return datetime.fromtimestamp(epoch, timezone.utc).isoformat()
# call_ids whose `call_start` has already gone out over MQTT. A segment can open
# before its talkgroup is known (audio onset can precede the OP25 grant), and
# C2's _on_call_start writes talkgroup_id straight into a new Firestore `calls`
# doc — publishing early with tgid=None would create a permanently untagged call.
# So the start is held back until attribution succeeds, and replayed just before
# the end event if it resolved late.
_published_starts: set = set()
async def on_call_start(data: dict):
radio_bot.start_stream()
await mqtt_manager.publish_status("recording")
await mqtt_manager.publish_metadata("call_start", data)
await call_recorder.start_recording(data["call_id"])
# started_at_epoch is the detected voice onset (or, in console fallback mode,
# OP25's call_log timestamp). The recorder slices the ring buffer back to it
# minus the pre-roll, so however late the poll loop noticed, the audio still
# starts in the right place.
await call_recorder.start_recording(
data["call_id"],
start_epoch=data.get("started_at_epoch"),
)
if data.get("attributed", True):
_published_starts.add(data["call_id"])
await mqtt_manager.publish_metadata("call_start", data)
else:
logger.info(
f"Call {data['call_id']} started on audio onset with no talkgroup yet — holding the "
"call_start event until the console attributes it."
)
async def on_call_end(data: dict):
radio_bot.stop_stream()
file_path = await call_recorder.stop_recording()
if file_path:
call_id = data["call_id"]
published_start = call_id in _published_starts
_published_starts.discard(call_id)
if not data.get("attributed", True):
# ORPHAN AUDIO. metadata_watcher has already logged the details at ERROR.
# The audio is dropped rather than uploaded: a call with no talkgroup is
# worse than no call at all, because it silently poisons correlation.
await call_recorder.discard_recording()
if published_start:
# Should not happen (attribution only ever improves), but if a start
# did go out, the doc must not be left hanging in "active".
data["audio_skipped"] = "unattributed"
await mqtt_manager.publish_metadata("call_end", data)
await mqtt_manager.publish_status("online")
return
recording = await call_recorder.stop_recording(end_epoch=data.get("ended_at_epoch"))
if recording is not None and recording.path is not None:
# Silence trimming shortens the audio, so the audio's own bounds no
# longer equal the call's. `started_at`/`ended_at` keep meaning the CALL
# (what OP25 observed on the control channel) — these extra fields carry
# the AUDIO's wall-clock bounds so playback, correlation and incident
# timelines can still map an audio offset back to real time:
# wall_clock_of(audio_offset_t) == audio_start_epoch + t
data["audio_start_at"] = _iso(recording.audio_start_epoch)
data["audio_end_at"] = _iso(recording.audio_end_epoch)
data["audio_start_epoch"] = recording.audio_start_epoch
data["audio_end_epoch"] = recording.audio_end_epoch
data["audio_lead_trimmed"] = round(recording.lead_trimmed, 3)
data["audio_tail_trimmed"] = round(recording.tail_trimmed, 3)
if recording.clamped_seconds:
data["audio_clamped_seconds"] = round(recording.clamped_seconds, 3)
if recording is not None and recording.path is not None:
node_cfg = load_node_config()
audio_url = await call_recorder.upload_recording(
file_path,
recording.path,
data["call_id"],
talkgroup_id=data.get("tgid"),
talkgroup_name=data.get("tgid_name"),
system_id=node_cfg.assigned_system_id,
audio_start_epoch=recording.audio_start_epoch,
audio_end_epoch=recording.audio_end_epoch,
)
if audio_url:
data["audio_url"] = audio_url
else:
logger.error(f"Audio upload failed for call {data['call_id']}. Verify C2_URL and Node API Key.")
elif recording is not None and recording.all_silence:
# Explicit policy: an all-silence recording is not uploaded. It has no
# transcript value and silence is what makes Whisper invent text.
data["audio_skipped"] = "all_silence"
logger.warning(f"Call {data['call_id']} was pure silence — no upload. Investigate the audio path.")
else:
logger.warning(
f"No recording file generated for call {data['call_id']} "
"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_status("online")
@@ -184,6 +272,10 @@ async def lifespan(app: FastAPI):
# Wire callbacks
metadata_watcher.on_call_start = on_call_start
metadata_watcher.on_call_end = on_call_end
# Segment boundaries come from the audio itself; this is how the watcher
# sees it. Without this the watcher falls back to control-channel
# segmentation, which is measurably wrong in both directions.
metadata_watcher.audio_activity = call_recorder.audio_activity
mqtt_manager.on_command = on_command
mqtt_manager.on_config_push = on_config_push
mqtt_manager.on_api_key = on_api_key
@@ -191,7 +283,7 @@ async def lifespan(app: FastAPI):
# Start services (radio_bot starts on-demand when a discord_join command arrives)
await mqtt_manager.connect()
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
from app.internal.system_cacher import fetch_and_cache_systems
+1
View File
@@ -37,6 +37,7 @@ class NodeConfig(BaseModel):
enforce_override_timeout: bool = True
override_system_id: Optional[str] = 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):
+11
View File
@@ -48,6 +48,17 @@ async def get_status():
"assigned_system_id": node_cfg.assigned_system_id,
"system_name": system_name,
"is_recording": call_recorder.is_recording,
# Health of the PulseAudio capture that feeds every recording — the single
# most useful signal when recordings come back empty. Segment boundaries
# come from this stream, so audio_silence_seconds is also how far the
# node currently is from closing whatever it is recording.
"audio_capture": call_recorder.is_capturing,
"buffered_seconds": round(call_recorder.buffered_seconds, 1),
"audio_silence_seconds": round(call_recorder.audio_activity().silence_seconds, 1),
# Audio that was recorded but had no OP25 talkgroup anywhere near it, so
# it was discarded rather than uploaded. Non-zero means either the
# console is not decoding or something else is feeding drb_sink.
"unattributed_segments": metadata_watcher.unattributed_segments,
"active_tgid": active_tgid,
"active_tgid_name": active_tgid_name,
"active_call_id": metadata_watcher.active_call_id,
+218
View File
@@ -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)
+634
View File
@@ -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
+134
View File
@@ -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)
+141
View File
@@ -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
+65 -32
View File
@@ -1,32 +1,65 @@
#!/bin/bash
# --- Start PulseAudio Daemon ---
# -n: skip default config (load modules inline — avoids system.pa parsing issues)
# --system: run as system-wide daemon
# --log-target=stderr: makes errors visible in Docker logs
# &: background so this script continues; output still captured by Docker
echo "Starting PulseAudio daemon..."
mkdir -p /run/pulse
chmod 777 /run/pulse
pulseaudio --exit-idle-time=-1 -n --system \
--load="module-native-protocol-unix socket=/run/pulse/native auth-anonymous=1" \
--load="module-null-sink sink_name=drb_sink sink_properties=device.description=DRB-Sink" \
--log-target=stderr &
# Wait for the socket to actually exist before continuing
echo "Waiting for PulseAudio socket..."
for i in $(seq 1 20); do
if [ -S /run/pulse/native ]; then
echo "PulseAudio socket ready."
break
fi
sleep 0.5
done
if [ ! -S /run/pulse/native ]; then
echo "WARNING: PulseAudio socket not found after 10s — edge-node audio will fail."
fi
ls -la /run/pulse/
# --- Execute the main command (uvicorn) ---
echo "Starting FastAPI application..."
exec "$@"
#!/bin/bash
PULSE_SOCKET=/run/pulse/native
PULSE_PIDFILE=/run/pulse/pid
mkdir -p /run/pulse
chmod 777 /run/pulse
# Returns 0 (true) only when a PulseAudio daemon actually answers on
# $PULSE_SOCKET. A socket/pid FILE existing proves nothing by itself — that
# is exactly the bug this script works around (see stale-state check below).
pulse_daemon_alive() {
PULSE_SERVER="unix:${PULSE_SOCKET}" timeout 2 pactl info >/dev/null 2>&1
}
# --- Clear stale PulseAudio state left behind by a killed daemon ---
# The `pulse_socket` named volume survives container recreation, but the
# PulseAudio process that owned it does not. If the previous container was
# recreated (not gracefully stopped), its pid file and native socket are
# still sitting in the volume; pulseaudio's pid.c sees the pid file and
# refuses to start ("Daemon already running") even though nothing is
# listening. Only remove these when nothing actually answers on the socket —
# never delete a socket a live daemon is using.
if [ -S "$PULSE_SOCKET" ] || [ -f "$PULSE_PIDFILE" ]; then
if pulse_daemon_alive; then
echo "PulseAudio daemon already alive and responding at ${PULSE_SOCKET} — leaving state as-is."
else
echo "STALE STATE: found ${PULSE_PIDFILE} / ${PULSE_SOCKET} from a previous container, but no daemon answers — clearing before start."
rm -f "$PULSE_SOCKET" "$PULSE_PIDFILE"
fi
fi
# --- Start PulseAudio Daemon ---
# -n: skip default config (load modules inline — avoids system.pa parsing issues)
# --system: run as system-wide daemon
# --log-target=stderr: makes errors visible in Docker logs
# &: background so this script continues; output still captured by Docker
echo "Starting PulseAudio daemon..."
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 "$@"