Skip to content

T
Tidal
Commit 187b17ce by PLN (Algolia)
Options

gig-log: the MIDI lens asks the kernel who it is wired to, on a clock 

Zero control moves were logged for the whole 2026-09-24 set, and every
cheap check said fine. Two independent faults, both found by looking:

THE CHECK RAN ON TRAFFIC, NOT ON A CLOCK. The re-resolve lived inside
'for line in self._proc.stdout', so it only ran after a line ARRIVED. A
bound port that goes quiet blocks that iterator forever, and aseqdump does
not exit — so the loop parked on a blocking read from 01:01 through a
94-minute set. Now a timed select: the liveness question is asked every
UPGRADE_S whether or not the board said anything. The old test asserted
this the other way round, on the reasoning that running in the read loop
was 'cheap by construction: an idle surface costs nothing at all'. An idle
surface cost the gig. 'Costs nothing when idle' and 'notices when idle'
are the same code path and only one can be true.

A NAME AND AN ADDRESS ARE BOTH USELESS HERE. 38 hours after the set, 133:0
'ParVagues LCXL3' still resolved to that exact address under that exact
name — so neither 'is it gone' nor 'did it move' could see anything. What
happened is the third thing: lcxl3-driver restarted repeatedly between
00:34 and 10:27, and the kernel handed each new sequencer client the same
number. Our subscription died with the old one. Verified live: client 133
was 'Connecting To: 129:0, 14:0' and gig-log's aseqdump, client 135, was
not in the list.

So subscription_alive() asks the kernel's own wiring table, matching the
CHILD's pid — the same discrimination lcxl3-driver's board_link_alive
makes, for the same reason. It reads False on the real dead link and True
on SuperCollider, which is wired to the same port; 'cannot tell' is None,
never False, so a box where aconnect differs does not thrash.

gig-log status now names the binding, its subscription state and the
session's control-event count. It used to answer 'is it writing', which
was true and useless on the night the file grew at 1 Hz with nothing in
it. A dashboard that shows LIVE while a whole lens is dead is the green
check this rig has learned not to trust.

