Commit b9564095 by PLN (Algolia)

fix(watchdog): a boot is not a death, and the rig only gets three starts

parvagues-sc.service is Type=simple, so systemd calls it active the instant
sclang execs -- but scsynth is sclang's child and appears ~8s later. The loop
acted at MISSES_TO_ACT*POLL_SECS = 6s, so every healthy start earned a restart:

  23:17:12 scsynth GONE (3 polls) while parvagues-sc.service is active
           -- restarting (0 prior in window)
  23:17:21 scsynth up after 8s

'0 prior in window' on a start where nothing was wrong. The restart was not the
damage; the rate limit was. Each clean start spent two of systemd's
StartLimitBurst=3, so a second start inside StartLimitIntervalUSec=5min hit the
limit and left the unit failed/start-limit-hit -- refusing to start at all until
reset-failed. On stage that is indistinguishable from a dead rig.

BOOT_GRACE_SECS=30, measured from the unit's own ActiveEnterTimestamp, and it
says 'holding off' in the journal rather than waiting silently. Misses keep
counting through the grace so an expiring grace acts at once. The per-poll
is-active became one show returning both fields: 7.0ms -> 9.4ms, +0.12% of a
core, measured not assumed.

Also cures the watchdog of the same pgrep -x that cost protect a tenth of a
core -- 52.9ms per poll while SC is up (3.0% of a core WHILE PLAYING) against
20.8ms for one stateless /proc/*/comm pass, zero forks. Duplicated from
parvagues-protect rather than shared: that script is copied to /usr/local/bin
and runs as root, so it must not source anything from a user-writable repo.

rig-doctor's check_protect now asks whether protection WORKS: the running
daemon's live CapEff from /proc must include cap_dac_override, and the daemon's
own --check must pass. It was green all through the day the guard could not
write a single oom_score_adj, because it tested that two files existed.

Verified end to end on the rig: protect caught pids created 9min after it
started (oom:200->-1000 on sclang[257669]), and the watchdog held off at 6s and
spent none of the rate limit. Suite 11/11 incl. a new slow-boot regression case;
rig-doctor 46 checks, 0 fail.
parent a828d5f0
...@@ -4,6 +4,61 @@ Sprint entries, newest first. Player-facing: what changed about *playing*, not ...@@ -4,6 +4,61 @@ Sprint entries, newest first. Player-facing: what changed about *playing*, not
about the code. Task IDs reference the L'Armada board; `n/a` where the work was about the code. Task IDs reference the L'Armada board; `n/a` where the work was
unplanned (which, on a gig night, is most of it). unplanned (which, on a gig night, is most of it).
## Sprint 5 — 2026-09-06 (latest) · nothing restarts a boot that is going fine
Sprint 4 measured the guard and found it fidgeting. Measuring it also turned up
the thing that could actually end a set: the recovery watchdog was restarting
SuperDirt every single time it started normally, and spending the rig's three
allowed starts to do it.
### Fixed
- **Starting SuperDirt no longer restarts it** (n/a). `parvagues-sc` reports
`active` the instant sclang execs; scsynth is its child and appears ~8 s
later; the watchdog gave up waiting at 6 s. So every clean start earned a
restart — and each start therefore spent two of systemd's three allowed
starts, meaning a second start inside five minutes left the rig
`failed (start-limit-hit)`, refusing to come up at all until
`reset-failed`. On stage that is indistinguishable from dead, and the
watchdog was the cause. It now holds off for `BOOT_GRACE_SECS=30` measured
from the unit's own `ActiveEnterTimestamp`, and says so in the journal
instead of waiting silently. Costs no extra fork: the per-poll `is-active`
became one `show` returning both fields.
- **`rig-doctor` asks whether protection works, not whether its files exist**
(n/a). `parvagues-protect: PASS` was green all through the day the daemon
could not write a single `oom_score_adj` — it tested for a `bin` and a
`unit`, the one pair that stayed true. It now also reads the running
daemon's live `CapEff` from `/proc` and asserts `cap_dac_override`, and
shells out to the daemon's own `--check` for per-process truth.
- **The watchdog stops paying for `pgrep` too** (n/a). Measuring the boot-grace
fix showed the watchdog carrying the same 59 ms-per-call `pgrep -x` protect
had just been cured of, on every poll while SuperDirt is up — 3.0% of a core
*while playing*. Same cure: one stateless pass over `/proc/*/comm`, 20.8 ms,
no forks. Duplicated rather than shared, because the protect script is copied
to `/usr/local/bin` and run as root and must not source anything out of a
user-writable repo.
### Added
- **A regression test for the boot grace** (n/a) — case 6 of
`tools/tests/test-sc-watchdog.sh`: a fake unit that takes 10 s to produce its
server, asserting the watchdog neither restarts it nor spends any of its
rate-limit budget. The four older cases now pin `SCWD_BOOT_GRACE=0`, because
they are about a server that *died*, and a grace would have quietly turned
them into tests of their own timeout arithmetic.
### Doctrine
- **A test must not grep for a word its own good news contains.** The grace
message first read "waiting, not restarting"; the regression test looked for
`restarting` as evidence of failure, and so failed on the exact log line
proving it had worked. It now matches `GONE (`, which appears only where the
watchdog decides to act, and the message says "holding off". Third costume
tonight of the same lesson: presence of a string is not presence of a fact.
- **Check the scope of the helper, not just its name.** `check_protect`'s
first draft called `_unit_active()`, which is `--user`-scoped and appends
`.service` itself — it would have reported a perfectly healthy *system* unit
as inactive. Exactly the shape of the pyenv-vs-`/usr/bin/python3` miss that
started this whole audit.
## Sprint 4 — 2026-09-06 (later) · the guard stops charging rent ## Sprint 4 — 2026-09-06 (later) · the guard stops charging rent
Sprint 3's guard finally guarded. Then we asked what it cost to do so, and the Sprint 3's guard finally guarded. Then we asked what it cost to do so, and the
......
...@@ -2158,8 +2158,30 @@ scattered through this file resolve locally. ...@@ -2158,8 +2158,30 @@ scattered through this file resolve locally.
contains "ardour" must not) and against `chrt -p`/`cat` on live scsynth+sclang. contains "ardour" must not) and against `chrt -p`/`cat` on live scsynth+sclang.
**Still to do: `sudo tools/install-protect.sh`** — the repo has the fix, the **Still to do: `sudo tools/install-protect.sh`** — the repo has the fix, the
running daemon does not. running daemon does not.
- **`sc-watchdog` restarts SuperDirt on every clean start, and two starts in - ~~**`sc-watchdog` restarts SuperDirt on every clean start, and two starts in
five minutes leave the rig `failed` and unstartable.** Found 2026-09-06 by five minutes leave the rig `failed` and unstartable.**~~ **FIXED 2026-09-06
(late).** `BOOT_GRACE_SECS=30` (injectable as `SCWD_BOOT_GRACE`): once the
miss threshold is reached, the loop asks how long the unit has actually been
active and holds off if that is under the grace. Misses keep counting during
it, so an expiring grace acts immediately rather than restarting a 6 s count.
Costs no extra fork — the per-poll `systemctl --user is-active` became one
`systemctl --user show -p ActiveState -p ActiveEnterTimestamp` — though not
nothing, measured rather than assumed: 7.0 ms → 9.4 ms, so +0.12% of a core.
The `date -d` parse runs only on the rare path where a restart was about to
happen.
**And while measuring that, the watchdog turned out to pay the same 59 ms
`pgrep -x` protect had just been cured of**, on every poll while SC is up —
3.0% of a core *while playing*. Replaced with `proc_alive()`, the same
stateless `/proc/*/comm` pass (52.9 ms → **20.8 ms**, zero forks,
differentially verified against `pgrep -x` on `scsynth`/`scsynthx`/
`myscsynth`/`sclang`/absent). Deliberately duplicated rather than shared:
parvagues-protect is copied to `/usr/local/bin` and runs as root, so it must
not source anything from a user-writable repo. Net: while playing 3.00% →
1.51%; while idle 0.35% → 0.47%, the `show` call being the price of the
correctness fix. Regression test added as case 6 in `tools/tests/test-sc-watchdog.sh`:
a fake unit that takes 10 s to produce its server, asserting no `GONE (` line
and no rate-limit spend. Suite: 11 passed, 0 failed.
Original diagnosis, kept because the shape recurs — found 2026-09-06 by
starting `parvagues-sc` for an unrelated test. `parvagues-sc.service` is starting `parvagues-sc` for an unrelated test. `parvagues-sc.service` is
`Type=simple`, so it reports `active` the instant `sclang` execs — but `Type=simple`, so it reports `active` the instant `sclang` execs — but
`scsynth` only appears ~8 s later, when SuperDirt boots the server. The `scsynth` only appears ~8 s later, when SuperDirt boots the server. The
...@@ -2195,7 +2217,32 @@ scattered through this file resolve locally. ...@@ -2195,7 +2217,32 @@ scattered through this file resolve locally.
free. Reconcile on change instead of on a timer and each drops to ~0.1%. free. Reconcile on change instead of on a timer and each drops to ~0.1%.
Total idle rig cost today: **~14.5% of a core with nothing playing**; protect's Total idle rig cost today: **~14.5% of a core with nothing playing**; protect's
fix takes that to ~5.8%, and these two would take it under 1%. fix takes that to ~5.8%, and these two would take it under 1%.
- **`rig-doctor`'s `parvagues-protect: PASS` tests for files, not for function.** **Probed 2026-09-06, so the next session starts from evidence, not hope:**
`pw-link -m -o` blocks, dumps current state prefixed `=`, and then emits on
change — that is the event source, confirmed by hand. (`pw-link -m -l`
printed nothing in 5 s; use `-o`/`-i`, not `-l`.) Shape:
`reconcile` once, then `pw-link -m -o | while read -r _; do <debounce>;
reconcile; done`, with `Restart=always` covering pw-link dying and a slow
fallback timer covering a missed event. **Deliberately NOT done tonight**:
both scripts are on the gig path and their own headers say a bug out here is
merely noisy only because the *boot* path was kept separate. Rewriting two
reconcile loops' control flow at midnight is how that stops being true.
This one wants its own session, with a `--dry-run` mode first, the way
sc-watchdog earned one.
- ~~**`rig-doctor`'s `parvagues-protect: PASS` tests for files, not for
function.**~~ **FIXED 2026-09-06 (late).** `check_protect()` now asks three
questions instead of one: are the files there, is the daemon *running* with
`cap_dac_override` in its live `CapEff` (read from `/proc/<MainPID>/status`,
no `capsh` dependency), and what does its own `--check` say about every
process that makes sound. Two rows now: `parvagues-protect` and
`parvagues-protect coverage`. Negative-tested against the live fault — pointed
at an unprivileged pid it reports FAIL and names the capability, and it
distinguishes "unverifiable" (pid gone → WARN) from "verified missing"
(`CapEff=0x0` → FAIL). One bug caught while writing it: the first version
used the `_unit_active()` helper, which is `--user`-scoped and appends
`.service` itself — it would have reported a healthy SYSTEM unit as inactive,
the same wrong-scope mistake as asking the wrong interpreter.
Original diagnosis: it tested for files, not function.
It checks that `bin` and `unit` exist — the exact pair that stayed true all It checks that `bin` and `unit` exist — the exact pair that stayed true all
through 2026-09-06 while the daemon could not write a single `oom_score_adj` through 2026-09-06 while the daemon could not write a single `oom_score_adj`
(missing `CAP_DAC_OVERRIDE`, see the install entry above). Should shell out to (missing `CAP_DAC_OVERRIDE`, see the install entry above). Should shell out to
......
...@@ -821,17 +821,101 @@ def check_perf_audio() -> None: ...@@ -821,17 +821,101 @@ def check_perf_audio() -> None:
f"modes without a password prompt", install_cmd) f"modes without a password prompt", install_cmd)
# CAP_DAC_OVERRIDE is capability number 1, so bit 1 of the capability bitmask.
# It is the one uid 0 needs in order to OPEN a file it does not own — and the one
# a hardened CapabilityBoundingSet drops without saying so.
_CAP_DAC_OVERRIDE = 1 << 1
def _daemon_caps(pid: str) -> int | None:
"""Effective capabilities of a running pid, from /proc. No capsh needed."""
try:
for line in Path(f"/proc/{pid}/status").read_text().splitlines():
if line.startswith("CapEff:"):
return int(line.split()[1], 16)
except (OSError, ValueError, IndexError):
return None
return None
def check_protect() -> None: def check_protect() -> None:
"""Ask whether protection is IN EFFECT, not whether its files are on disk.
2026-09-06: this check reported PASS all day while the daemon could not write
a single oom_score_adj. It tested that `bin` and `unit` existed — the one pair
that stayed true through a missing CAP_DAC_OVERRIDE, through an installer that
left a stale process running, and through a guard that had never protected
anything. Presence standing in for function, which is this rig's most
expensive recurring bug shape.
So: presence, then the live capability set of the running daemon, then the
daemon's own --check (read-only, unprivileged, exits non-zero when something
that makes sound is killable or non-realtime).
"""
binp = Path("/usr/local/bin/parvagues-protect") binp = Path("/usr/local/bin/parvagues-protect")
unitp = Path("/etc/systemd/system/parvagues-protect.service") unitp = Path("/etc/systemd/system/parvagues-protect.service")
bin_state, unit_state = path_state(binp), path_state(unitp) bin_state, unit_state = path_state(binp), path_state(unitp)
if bin_state == "present" and unit_state == "present": if not (bin_state == "present" and unit_state == "present"):
add("INSTALL SURFACE", "parvagues-protect", PASS, f"{binp} + {unitp}")
else:
add("INSTALL SURFACE", "parvagues-protect", FAIL, add("INSTALL SURFACE", "parvagues-protect", FAIL,
f"bin={bin_state}, unit={unit_state} — the OOM killer can take " f"bin={bin_state}, unit={unit_state} — the OOM killer can take "
f"scsynth under memory pressure", f"scsynth under memory pressure",
"sudo tools/install-protect.sh") "sudo tools/install-protect.sh")
return
# --- the daemon, as it is actually running -----------------------------
rc, pid, _ = run_cmd(["systemctl", "show", "-p", "MainPID", "--value",
"parvagues-protect.service"])
pid = pid.strip()
# NOT _unit_active(): that helper is for --user units and appends `.service`
# itself. parvagues-protect is a SYSTEM unit (it needs CAP_SYS_RESOURCE to
# lower oom_score_adj past the user manager's floor), so asking the user
# manager about it returns "inactive" for a daemon that is running fine —
# the same wrong-scope mistake as asking the wrong interpreter.
_, active_out, _ = run_cmd(["systemctl", "is-active",
"parvagues-protect.service"])
active = active_out.strip() or "?"
caps = _daemon_caps(pid) if pid and pid != "0" else None
if active != "active" or not pid or pid == "0":
add("INSTALL SURFACE", "parvagues-protect", FAIL,
f"{binp} + {unitp} present, but the daemon is {active!r} "
f"(MainPID={pid or 'none'}) — nothing is enforcing anything",
"sudo systemctl restart parvagues-protect.service")
elif caps is None:
add("INSTALL SURFACE", "parvagues-protect", WARN,
f"daemon running as pid {pid}, but its /proc/{pid}/status could not "
f"be read, so its capabilities are unverified",
"check by hand: sudo grep CapEff /proc/%s/status" % pid)
elif not caps & _CAP_DAC_OVERRIDE:
add("INSTALL SURFACE", "parvagues-protect", FAIL,
f"daemon pid {pid} holds CapEff=0x{caps:x}, which does NOT include "
f"cap_dac_override. Running as root is not enough: uid 0 bypasses "
f"file permissions through that capability specifically, and every "
f"write to a pln-owned 0644 /proc/<pid>/oom_score_adj will return "
f"EACCES while `id -u` still says 0. Protection is decoration.",
"sudo tools/install-protect.sh (the unit must list "
"CAP_DAC_OVERRIDE in both CapabilityBoundingSet and "
"AmbientCapabilities, and the installer must RESTART, not "
"`enable --now`, which no-ops on a running unit)")
else:
add("INSTALL SURFACE", "parvagues-protect", PASS,
f"daemon pid {pid} active with cap_dac_override "
f"(CapEff=0x{caps:x}); {binp} + {unitp}")
# --- what it is actually protecting right now --------------------------
rc, out, err = run_cmd([str(binp), "--check"], timeout=15)
# --check pads its columns for a human reading a terminal; the doctor's own
# table re-wraps, so collapse the padding rather than shipping it twice.
lines = [" ".join(l.split()) for l in (out or "").splitlines() if l.strip()]
detail = "; ".join(lines) or (err or "").strip() or "no output"
if rc == 0:
add("INSTALL SURFACE", "parvagues-protect coverage", PASS, detail)
else:
add("INSTALL SURFACE", "parvagues-protect coverage", FAIL,
f"{binp} --check exited {rc}: {detail}",
"something that makes sound is killable or non-realtime. If the "
"daemon is up and holds cap_dac_override, it is not SEEING the "
"process — check the comm regexes in TARGETS.")
def check_local_bin_symlinks() -> None: def check_local_bin_symlinks() -> None:
......
...@@ -39,6 +39,13 @@ ...@@ -39,6 +39,13 @@
# BOOT_WAIT_SECS, and only then decides. # BOOT_WAIT_SECS, and only then decides.
# 3. It was never run in a mode that could be tested without silencing the rig. # 3. It was never run in a mode that could be tested without silencing the rig.
# Hence --dry-run. Exercise that first, always. # Hence --dry-run. Exercise that first, always.
# 4. It had no BOOT GRACE, so it restarted every healthy start (2026-09-06). The
# unit is `active` the instant sclang execs; scsynth appears ~8s later; this
# loop acted at 6s. Every clean start therefore burned two of systemd's three
# allowed starts, and a second start inside five minutes left parvagues-sc
# `failed (start-limit-hit)` — refusing to start at all until reset-failed.
# Failure mode 2 is the same mistake, and its fix (BOOT_WAIT_SECS) was only
# ever wired to the post-restart wait, never to the initial start.
# #
# It also honours the reason parvagues-sc.service carries its "audio gear should never # It also honours the reason parvagues-sc.service carries its "audio gear should never
# flap" comment: MAX_RESTARTS in a rolling window, then give up LOUDLY and stay down, # flap" comment: MAX_RESTARTS in a rolling window, then give up LOUDLY and stay down,
...@@ -55,6 +62,31 @@ PROC="${SCWD_PROC:-scsynth}" ...@@ -55,6 +62,31 @@ PROC="${SCWD_PROC:-scsynth}"
POLL_SECS=2 # how often we look POLL_SECS=2 # how often we look
MISSES_TO_ACT=3 # ~6s absent before we believe it MISSES_TO_ACT=3 # ~6s absent before we believe it
BOOT_WAIT_SECS=100 # > TimeoutStopSec (90s); a restart may legitimately take this BOOT_WAIT_SECS=100 # > TimeoutStopSec (90s); a restart may legitimately take this
# How long after the unit goes `active` we refuse to call scsynth "gone".
#
# THE UNIT GOES ACTIVE BEFORE THE AUDIO SERVER EXISTS. parvagues-sc.service is
# Type=simple, so systemd marks it active the instant `sclang` execs — but
# scsynth is sclang's CHILD and only appears once SuperDirt has recompiled the
# class library and booted the server. Measured 2026-09-06: **8 s**. This loop
# acted after MISSES_TO_ACT * POLL_SECS = 6 s, so EVERY HEALTHY START tripped it:
#
# 23:17:12 scsynth GONE (3 polls) while parvagues-sc.service is active
# — restarting (0 prior in window)
# 23:17:21 scsynth up after 8s
# 23:17:21 recovered
#
# `0 prior in window` on a start where nothing was wrong. The restart is not the
# real damage; the rate limit is. Each clean start spent TWO of systemd's
# StartLimitBurst=3 (the operator's, then ours), so a second start inside
# StartLimitIntervalUSec=5min landed on `start-limit-hit` and parvagues-sc then
# refused to start AT ALL until `systemctl --user reset-failed`. On stage that is
# indistinguishable from a dead rig, and this watchdog was the cause of it.
#
# 30 s is ~4x the measured boot and far below anything a human notices. Note that
# BOOT_WAIT_SECS already solved this for the post-RESTART wait (see await_scsynth,
# and failure mode 2 in the header) — it was simply never wired to the INITIAL
# start, which is the whole bug.
BOOT_GRACE_SECS="${SCWD_BOOT_GRACE:-30}"
MAX_RESTARTS=3 # per WINDOW_SECS, then stop trying and stay loud MAX_RESTARTS=3 # per WINDOW_SECS, then stop trying and stay loud
WINDOW_SECS=600 WINDOW_SECS=600
...@@ -92,6 +124,63 @@ notify() { ...@@ -92,6 +124,63 @@ notify() {
notify-send -a "ParVagues" -u "$urgency" -t "$timeout" "$title" "$body" 2>/dev/null || true notify-send -a "ParVagues" -u "$urgency" -t "$timeout" "$title" "$body" 2>/dev/null || true
} }
# proc_alive <comm> — is a process with this exact binary name running?
#
# Same answer as `pgrep -x "$comm"`, and 2x cheaper with no fork at all: pgrep
# walks every /proc entry AND reads cmdline for all of them, measured at 59 ms a
# call on this box, against 28 ms for one bash pass over /proc/*/comm. This loop
# calls it on every poll while the unit is up, so at a 2 s poll that is 3.0% of a
# core while playing versus 1.4%. Lifted from parvagues-protect, which cut its
# own cost 7.7x the same way (2026-09-06) — DUPLICATED rather than shared on
# purpose: that script is copied to /usr/local/bin and run as root, so it must
# not source anything out of a user-writable repo.
#
# Matches comm exactly, like `pgrep -x` and unlike `pgrep -f`: the watchdog must
# never be fooled into thinking the audio server is alive by a shell script whose
# path happens to contain its name.
#
# STATELESS on purpose — no pid cache. The kernel recycles pids, and this rig's
# most expensive recurring bug shape is a binding that was true once.
proc_alive() {
local p comm want="$1" first="${1:0:1}"
for p in /proc/[0-9]*; do
read -r comm 2>/dev/null < "$p/comm" || continue
case "$comm" in
"$first"*) [ "$comm" = "$want" ] && return 0 ;;
esac
done
return 1
}
# unit_state — sets U_ACTIVE (1/0) and U_ACTIVE_FOR (seconds, or -1 if unknown).
#
# ONE `systemctl show` where there used to be one `is-active`: the grace window
# costs no fork the loop was not already paying for. Not free, though, and the
# difference was measured rather than assumed — `is-active --quiet` is 7.0 ms,
# `show -p ActiveState -p ActiveEnterTimestamp` is 9.4 ms, so +2.4 ms per 2 s
# poll = +0.12% of a core. Worth it; the `date -d` parse stays on the rare path.
# An empty
# ActiveEnterTimestamp (a unit that has never run) yields -1, which the caller
# treats as "no grace" — the pre-2026-09-06 behaviour, not a free pass.
U_ACTIVE=0
U_ACTIVE_FOR=-1
unit_state() {
local line st="" ts=""
while IFS= read -r line; do
case "$line" in
ActiveState=*) st="${line#*=}" ;;
ActiveEnterTimestamp=*) ts="${line#*=}" ;;
esac
done < <(systemctl --user show -p ActiveState -p ActiveEnterTimestamp "$UNIT" 2>/dev/null)
[ "$st" = "active" ] && U_ACTIVE=1 || U_ACTIVE=0
U_ACTIVE_FOR=-1
if [ "$U_ACTIVE" = 1 ] && [ -n "$ts" ]; then
local t0; t0=$(date -d "$ts" +%s 2>/dev/null) || return 0
[ -n "$t0" ] && U_ACTIVE_FOR=$(( $(printf '%(%s)T' -1) - t0 ))
fi
return 0
}
# Restart timestamps within the rolling window, persisted across our own death. # Restart timestamps within the rolling window, persisted across our own death.
recent_restarts() { recent_restarts() {
local now t keep=() local now t keep=()
...@@ -113,14 +202,14 @@ await_scsynth() { ...@@ -113,14 +202,14 @@ await_scsynth() {
local waited=0 local waited=0
while (( waited < BOOT_WAIT_SECS )); do while (( waited < BOOT_WAIT_SECS )); do
sleep "$POLL_SECS"; waited=$(( waited + POLL_SECS )) sleep "$POLL_SECS"; waited=$(( waited + POLL_SECS ))
if pgrep -x "$PROC" >/dev/null 2>&1; then if proc_alive "$PROC"; then
log "$PROC up after ${waited}s"; return 0 log "$PROC up after ${waited}s"; return 0
fi fi
done done
return 1 return 1
} }
log "sc-watchdog: watching $PROC (poll ${POLL_SECS}s, act after ${MISSES_TO_ACT} misses)$( ((DRY_RUN)) && echo ' [DRY RUN — will not restart]')" log "sc-watchdog: watching $PROC (poll ${POLL_SECS}s, act after ${MISSES_TO_ACT} misses, ${BOOT_GRACE_SECS}s boot grace)$( ((DRY_RUN)) && echo ' [DRY RUN — will not restart]')"
misses=0 misses=0
gave_up=0 gave_up=0
...@@ -130,11 +219,12 @@ while true; do ...@@ -130,11 +219,12 @@ while true; do
# Only our business while the unit is meant to be up. If PLN stopped SuperDirt on # Only our business while the unit is meant to be up. If PLN stopped SuperDirt on
# purpose, silence is the correct state and we must not resurrect it. # purpose, silence is the correct state and we must not resurrect it.
if ! systemctl --user is-active --quiet "$UNIT"; then unit_state
if (( ! U_ACTIVE )); then
misses=0; gave_up=0; continue misses=0; gave_up=0; continue
fi fi
if pgrep -x "$PROC" >/dev/null 2>&1; then if proc_alive "$PROC"; then
(( misses > 0 )) && log "$PROC back after ${misses} miss(es)" (( misses > 0 )) && log "$PROC back after ${misses} miss(es)"
misses=0; gave_up=0; continue misses=0; gave_up=0; continue
fi fi
...@@ -143,6 +233,21 @@ while true; do ...@@ -143,6 +233,21 @@ while true; do
(( misses < MISSES_TO_ACT )) && continue (( misses < MISSES_TO_ACT )) && continue
(( gave_up )) && continue (( gave_up )) && continue
# STILL BOOTING IS NOT STILL DEAD. (The message says "holding off", never
# "not restarting": the regression test greps the log for evidence of a
# restart, and a reassurance containing the word it searches for is a test
# that fails on its own good news. It did, first run.) See BOOT_GRACE_SECS: the unit reports active
# the moment sclang execs, and scsynth arrives ~8s later. Without this gate the
# watchdog restarted every healthy start of SuperDirt and spent the rig's
# StartLimitBurst doing it. Keep counting misses (so the grace expiring acts
# immediately rather than restarting the 6s count) but say nothing and do
# nothing: an operator watching the journal should not see a fault reported for
# a boot that is going fine.
if (( U_ACTIVE_FOR >= 0 && U_ACTIVE_FOR < BOOT_GRACE_SECS )); then
(( misses == MISSES_TO_ACT )) && log "$PROC not up yet, ${U_ACTIVE_FOR}s into a ${BOOT_GRACE_SECS}s boot grace — holding off"
continue
fi
if (( DRY_RUN )); then if (( DRY_RUN )); then
log "[dry-run] $PROC GONE (${misses} polls) — WOULD restart ${UNIT}" log "[dry-run] $PROC GONE (${misses} polls) — WOULD restart ${UNIT}"
notify normal 6000 "Audio server died (dry run)" "scsynth is gone. Not restarting: --dry-run." notify normal 6000 "Audio server died (dry run)" "scsynth is gone. Not restarting: --dry-run."
......
...@@ -28,8 +28,13 @@ bad() { printf ' \033[31mFAIL\033[0m %s\n' "$1"; FAIL=$((FAIL+1)); } ...@@ -28,8 +28,13 @@ bad() { printf ' \033[31mFAIL\033[0m %s\n' "$1"; FAIL=$((FAIL+1)); }
cleanup() { cleanup() {
[ -n "$WD_PID" ] && kill "$WD_PID" 2>/dev/null [ -n "$WD_PID" ] && kill "$WD_PID" 2>/dev/null
[ -n "${SLOW_WD:-}" ] && kill "$SLOW_WD" 2>/dev/null
systemctl --user stop "$UNIT" 2>/dev/null systemctl --user stop "$UNIT" 2>/dev/null
systemctl --user reset-failed "$UNIT" 2>/dev/null systemctl --user reset-failed "$UNIT" 2>/dev/null
if [ -n "${SLOW_UNIT:-}" ]; then
systemctl --user stop "$SLOW_UNIT" 2>/dev/null
systemctl --user reset-failed "$SLOW_UNIT" 2>/dev/null
fi
pkill -x "$PROC" 2>/dev/null pkill -x "$PROC" 2>/dev/null
rm -rf "$TMP" rm -rf "$TMP"
} }
...@@ -68,7 +73,13 @@ fi ...@@ -68,7 +73,13 @@ fi
# SCWD_NO_NOTIFY=1: a test must never page a human about a fake unit. The first run # SCWD_NO_NOTIFY=1: a test must never page a human about a fake unit. The first run
# fired real STICKY notifications naming scwd-test-<pid>.service, which reached PLN # fired real STICKY notifications naming scwd-test-<pid>.service, which reached PLN
# after the test had exited and after that unit had ceased to exist. # after the test had exited and after that unit had ceased to exist.
# SCWD_BOOT_GRACE=0: tests 2-5 are about a server that DIED on a unit that has
# been up for a while. The boot grace (test 6) is a different claim and must not
# silently change what these measure — with the 30s default, test 2 would be
# waiting out a grace window rather than observing a recovery, and would pass or
# fail on its own timeout arithmetic.
SCWD_UNIT="$UNIT" SCWD_PROC="$PROC" SCWD_STATE="$STATE" SCWD_NO_NOTIFY=1 \ SCWD_UNIT="$UNIT" SCWD_PROC="$PROC" SCWD_STATE="$STATE" SCWD_NO_NOTIFY=1 \
SCWD_BOOT_GRACE=0 \
./tools/sc-watchdog.sh >"$TMP/wd.log" 2>&1 & ./tools/sc-watchdog.sh >"$TMP/wd.log" 2>&1 &
WD_PID=$! WD_PID=$!
...@@ -90,7 +101,12 @@ fi ...@@ -90,7 +101,12 @@ fi
# restarting, rather than looping forever. # restarting, rather than looping forever.
for i in 1 2 3 4; do pkill -x "$PROC" 2>/dev/null; sleep 12; done for i in 1 2 3 4; do pkill -x "$PROC" 2>/dev/null; sleep 12; done
sleep 5 sleep 5
n=$(grep -c 'restarting' "$TMP/wd.log" 2>/dev/null || echo 0) # NO `|| echo 0` here: grep -c already PRINTS 0 when it finds nothing, and it
# also exits 1, so the fallback appends a second zero and every later
# `-eq`/`-le` fails on the literal string "0\n0". Passed unnoticed in this
# case only because there were always matches; case 6 below, where zero is the
# expected answer, is where it surfaced.
n=$(grep -c 'GONE (' "$TMP/wd.log" 2>/dev/null); n=${n:-0}
if [ "$n" -le 3 ]; then ok "rate limiter held: $n restart(s), max 3" if [ "$n" -le 3 ]; then ok "rate limiter held: $n restart(s), max 3"
else bad "rate limiter did NOT hold: $n restarts (unbounded flap)"; fi else bad "rate limiter did NOT hold: $n restarts (unbounded flap)"; fi
...@@ -108,8 +124,71 @@ else ...@@ -108,8 +124,71 @@ else
bad "resurrected a unit PLN stopped on purpose" bad "resurrected a unit PLN stopped on purpose"
fi fi
# --- 6. THE REGRESSION: a unit that is still BOOTING must not be restarted -----
# 2026-09-06. parvagues-sc.service is Type=simple, so systemd calls it active the
# instant sclang execs — but scsynth is sclang's child and takes ~8s to appear.
# This loop acted at MISSES_TO_ACT*POLL_SECS = 6s, so EVERY HEALTHY START earned a
# restart, each clean start spent two of systemd's three allowed starts, and a
# second start inside five minutes left the rig `failed (start-limit-hit)` and
# unstartable. The fake below reproduces exactly that: 10s to first server.
kill "$WD_PID" 2>/dev/null; WD_PID=""
systemctl --user stop "$UNIT" 2>/dev/null
systemctl --user reset-failed "$UNIT" 2>/dev/null
pkill -x "$PROC" 2>/dev/null
sleep 1
SLOW_UNIT="scwd-slow-$$.service"
cat > "$TMP/fake-lang-slow.sh" <<EOF
#!/usr/bin/env bash
sleep 10 # SuperDirt recompiling the class library
"$TMP/$PROC" infinity & # ... and only now is there an audio server
while true; do sleep 1; done
EOF
chmod +x "$TMP/fake-lang-slow.sh"
systemd-run --user --unit="$SLOW_UNIT" --quiet \
--property=Restart=no --property=Type=simple \
"$TMP/fake-lang-slow.sh" >/dev/null 2>&1 || bad "could not create slow-boot unit"
SCWD_UNIT="$SLOW_UNIT" SCWD_PROC="$PROC" SCWD_STATE="$TMP/restarts-slow" \
SCWD_NO_NOTIFY=1 SCWD_BOOT_GRACE=30 \
./tools/sc-watchdog.sh >"$TMP/wd-slow.log" 2>&1 &
SLOW_WD=$!
sleep 18 # past the 6s act threshold, past the 10s boot, inside the 30s grace
# Match `GONE (`, which appears ONLY on the line where the watchdog decides to
# act. Grepping for "restarting" matched the grace message's own "not
# restarting" and failed this test on its own good news, first run.
if grep -q 'GONE (' "$TMP/wd-slow.log" 2>/dev/null; then
bad "restarted a unit that was merely still booting (the start-limit bug is back)"
else
ok "did not restart a still-booting unit"
fi
if grep -q 'boot grace' "$TMP/wd-slow.log" 2>/dev/null; then
ok "said so in the journal rather than staying silent"
else
bad "waited but never logged why (a silent wait is indistinguishable from a hang)"
fi
if pgrep -x "$PROC" >/dev/null; then
ok "slow server came up on its own, unassisted"
else
bad "slow server never appeared — the fake is wrong, not the watchdog"
fi
n_slow=$(grep -c 'GONE (' "$TMP/wd-slow.log" 2>/dev/null); n_slow=${n_slow:-0}
if [ "${n_slow:-0}" -eq 0 ] && [ ! -s "$TMP/restarts-slow" ]; then
ok "spent none of the unit's StartLimitBurst budget"
else
bad "recorded $n_slow restart(s) against the rate limit for a healthy boot"
fi
kill "$SLOW_WD" 2>/dev/null
systemctl --user stop "$SLOW_UNIT" 2>/dev/null
systemctl --user reset-failed "$SLOW_UNIT" 2>/dev/null
pkill -x "$PROC" 2>/dev/null
echo
echo "--- watchdog log (crash recovery) ---"; sed 's/^/ /' "$TMP/wd.log"
echo echo
echo "--- watchdog log ---"; sed 's/^/ /' "$TMP/wd.log" echo "--- watchdog log (slow boot) ---"; sed 's/^/ /' "$TMP/wd-slow.log"
echo echo
printf 'test-sc-watchdog: %d passed, %d failed\n' "$PASS" "$FAIL" printf 'test-sc-watchdog: %d passed, %d failed\n' "$PASS" "$FAIL"
[ "$FAIL" -eq 0 ] [ "$FAIL" -eq 0 ]
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