gig_record: restart the recorder alone when its input clock breaks

After a suspend the pulse input stepped back ~2 h and ffmpeg never exited, so
nothing restarted it. A guard inside the recorder's own unit watches the log for
the Non-monotonic DTS line (zero in a healthy recorder) and restarts the
recorder, at most once per 120 s so it cannot flap.

tools/gig_record.sh

@@ -89,6 +89,49 @@ default_monitor() {
 # growing?" cannot tell a healthy recorder from a dead one. With it, the file grows every
 # second even in silence (~230 B/s), so mtime means something and at most ~1 s is at risk.
 
+# THE RECORDER'S INPUT CLOCK CAN BREAK UNDER IT (found 2026-10-13)
+# The laptop slept overnight; on wake the pulse input's timestamps stepped ~2 h BACKWARD and
+# ffmpeg never recovered: ~255,000 "Non-monotonic DTS" lines (one per packet), libopus
+# "Queue input is backward in time", segments reporting 100,000 s, and a 56 s hole in the
+# file at 10:00 that tripped the health alarm. The audio decoded, the clock under it was
+# wrong, and nothing restarted it because ffmpeg never exited. A healthy recorder logs ZERO
+# of these lines, so the symptom itself is the trigger: no resume detection, no clock maths,
+# and it also catches a break that has nothing to do with suspend.
+# (Tried and rejected, measured: -use_wallclock_as_timestamps 1 makes the STEADY state worse,
+# 140 "backward in time" lines in 20 s.)
+#
+# Owners repair, gig-log observes: this lives with the recorder, inside its unit, so it dies
+# with it. It restarts the recorder ALONE (never the sound), and at most once per
+# GUARD_COOLDOWN seconds so a cause that is not a one-off cannot make the black box flap;
+# past that it stays put and stays loud (the health check reports a stale segment).
+BAD_CLOCK='Non-monotonic DTS'
+GUARD_COOLDOWN="${GIG_RECORD_GUARD_COOLDOWN:-120}"
+GUARD_STAMP="$OUT_DIR/.guard-restart"
+
+restart_recorder() {
+    if [ -n "${INVOCATION_ID:-}" ]; then
+        systemctl --user --no-block restart gig-record.service
+    else
+        "${SELF:-$0}" stop; "${SELF:-$0}" start
+    fi
+}
+
+guard_clock() {
+    local pid="$1" last now
+    # process substitution, not a pipe: under pipefail grep -m1 closing early would turn
+    # tail's SIGPIPE into a failed pipeline (the same trap master_sink documents)
+    if grep -m1 -q "$BAD_CLOCK" < <(tail -n0 -F --pid="$pid" "$LOG_FILE" 2>/dev/null); then
+        now="$(date +%s)"; last="$(cat "$GUARD_STAMP" 2>/dev/null || echo 0)"
+        if [ $((now - last)) -lt "$GUARD_COOLDOWN" ]; then
+            echo "gig_record: input clock broken again within ${GUARD_COOLDOWN}s; NOT restarting, the recorder stays degraded" >>"$LOG_FILE"
+            return 0
+        fi
+        echo "$now" > "$GUARD_STAMP"
+        echo "gig_record: input clock stepped back ($BAD_CLOCK); restarting the recorder alone" >>"$LOG_FILE"
+        restart_recorder
+    fi
+}
+
 cmd_start() {
     if [ -f "$PID_FILE" ] && kill -0 "$(cat "$PID_FILE")" 2>/dev/null; then
         echo "gig_record: already running (pid $(cat "$PID_FILE"))"
@@ -104,7 +147,11 @@ cmd_start() {
         -segment_format_options flush_packets=1 \
         "$OUT_DIR/%Y-%m-%d_%H%M%S.opus" \
         >>"$LOG_FILE" 2>&1 &
-    echo $! > "$PID_FILE"
+    local ffpid=$!
+    echo "$ffpid" > "$PID_FILE"
+    disown
+    # the guard watches this one ffmpeg and ends when it does
+    SELF="${BASH_SOURCE[0]}" guard_clock "$ffpid" </dev/null >/dev/null 2>&1 &
     disown
     echo "gig_record: started (pid $(cat "$PID_FILE"))"
 }

tools/tests/test_gig_record_clock_guard.py

+"""The black box restarts itself when its input clock breaks, and only then.
+
+WHY (2026-10-13)
+After an overnight suspend the recorder's pulse input stepped ~2 h backward. ffmpeg never
+exited, so nothing restarted it: ~255,000 "Non-monotonic DTS" lines, segments reporting
+100,000 s, a 56 s hole in the file. A healthy recorder logs none of those lines, so the line
+is the trigger. These tests drive the script's own guard_clock() with a fake systemctl and a
+stand-in for the ffmpeg pid.
+"""
+from __future__ import annotations
+
+import os
+import pathlib
+import subprocess
+import time
+
+TOOLS = pathlib.Path(__file__).resolve().parent.parent
+SCRIPT = TOOLS / "gig_record.sh"
+BAD = "[segment @ 0x1] Non-monotonic DTS in output stream 0:0; previous: 9, current: 3; changing to 10."
+
+
+def rig(tmp_path, cooldown=120):
+    (tmp_path / "systemctl").write_text(f'#!/usr/bin/env bash\necho "$@" >> "{tmp_path}/calls"\n')
+    (tmp_path / "systemctl").chmod(0o755)
+    log = tmp_path / "recorder.log"
+    log.write_text("old noise\n" + BAD + "\n")          # history must not trigger anything
+    env = dict(os.environ, PATH=f"{tmp_path}:{os.environ['PATH']}", INVOCATION_ID="x",
+               GIG_RECORD_GUARD_COOLDOWN=str(cooldown))
+    prog = (f'OUT_DIR="{tmp_path}"; LOG_FILE="{log}"; '
+            f'source <(sed -n "/^BAD_CLOCK=/,/^GUARD_STAMP=/p;/^restart_recorder()/,/^}}/p;/^guard_clock()/,/^}}/p" "{SCRIPT}"); '
+            'guard_clock "$1"')
+    ffmpeg = subprocess.Popen(["sleep", "30"])           # the process the guard watches
+    guard = subprocess.Popen(["bash", "-c", prog, "guard", str(ffmpeg.pid)], env=env,
+                             stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
+    time.sleep(0.6)                                      # let tail attach before we write
+    return ffmpeg, guard, log, tmp_path / "calls"
+
+
+def append(log, line):
+    with open(log, "a") as f:
+        f.write(line + "\n")
+
+
+def test_a_broken_clock_restarts_the_recorder_alone(tmp_path):
+    ffmpeg, guard, log, calls = rig(tmp_path)
+    try:
+        append(log, BAD)
+        guard.wait(timeout=10)
+        assert calls.read_text().strip() == "--user --no-block restart gig-record.service"
+    finally:
+        ffmpeg.kill()
+
+
+def test_history_and_ordinary_lines_do_not_restart_it(tmp_path):
+    ffmpeg, guard, log, calls = rig(tmp_path)
+    try:
+        append(log, "[aist#0:0/pcm_s16le @ 0x1] Guessed Channel Layout: stereo")
+        time.sleep(1.2)
+        assert guard.poll() is None and not calls.exists()      # still watching, nothing done
+    finally:
+        ffmpeg.kill()
+        ffmpeg.wait()                  # reaped, as init does: a zombie still answers kill -0
+    guard.wait(timeout=10)                                       # and it ends with the recorder
+    assert not calls.exists()
+
+
+def test_it_does_not_flap_inside_the_cooldown(tmp_path):
+    (tmp_path / ".guard-restart").write_text(f"{int(time.time())}\n")   # restarted a moment ago
+    ffmpeg, guard, log, calls = rig(tmp_path, cooldown=120)
+    try:
+        append(log, BAD)
+        guard.wait(timeout=10)
+        assert not calls.exists()
+        assert "NOT restarting" in log.read_text()
+    finally:
+        ffmpeg.kill()
+
+
+def test_start_launches_the_guard_on_the_ffmpeg_pid():
+    src = SCRIPT.read_text()
+    assert 'local ffpid=$!' in src and 'guard_clock "$ffpid"' in src
+    assert "-use_wallclock_as_timestamps" not in src.replace("(Tried and rejected", "").split("cmd_start()")[1]