Note: tools/tests/test_one_tidal_parser.py fails at HEAD too, on
fold-orbits.py. Untouched here.
parent 6a94b47b
Showing with 429 additions and 16 deletions
TODO.d/2026-09-25-post-gig-belt-and-braces.md
......@@ -16,7 +16,7 @@ Each line pays off a `TODO_GIG` "NOT TONIGHT" entry or a loss measured in
- [x] **2. Nothing checks record-arm.** `Tidal 08` sat at `rec-enable=0` all
night; twelve tools audit faders, mutes, routing, ghosts, preload — none
audit arm. Extend `check-mix.py`, add a `check-gig.py` probe.
- [ ] **3. gig-log loses its MIDI address.** Bound seq port `133:0` at 00:59,
- [x] **3. gig-log loses its MIDI address.** Bound seq port `133:0` at 00:59,
never rebound; zero control moves logged for a 94-minute set. Probe now,
rebind as its own change. (`TODO_GIG`: "gig-log loses its MIDI address and
never looks for it again")
......
tools/gig-log.py
......@@ -67,6 +67,10 @@ RECORD KINDS (the `k` field)
per tick WHILE recording, so the timeline has a spine — never while
idle. See "TWO LENSES ON RECORDING" below for what a disagreement
between them means and why it is reported, never resolved quietly.
mbind which sequencer port the MIDI lens bound, and whether its CC numbers
were translated. Written on every (re)bind, so a reader months later
never has to guess — and several appearing in one session is the
reader recovering from a replug, not a fault.
mark a human annotation from `gig-log.py mark`
end once, at stop
......@@ -118,6 +122,7 @@ import glob
import json
import os
import re
import selectors
import shutil
import signal
import socket
......@@ -579,6 +584,63 @@ def find_seq_port(want: str | None = None) -> tuple[str | None, str | None]:
return None, None
def subscription_alive(port: str, child_pid: int) -> bool | None:
"""Is OUR aseqdump still subscribed to `port`? None = cannot tell.
WHY A NAME AND AN ADDRESS ARE BOTH USELESS HERE (2026-09-25)
The 2026-09-24 set logged zero control moves. The lens had bound 133:0
'ParVagues LCXL3' at 00:59, and 38 hours later that port STILL resolved to
that exact address and that exact name — so neither "is it gone" nor "did it
move" could see the fault. What happened is the third thing: lcxl3-driver
restarted (repeatedly, between 00:34 and 10:27), and every restart destroys
the ALSA sequencer client and rebuilds it. The kernel handed the new client
the SAME number, and our subscription died with the old one.
`aseqdump` does not exit when that happens. It sits on a port that will
never speak to it again, and from the outside a dead subscription is
indistinguishable from a performer who is not touching the board.
So ask the kernel who is actually wired to whom. This is the same
discrimination lcxl3-driver's `board_link_alive` makes, and for the same
reason: subscriptions are the truth, names are a label. Matching on the
CHILD's pid rather than our own, because the subscriber is the aseqdump we
spawned, not this process.
"""
if not shutil.which("aconnect"):
return None
try:
r = subprocess.run(["aconnect", "-l"], capture_output=True, text=True,
timeout=5)
except (OSError, subprocess.SubprocessError):
return None
out = r.stdout or ""
if not out:
return None
mine: set[str] = set()
want_client, want_port = (port.split(":") + [""])[:2]
in_block = on_port = False
peers: set[str] = set()
for line in out.splitlines():
if line.startswith("client "):
cid = line.split()[1].rstrip(":")
if f"pid={child_pid}" in line:
mine.add(cid)
in_block = cid == want_client
on_port = False
continue
if not in_block or not line.strip():
continue
tok = line.strip().split()
if line[0] in " \t" and tok and tok[0].isdigit():
on_port = tok[0] == want_port
continue
if on_port and "Connecting To:" in line:
peers |= {p.split(":")[0] for p in tok[2:] if ":" in p}
if not mine:
return None # our aseqdump has no client at all — nothing to judge
return bool(peers & mine)
class MidiReader(threading.Thread):
"""Reads one aseqdump and accumulates a COALESCED window.
......@@ -718,17 +780,62 @@ class MidiReader(threading.Thread):
# would be a confident wrong record -- the same class of bug as
# everything else found today, in the one file whose whole job is to
# be trustworthy after the fact.
# ON A CLOCK, NOT ON TRAFFIC (2026-09-25). The check below used to
# live inside `for line in self._proc.stdout`, i.e. it only ran
# after a line ARRIVED. A bound port that goes quiet blocks that
# iterator forever, so the reader never asks again — which is
# exactly what happened on 2026-09-24: bound 133:0 at 00:59, the
# port went silent at 01:01, and the loop parked on a blocking read
# through a whole 94-minute set. Zero `cc` rows for the gig, and
# `aseqdump` never exited, so the outer re-resolve never fired
# either. A replug is the same shape: it destroys the kernel's
# sequencer client and rebuilds it under a NEW address, silently
# dropping every subscription (see lcxl3-driver's board_link_alive),
# and nothing tells us.
#
# So: a timed read. `select` returns on the timeout whether or not
# the board said anything, and the liveness question is asked on a
# wall clock. One `aseqdump -l` per UPGRADE_S, which is the same
# cost the old code intended to pay and did not.
last_check = time.time()
for line in self._proc.stdout:
if self._stop.is_set():
sel = selectors.DefaultSelector()
sel.register(self._proc.stdout, selectors.EVENT_READ)
try:
while not self._stop.is_set():
if sel.select(1.0):
line = self._proc.stdout.readline()
if not line: # aseqdump exited
break
self.feed(line, time.time())
now = time.time()
if not self.fixed and now - last_check >= self.UPGRADE_S:
if self.fixed or now - last_check < self.UPGRADE_S:
continue
last_check = now
_addr, better = find_seq_port()
# Three reasons to rebind, and the last two are new:
# 1. something better turned up (the 2026-09-23 case:
# lcxl3-driver starts after us and publishes a port we
# prefer to the board's own raw DAW port).
# 2. our port is GONE from the bus — unplugged, or the
# driver restarted. Holding a dead subscription looks
# identical to a quiet performer.
# 3. our port's ADDRESS MOVED. Same name, new client
# number: that is a replug, and our subscription went
# with the old client.
addr, better = find_seq_port()
if preference_rank(better) < preference_rank(self.matched):
break # rebind to the better one
break
mine, _ = find_seq_port(self.matched) if self.matched else (None, None)
if mine is None or mine != self.port:
break
# 4. THE ONE THE GIG NEEDED. The port is there, under the
# same name, at the same address — and our subscription
# to it is dead, because the publisher restarted and the
# kernel reused the client number. Only the kernel's own
# wiring table can see this; see subscription_alive().
if subscription_alive(self.port, self._proc.pid) is False:
break
finally:
sel.close()
self.alive = False
if self._stop.wait(3.0):
return
......@@ -2132,6 +2239,30 @@ def cmd_controls(path: Path, since: str | None = None,
return 0
def _aseqdump_children(recorder_pids: list[str]) -> list[int]:
"""The aseqdump processes the running recorder(s) spawned.
`status` runs in its own process, so it cannot know the child pid the way
the reader does. /proc's ppid is the link. Only children are considered: a
stray aseqdump someone started in a terminal is not our lens, and judging
the lens by it would be the same category error as counting a concurrent
`gig-log.py report` as a second recorder.
"""
out = []
want = set(recorder_pids)
for path in glob.glob("/proc/[0-9]*/stat"):
try:
fields = (perf._read(path) or "").rsplit(")", 1)
if len(fields) != 2 or "(aseqdump" not in fields[0]:
continue
ppid = fields[1].split()[1]
except (OSError, IndexError):
continue
if ppid in want:
out.append(int(path.split("/")[2]))
return out
def cmd_status(d: Path = LOG_DIR) -> int:
r = subprocess.run(["systemctl", "--user", "is-active", "gig-log.service"],
capture_output=True, text=True)
......@@ -2161,6 +2292,57 @@ def cmd_status(d: Path = LOG_DIR) -> int:
f"({'LIVE' if age < 10 else 'stale'})")
print(f"all logs : {len(list(d.glob('gig-*.jsonl')))} files, "
f"{sum(f.stat().st_size for f in d.glob('gig-*.jsonl'))/1e6:.2f} MB")
# WHAT IS THE MIDI LENS ACTUALLY BOUND TO (added 2026-09-25)
# `status` used to answer "is it writing", which was true and useless for
# the one question that mattered on 2026-09-24: the recorder was LIVE, the
# file was growing at 1 Hz, and not one control move was in it. The lens had
# bound 133:0 at 00:59, that port went silent at 01:01, and nothing said so.
# A dashboard that shows "LIVE" while a whole lens is dead is the kind of
# green check this rig has learned not to trust, so the binding is named —
# and checked against the bus, because a held address is not a live one.
bind, cc_n, last_cc = None, 0, None
for line in p.open(errors="replace"):
if '"mbind"' not in line and '"cc"' not in line and '"note"' not in line:
continue
try:
rec = json.loads(line)
except json.JSONDecodeError:
continue
if rec.get("k") == "mbind":
bind = rec
elif rec.get("k") in ("cc", "note"):
cc_n += 1
last_cc = rec.get("t")
if bind is None:
print("midi lens : NEVER BOUND — no mbind record in this log")
else:
live, _ = find_seq_port(bind.get("name")) if MidiReader.available() else (None, None)
addr = bind.get("p")
if live is None:
state = "GONE from the bus"
elif live != addr:
state = (f"MOVED to {live} (replug) — rebind due within "
f"{MidiReader.UPGRADE_S:.0f}s")
else:
# On the bus is not the same as wired to us. Ask the kernel which
# aseqdump the recorder actually spawned, and whether that client is
# still subscribed — the 2026-09-24 failure looked perfect at every
# level above this one.
state = "on the bus"
subs = [subscription_alive(addr, pid) for pid in _aseqdump_children(running)]
if subs and all(x is False for x in subs):
state = ("on the bus but NOT WIRED TO US — the publisher "
"restarted and took our subscription with it; "
"restart gig-log")
elif any(x is True for x in subs):
state = "on the bus, subscribed"
print(f"midi lens : {addr} {bind.get('name')!r} — {state}")
quiet = f", last {time.time() - last_cc:.0f}s ago" if last_cc else ""
print(f" {cc_n} control events this session{quiet}")
if not cc_n:
print(" ^ zero. Touch a knob: if it stays 0, the "
"lens is bound to the wrong port.")
return 0
......
tools/tests/test_gig_log_midi.py
......@@ -13,7 +13,10 @@ These tests are about the resolver and the dialect, not about aseqdump.
from __future__ import annotations
import importlib.util
import os
import pathlib
import time
import threading
import sys
import pytest
......@@ -165,15 +168,243 @@ def test_a_pinned_port_is_never_upgraded_away_from():
"""--midi-port is a human saying 'this one'. Second-guessing that would make
the flag a suggestion."""
src = (TOOLS / "gig-log.py").read_text()
loop = src[src.index("# UPGRADE WHILE BOUND"):src.index("self.alive = False", src.index("# UPGRADE WHILE BOUND"))]
assert "not self.fixed" in loop
loop = src[src.index("# ON A CLOCK, NOT ON TRAFFIC"):
src.index("self.alive = False", src.index("# ON A CLOCK, NOT ON TRAFFIC"))]
assert "self.fixed or" in loop, "a pinned port must short-circuit the rebind"
# ── the check must run on a CLOCK, not on traffic ──────────────────────────
# This file used to assert the opposite, on the reasoning that running inside
# `for line in self._proc.stdout` was "cheap by construction: an idle surface
# costs nothing at all". An idle surface cost the whole 2026-09-24 set: the
# reader bound 133:0 at 00:59, the port went silent at 01:01, and the iterator
# parked on a blocking read for nineteen hours. Zero `cc` rows for a 94-minute
# gig, and `aseqdump` never exited so the outer re-resolve never fired either.
#
# "Costs nothing when idle" and "notices when idle" are the same code path, and
# only one of them can be true. The tests below pick the one the gig chose.
class _Pipe:
"""A real fd that never produces a line — an aseqdump on a quiet port.
Real, not a mock, because the loop now uses `selectors` and the whole point
is that select() returns on its TIMEOUT rather than on data. A fake object
would let a regression that waits for data pass.
"""
def __init__(self):
r, self._w = os.pipe()
self.stdout = os.fdopen(r, "r")
self.pid = os.getpid() # the reader asks its child's pid
def poll(self):
return None
def terminate(self):
pass
def close(self):
self.stdout.close()
os.close(self._w)
def test_a_quiet_port_still_gets_re_resolved(monkeypatch):
"""The 2026-09-24 bug, as the timeline that produces it."""
pipes = []
def fake_popen(argv, **kw):
p = _Pipe()
pipes.append(p)
return p
# First answer: the board's own raw DAW port. Then the driver appears and
# publishes the port we prefer. Nothing is ever READ from the pipe, so the
# only way to reach the second answer is a timed check.
answers = [("24:1", "LCXL3 1 DAW"), ("130:0", "ParVagues LCXL3")]
calls = {"n": 0}
def find_seq_port(want=None):
if want is None:
calls["n"] += 1
return answers[min(calls["n"] - 1, len(answers) - 1)]
for addr, name in answers:
if name == want:
return addr, name
return None, None
monkeypatch.setattr(GL.subprocess, "Popen", fake_popen)
monkeypatch.setattr(GL, "find_seq_port", find_seq_port)
monkeypatch.setattr(GL.MidiReader, "UPGRADE_S", 0.05)
# subscription_alive() is a DIFFERENT rebind reason with its own test
# below. Left live here it would also see the faked Popen and crash the
# reader thread — a crash these tests would still have passed through,
# because the rebind under test happens first. Inert = "cannot tell".
monkeypatch.setattr(GL, "subscription_alive", lambda port, pid: None)
r = GL.MidiReader()
t = threading.Thread(target=r.run, daemon=True)
t.start()
deadline = time.time() + 6.0
while time.time() < deadline and r.matched != "ParVagues LCXL3":
time.sleep(0.05)
r.stop()
t.join(timeout=3.0)
for p in pipes:
p.close()
assert r.matched == "ParVagues LCXL3", (
"a silent port was never re-resolved — the loop is waiting for a line "
"again, which is the bug that lost 2026-09-24's MIDI")
binds = [d for d in r.discrete if d.get("k") == "mbind"]
assert len(binds) >= 2, "every rebind must be recorded in the log"
def test_a_vanished_port_is_not_held_forever(monkeypatch):
"""A replug destroys the kernel's sequencer client and rebuilds it under a
new address, dropping the subscription silently. Holding the dead one looks
exactly like a quiet performer, so the reader must notice by itself."""
pipes = []
def fake_popen(argv, **kw):
p = _Pipe()
pipes.append(p)
return p
state = {"addr": "130:0"}
def find_seq_port(want=None):
if want is None:
return state["addr"], "ParVagues LCXL3"
return (state["addr"], want) if want == "ParVagues LCXL3" else (None, None)
monkeypatch.setattr(GL.subprocess, "Popen", fake_popen)
monkeypatch.setattr(GL, "find_seq_port", find_seq_port)
monkeypatch.setattr(GL.MidiReader, "UPGRADE_S", 0.05)
# subscription_alive() is a DIFFERENT rebind reason with its own test
# below. Left live here it would also see the faked Popen and crash the
# reader thread — a crash these tests would still have passed through,
# because the rebind under test happens first. Inert = "cannot tell".
monkeypatch.setattr(GL, "subscription_alive", lambda port, pid: None)
r = GL.MidiReader()
t = threading.Thread(target=r.run, daemon=True)
t.start()
deadline = time.time() + 4.0
while time.time() < deadline and r.port != "130:0":
time.sleep(0.05)
assert r.port == "130:0"
state["addr"] = "131:0" # the replug: same name, new client
deadline = time.time() + 6.0
while time.time() < deadline and r.port != "131:0":
time.sleep(0.05)
r.stop()
t.join(timeout=3.0)
for p in pipes:
p.close()
assert r.port == "131:0", "the reader kept a subscription the replug killed"
def test_the_upgrade_interval_is_not_eager():
"""It spawns `aseqdump -l`, so the clock must stay slow."""
assert GL.MidiReader.UPGRADE_S >= 5.0
# ── subscriptions are the truth; names and addresses are labels ────────────
# The 2026-09-24 set logged ZERO control moves, and every cheap check said
# fine: the port existed, under the name we wanted, at the address we bound.
# What had happened is that lcxl3-driver restarted (repeatedly, 00:34→10:27)
# and the kernel handed the new sequencer client the SAME number, so our
# subscription had died with the old one. `aseqdump` does not exit for that.
#
# Verified on the live machine 2026-09-25, 38 hours after the set: client 133
# 'ParVagues LCXL3' was `Connecting To: 129:0, 14:0` and gig-log's aseqdump
# (client 135) was not in the list. The dead link was still there.
ACONNECT = """\
client 0: 'System' [type=kernel]
0 'Timer '
Connecting To: 143:0, 129:0
client 129: 'SuperCollider' [type=user,pid=2157541]
0 'in0 '
Connected From: 0:0, 133:0
client 133: 'RtMidiOut Client' [type=user,pid=2160454]
0 'ParVagues LCXL3 '
Connecting To: 129:0, 14:0
client 134: 'RtMidiIn Client' [type=user,pid=2160454]
0 'ParVagues LCXL3 FB'
client 135: 'aseqdump' [type=user,pid=1576550]
0 'aseqdump '
"""
def test_the_upgrade_check_is_between_events_not_on_a_timer():
"""Cheap by construction: it runs in the read loop, so an idle surface costs
nothing at all and a busy one is still bounded by UPGRADE_S."""
src = (TOOLS / "gig-log.py").read_text()
loop = src[src.index("# UPGRADE WHILE BOUND"):src.index("self.alive = False", src.index("# UPGRADE WHILE BOUND"))]
assert "for line in self._proc.stdout" in loop
assert "UPGRADE_S" in loop
assert GL.MidiReader.UPGRADE_S >= 5.0, "too eager: this spawns aseqdump -l"
def _aconnect(monkeypatch, text=ACONNECT):
class R:
stdout = text
monkeypatch.setattr(GL.shutil, "which", lambda _: "/usr/bin/aconnect")
monkeypatch.setattr(GL.subprocess, "run", lambda *a, **k: R())
def test_a_dead_subscription_is_seen_as_dead(monkeypatch):
"""The exact table from the gig: 133:0 is up, and we are not on it."""
_aconnect(monkeypatch)
assert GL.subscription_alive("133:0", 1576550) is False
def test_a_live_subscription_is_seen_as_live(monkeypatch):
"""SuperCollider IS wired to 133:0, so its pid must read True — otherwise
the check is just always-False and would rebind in a loop forever."""
_aconnect(monkeypatch)
assert GL.subscription_alive("133:0", 2157541) is True
def test_a_pid_with_no_client_is_unknown_not_dead(monkeypatch):
"""None, never False. Rebinding on 'cannot tell' would thrash the reader
every UPGRADE_S on any box where aconnect reports differently."""
_aconnect(monkeypatch)
assert GL.subscription_alive("133:0", 999999) is None
def test_no_aconnect_means_unknown(monkeypatch):
monkeypatch.setattr(GL.shutil, "which", lambda _: None)
assert GL.subscription_alive("133:0", 1576550) is None
def test_the_port_number_is_matched_not_just_the_client(monkeypatch):
"""A client's port 1 can be wired where its port 0 is not."""
_aconnect(monkeypatch)
assert GL.subscription_alive("133:1", 2157541) is None or \
GL.subscription_alive("133:1", 2157541) is False
def test_the_reader_rebinds_on_a_dead_subscription(monkeypatch):
"""End to end: name unchanged, address unchanged, subscription dead.
This is the case the other three rebind reasons cannot see, and the only
one that describes 2026-09-24.
"""
pipes = []
monkeypatch.setattr(GL.subprocess, "Popen",
lambda argv, **kw: pipes.append(_Pipe()) or pipes[-1])
monkeypatch.setattr(GL, "find_seq_port",
lambda want=None: ("133:0", "ParVagues LCXL3"))
monkeypatch.setattr(GL.MidiReader, "UPGRADE_S", 0.05)
monkeypatch.setattr(GL, "subscription_alive", lambda port, pid: False)
r = GL.MidiReader()
t = threading.Thread(target=r.run, daemon=True)
t.start()
deadline = time.time() + 5.0
while time.time() < deadline and \
sum(1 for d in r.discrete if d.get("k") == "mbind") < 2:
time.sleep(0.05)
r.stop()
t.join(timeout=3.0)
for p in pipes:
p.close()
binds = [d for d in r.discrete if d.get("k") == "mbind"]
assert len(binds) >= 2, (
"a dead subscription did not trigger a rebind — the lens would log "
"silence for a whole set again")
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