Commit c6d298eb by PLN (Algolia)

gig-log, gig-record: a burst read whole, and a target that can be checked

Two bugs I introduced or left standing in the two commits before this one.

SELECT PLUS READLINE DRAINS ONE LINE PER EVENT. readline() on a
TextIOWrapper pulls a whole chunk off the fd and hands back one line; the
rest sits in the wrapper's decoded buffer, where select() on the fd cannot
see it. A fader sweep is 100+ lines a second arriving in bursts, so the
tail of a gesture would be logged only when the NEXT gesture arrived,
stamped with the wrong second. Measured on a real pipe: 1 of 50 lines,
against 50 of 50 once the reader owns its own byte buffer. The old
blocking iterator never had this; select made it possible and nothing
tested it, because the fake pipe never wrote anything.

Same file: a rebind left the old aseqdump running. Harmless while rebinds
only happened after the stream ended -- and the previous commit made them
ordinary, since the driver restarted six times that night. The
steady-state check now also reuses one 'aseqdump -l' for both questions.

RUNNING IS NOT LISTENING. gig_record resolves its sink once, at start, and
gig-up starts units BEFORE it opens Ardour -- so in the flow that is
actually pressed it resolves while Ardour is closed, falls back to the
default sink, and if the laptop speakers are then cut (correct on stage)
the black box records a sink nothing reaches. 'gig_record.sh check' asks
whether what it HEARS is still where Master GOES, read off the running
process rather than recomputed; a new ADVISE probe runs it and skips when
Ardour is closed. "Not running" stays the other probe's question.

The master_sink awk now has tests, including the state the gig was in with
Master linked to two sinks at once -- it takes the first, which is a real
choice and not a good one, so the script names the sink it picked and the
test makes the ambiguity visible instead of silent.
parent e85dc610
...@@ -27,11 +27,16 @@ Each line pays off a `TODO_GIG` "NOT TONIGHT" entry or a loss measured in ...@@ -27,11 +27,16 @@ Each line pays off a `TODO_GIG` "NOT TONIGHT" entry or a loss measured in
laptop card while Master was hand-linked to the UMC. laptop card while Master was hand-linked to the UMC.
- [x] **5. Tableau de bord.** The Bridge should render `check-gig.py --json`, - [x] **5. Tableau de bord.** The Bridge should render `check-gig.py --json`,
not grow a bespoke "armed" tile. One source of truth. not grow a bespoke "armed" tile. One source of truth.
- [ ] **6. Ardour's OSC arm lens is broken** — `arm:false roll:false` for 76 - [ ] **6. `recordings/` has no retention.** The black box writes ~72 MB/hour of
opus, gitignored. A rehearsal week is >5 GB and the >500 MB rule bites
after one. Decide the policy — keep N days, or prune once a take is in
`../Prod/` — before it is a surprise. Nothing deletes anything today,
which is the safe half of the problem.
- [ ] **7. Ardour's OSC arm lens is broken** — `arm:false roll:false` for 76
recorded minutes, `conflict:true` on every record. Find out whether the recorded minutes, `conflict:true` on every record. Find out whether the
OSC surface is even enabled before anything reads it. A REC reminder must OSC surface is even enabled before anything reads it. A REC reminder must
key on the FILES lens only. key on the FILES lens only.
- [ ] **7. Propose, PLN's call:** a `Mix` track inside Ardour (input = - [ ] **8. Propose, PLN's call:** a `Mix` track inside Ardour (input =
`Master/audio_out 1+2`, armed) so the mix lands in the same take at stem `Master/audio_out 1+2`, armed) so the mix lands in the same take at stem
grade. Solves "one orbit unarmed", not "forgot REC". grade. Solves "one orbit unarmed", not "forgot REC".
......
...@@ -410,6 +410,25 @@ print(" ".join(str(p) for p in m.setlist_tracks()))')"""), ...@@ -410,6 +410,25 @@ print(" ".join(str(p) for p in m.setlist_tracks()))')"""),
"--converge starts it; tools/gig_record.sh status says what it is " "--converge starts it; tools/gig_record.sh status says what it is "
"pointed at — it follows Ardour's Master, not the default sink)"), "pointed at — it follows Ardour's Master, not the default sink)"),
# RUNNING IS NOT LISTENING, and this is the honest half of the claim above.
# gig_record resolves its target ONCE, at start. `gig-up --converge` starts
# units and THEN opens Ardour, so in the flow PLN presses, the recorder
# resolves while Ardour is closed and falls back to the default sink. Do
# TODO_GIG step 4 afterwards — cut the laptop speakers, correct on stage —
# and the black box is recording a sink nothing reaches. Silence, in the one
# file whose whole job is to have caught the show.
#
# "not running" is the probe above's question, so it passes here: one probe,
# one question, one fix.
Probe("gig-record on target", shell(r"""
out=$(bash tools/gig_record.sh check 2>&1); rc=$?
[ "$rc" = 1 ] && exit 0 # not running — the probe above owns that
[ "$rc" = 0 ] || { echo "$out"; exit "$rc"; }"""),
kind=ADVISE, needs=("ardour",),
fix="systemctl --user restart gig-record # it resolves the sink at "
"START, so it must be cycled AFTER Ardour is up and Master is "
"wired where the room hears it"),
# ---- the empirical gate, opt-in ---------------------------------------- # # ---- the empirical gate, opt-in ---------------------------------------- #
# Last, loud, and only on request: it makes sound and takes ~45s per track. # Last, loud, and only on request: it makes sound and takes ~45s per track.
# Booting the set to confirm what a typecheck just told you is ten wasted # Booting the set to confirm what a typecheck just told you is ten wasted
......
...@@ -797,16 +797,33 @@ class MidiReader(threading.Thread): ...@@ -797,16 +797,33 @@ class MidiReader(threading.Thread):
# the board said anything, and the liveness question is asked on a # the board said anything, and the liveness question is asked on a
# wall clock. One `aseqdump -l` per UPGRADE_S, which is the same # wall clock. One `aseqdump -l` per UPGRADE_S, which is the same
# cost the old code intended to pay and did not. # cost the old code intended to pay and did not.
# READ THE RAW FD, NOT THE TEXT WRAPPER. `readline()` on a
# TextIOWrapper pulls a whole chunk off the fd and hands back ONE
# line; the rest sits in the wrapper's decoded buffer, where
# select() on the fd cannot see it. A fader sweep is 100+ lines a
# second arriving in bursts, so that combination would drain one
# line per fd event: the tail of a gesture would be logged only
# when the NEXT gesture arrived, stamped with the wrong second.
# The old blocking iterator did not have that problem; select plus
# readline would have introduced it. So own the buffer here.
last_check = time.time() last_check = time.time()
fd = self._proc.stdout.fileno()
sel = selectors.DefaultSelector() sel = selectors.DefaultSelector()
sel.register(self._proc.stdout, selectors.EVENT_READ) sel.register(fd, selectors.EVENT_READ)
buf = b""
try: try:
while not self._stop.is_set(): while not self._stop.is_set():
if sel.select(1.0): if sel.select(1.0):
line = self._proc.stdout.readline() try:
if not line: # aseqdump exited chunk = os.read(fd, 65536)
except OSError:
break
if not chunk: # aseqdump exited
break break
self.feed(line, time.time()) buf += chunk
while b"\n" in buf:
raw, buf = buf.split(b"\n", 1)
self.feed(raw.decode("utf-8", "replace"), time.time())
now = time.time() now = time.time()
if self.fixed or now - last_check < self.UPGRADE_S: if self.fixed or now - last_check < self.UPGRADE_S:
continue continue
...@@ -824,7 +841,14 @@ class MidiReader(threading.Thread): ...@@ -824,7 +841,14 @@ class MidiReader(threading.Thread):
addr, better = find_seq_port() addr, better = find_seq_port()
if preference_rank(better) < preference_rank(self.matched): if preference_rank(better) < preference_rank(self.matched):
break break
mine, _ = find_seq_port(self.matched) if self.matched else (None, None) # One `aseqdump -l` covers both questions whenever the best
# port IS ours, which is the steady state — only ask again
# when the listing named something else.
if better == self.matched:
mine = addr
else:
mine, _ = (find_seq_port(self.matched) if self.matched
else (None, None))
if mine is None or mine != self.port: if mine is None or mine != self.port:
break break
# 4. THE ONE THE GIG NEEDED. The port is there, under the # 4. THE ONE THE GIG NEEDED. The port is there, under the
...@@ -837,6 +861,13 @@ class MidiReader(threading.Thread): ...@@ -837,6 +861,13 @@ class MidiReader(threading.Thread):
finally: finally:
sel.close() sel.close()
self.alive = False self.alive = False
# A rebind used to leave the old aseqdump running: it was only ever
# reached when the stream had already ended, so nobody noticed. The
# reasons above make rebinds ORDINARY — PLN restarted the driver six
# times on the night this was written — and one orphan per restart
# is a leak that also keeps a stale subscription on the bus.
if self._proc and self._proc.poll() is None:
self._proc.terminate()
if self._stop.wait(3.0): if self._stop.wait(3.0):
return return
......
...@@ -7,7 +7,8 @@ ...@@ -7,7 +7,8 @@
# Usage: # Usage:
# gig_record.sh start start recording in the background (opus, hourly segments) # gig_record.sh start start recording in the background (opus, hourly segments)
# gig_record.sh stop stop the background recorder # gig_record.sh stop stop the background recorder
# gig_record.sh status is it running? which file? how big? # gig_record.sh status is it running? which file? how big? pointed where?
# gig_record.sh check is what it hears still where Ardour Master goes?
# gig_record.sh slice FILE START_SEC MINUTES OUT fast lossless-cut a test excerpt # gig_record.sh slice FILE START_SEC MINUTES OUT fast lossless-cut a test excerpt
set -euo pipefail set -euo pipefail
...@@ -92,9 +93,22 @@ cmd_stop() { ...@@ -92,9 +93,22 @@ cmd_stop() {
fi fi
} }
# What is the RUNNING recorder actually listening to? Read it off the process,
# never off what we would choose today — those are different answers and the
# difference is the whole failure mode below.
recording_target() {
local pid
[ -f "$PID_FILE" ] || return 1
pid="$(cat "$PID_FILE")"
kill -0 "$pid" 2>/dev/null || return 1
tr '\0' '\n' < "/proc/$pid/cmdline" 2>/dev/null | awk '
prev == "-i" { print; exit } { prev = $0 }'
}
cmd_status() { cmd_status() {
if [ -f "$PID_FILE" ] && kill -0 "$(cat "$PID_FILE")" 2>/dev/null; then if [ -f "$PID_FILE" ] && kill -0 "$(cat "$PID_FILE")" 2>/dev/null; then
echo "gig_record: RUNNING (pid $(cat "$PID_FILE"))" echo "gig_record: RUNNING (pid $(cat "$PID_FILE"))"
echo "gig_record: listening to $(recording_target)"
ls -lh "$OUT_DIR"/*.opus 2>/dev/null | tail -3 ls -lh "$OUT_DIR"/*.opus 2>/dev/null | tail -3
du -sh "$OUT_DIR" 2>/dev/null du -sh "$OUT_DIR" 2>/dev/null
else else
...@@ -102,6 +116,34 @@ cmd_status() { ...@@ -102,6 +116,34 @@ cmd_status() {
fi fi
} }
# THE TARGET IS RESOLVED ONCE, AT START — and that is a trap worth a check.
# `gig-up --converge` starts units and THEN opens Ardour (launchers.py splits
# them on MIDI contention), so in the flow PLN actually presses, this recorder
# resolves its target while Ardour is still closed: it falls back to the
# default sink. Do TODO_GIG step 4 afterwards — cut the laptop speakers, which
# is correct on stage — and the black box is then recording a sink nothing
# reaches. Silence, in the one file whose whole job is to have caught the show.
#
# So: ask whether what it is LISTENING to is still where Master GOES. Exit 3
# means re-point it, which is one restart.
cmd_check() {
local now want
now="$(recording_target)" || { echo "gig_record: not running" >&2; return 1; }
want="$(master_sink)"
if [ -z "$want" ]; then
echo "gig_record: listening to $now; Ardour Master is not in the graph, "\
"so there is nothing to compare against"
return 0
fi
if [ "$now" = "${want}.monitor" ]; then
echo "gig_record: listening to $now — this is where Master goes. OK"
return 0
fi
echo "gig_record: listening to $now but Ardour Master now goes to $want" >&2
echo "gig_record: MIS-POINTED — restart it (systemctl --user restart gig-record)" >&2
return 3
}
# Fast, lossless (stream-copy) excerpt for auditioning / slop-visuals testing. # Fast, lossless (stream-copy) excerpt for auditioning / slop-visuals testing.
cmd_slice() { cmd_slice() {
local file="$1" start="$2" minutes="$3" out="${4:-}" local file="$1" start="$2" minutes="$3" out="${4:-}"
...@@ -115,6 +157,7 @@ case "${1:-}" in ...@@ -115,6 +157,7 @@ case "${1:-}" in
start) cmd_start ;; start) cmd_start ;;
stop) cmd_stop ;; stop) cmd_stop ;;
status) cmd_status ;; status) cmd_status ;;
check) cmd_check ;;
slice) shift; cmd_slice "$@" ;; slice) shift; cmd_slice "$@" ;;
*) echo "usage: $0 {start|stop|status|slice FILE START_SEC MINUTES [OUT]}" >&2; exit 1 ;; *) echo "usage: $0 {start|stop|status|check|slice FILE START_SEC MINUTES [OUT]}" >&2; exit 1 ;;
esac esac
...@@ -408,3 +408,63 @@ def test_the_reader_rebinds_on_a_dead_subscription(monkeypatch): ...@@ -408,3 +408,63 @@ def test_the_reader_rebinds_on_a_dead_subscription(monkeypatch):
assert len(binds) >= 2, ( assert len(binds) >= 2, (
"a dead subscription did not trigger a rebind — the lens would log " "a dead subscription did not trigger a rebind — the lens would log "
"silence for a whole set again") "silence for a whole set again")
# ── a burst must not be drained one line per fd event ──────────────────────
# A fader sweep is 100+ lines a second and it arrives in bursts. `readline()`
# on a TextIOWrapper pulls a whole chunk off the fd and returns ONE line,
# leaving the rest in the wrapper's decoded buffer where select() on the fd
# cannot see it — so the tail of a gesture would be logged only when the NEXT
# gesture arrived, stamped with the wrong second. The reader owns its own byte
# buffer for exactly this, and the test writes a real burst to a real fd
# because a fake stdout is what let the bug through the first time.
class _Burst(_Pipe):
def write_lines(self, lines):
os.write(self._w, ("\n".join(lines) + "\n").encode())
def test_a_burst_is_drained_whole(monkeypatch):
pipe = _Burst()
monkeypatch.setattr(GL.subprocess, "Popen", lambda argv, **kw: pipe)
monkeypatch.setattr(GL, "find_seq_port",
lambda want=None: ("130:0", "ParVagues LCXL3"))
monkeypatch.setattr(GL, "subscription_alive", lambda port, pid: None)
monkeypatch.setattr(GL.MidiReader, "UPGRADE_S", 60.0)
r = GL.MidiReader()
t = threading.Thread(target=r.run, daemon=True)
t.start()
deadline = time.time() + 3.0
while time.time() < deadline and not r.alive:
time.sleep(0.02)
assert r.alive, "the reader never bound"
# One sweep of a knob, written in a single call — the real shape.
sweep = [f" 0:0 Control change 0, controller 84, value {v}"
for v in range(50)]
pipe.write_lines(sweep)
deadline = time.time() + 3.0
while time.time() < deadline and r.events < 50:
time.sleep(0.02)
got = r.events
r.stop()
t.join(timeout=3.0)
pipe.close()
assert got == 50, (
f"{got} of 50 lines read from one burst — the reader is draining one "
"line per fd event, so a sweep's tail lands in the wrong second")
def test_the_window_coalesced_the_burst_into_one_row():
"""Not a new behaviour, but it is what makes the count above safe to log:
50 events become one `cc` row carrying n/first/last/min/max."""
r = GL.MidiReader()
now = 1_000_000.0
for v in range(50):
r.feed(f" 0:0 Control change 0, controller 84, value {v}", now)
assert r.events == 50
assert len(r.cc) == 1
(_port, _ch, cc), e = next(iter(r.cc.items()))
assert cc == 84 and e["n"] == 50 and e["lo"] == 0 and e["hi"] == 49
"""Where does the black box listen? The awk that answers it, tested.
WHY (2026-09-25)
`gig_record.sh` used to record `$(pactl get-default-sink).monitor`. On
2026-09-24 that was the laptop card while Ardour's Master had been hand-linked
to the UMC, and the net would only have caught the show because TODO_GIG step 4
("cut the laptop speakers") was never ticked. Tick it — which is correct on
stage, the laptop's speakers are a feedback path — and the black box records
silence. That is the worst failure a black box has, because it looks like it is
working.
So it follows `ardour:Master/audio_out 1` through the live graph. That resolution
is one awk program, it is the whole point of the change, and a shell pipeline
with no test is exactly the kind of screw this repo refuses to add. The
listings below are `pw-link -l`'s real shape, including the case the gig
actually had: Master linked to TWO sinks at once.
"""
from __future__ import annotations
import os
import pathlib
import subprocess
import textwrap
TOOLS = pathlib.Path(__file__).resolve().parent.parent
SCRIPT = TOOLS / "gig_record.sh"
UMC = "alsa_output.usb-BEHRINGER_UMC202HD_192k_12345678-00.pro-output-0"
LAPTOP = "alsa_output.pci-0000_00_1f.3-platform-sof_sdw.HiFi__hw_sofsoundwire__sink"
def run_master_sink(tmp_path, listing: str) -> str:
"""Call the script's own master_sink() with a faked `pw-link -l`."""
fake = tmp_path / "pw-link"
fake.write_text("#!/usr/bin/env bash\ncat <<'EOF'\n" + listing + "\nEOF\n")
fake.chmod(0o755)
env = dict(os.environ, PATH=f"{tmp_path}:{os.environ['PATH']}")
r = subprocess.run(
["bash", "-c",
f'source <(sed -n "/^master_sink()/,/^}}/p" "{SCRIPT}"); master_sink'],
capture_output=True, text=True, env=env, timeout=20)
return r.stdout.strip()
ONLY_UMC = textwrap.dedent(f"""\
SuperCollider:out_1
|-> ardour:Tidal 01/audio_in 1
ardour:Master/audio_out 1
|-> {UMC}:playback_AUX0
ardour:Master/audio_out 2
|-> {UMC}:playback_AUX1""")
# The 2026-09-24 state: Master reached the UMC *and* the laptop, on purpose, so
# there was always something audible until the PA was confirmed.
BOTH = textwrap.dedent(f"""\
ardour:Master/audio_out 1
|-> {UMC}:playback_AUX0
|-> {LAPTOP}:playback_FL
ardour:Master/audio_out 2
|-> {UMC}:playback_AUX1""")
NO_ARDOUR = textwrap.dedent(f"""\
SuperCollider:out_1
|-> {LAPTOP}:playback_FL
SuperCollider:out_2
|-> {LAPTOP}:playback_FR""")
# Master present as a port but wired to nothing — Ardour open, PA not patched.
UNWIRED = "ardour:Master/audio_out 1\nardour:Master/audio_out 2\nSuperCollider:out_1\n |-> x:y"
def test_it_finds_the_interface_master_is_wired_to(tmp_path):
assert run_master_sink(tmp_path, ONLY_UMC) == UMC
def test_ardour_absent_yields_nothing_so_the_caller_falls_back(tmp_path):
assert run_master_sink(tmp_path, NO_ARDOUR) == ""
def test_master_present_but_unwired_yields_nothing(tmp_path):
assert run_master_sink(tmp_path, UNWIRED) == ""
def test_two_sinks_resolve_to_one_and_it_is_named(tmp_path):
"""The gig's own state. It takes the FIRST link, which is a real choice and
not a good one — so the script prints which sink it picked, and this test
exists to make the ambiguity visible rather than silent. If the ordering
ever matters more than this, the answer is GIG_RECORD_TARGET, not cleverer
awk."""
got = run_master_sink(tmp_path, BOTH)
assert got in (UMC, LAPTOP)
assert got, "two links must still produce an answer, never an empty string"
def test_the_parser_ignores_other_clients_master_ports(tmp_path):
"""`SuperCollider:out_1`'s links must not be mistaken for Master's."""
listing = textwrap.dedent(f"""\
SuperCollider:out_1
|-> {LAPTOP}:playback_FL
ardour:Master/audio_out 1
|-> {UMC}:playback_AUX0""")
assert run_master_sink(tmp_path, listing) == UMC
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment