px-alive hits 'start operation timed out' during legitimate GPIO lease_wait park

[adrianwedd]

Observed (live robot, 2026-08-23, post-#286)

2e7b280d (#219 Track B, merged this morning) added a bounded Type=notify
startup contract for px-alive, with EXTEND_TIMEOUT_USEC heartbeats sent
before READY=1 specifically so the daemon can park indefinitely behind a
foreign GPIO lease (lease_wait) without the systemd watchdog killing it —
see CLAUDE.md's Idle-Alive Daemon section: "Do not add heartbeats inside
initialisation instead — that would keep the watchdog fed while wedged,
blinding it to the thing it exists to catch."

Tonight that contract was inconsistent. Journal excerpt (TimeoutStartUSec=1min):

19:53:03 px-alive[98434]: starting pid=98434 dry=False
19:53:03 px-alive[98434]: GPIO lease active (voice PID 96693) — parking in lease_wait
19:57:03 systemd[1]: px-alive.service: start operation timed out. Terminating.
19:57:03 px-alive[98434]: received signal 15 — shutting down
19:57:03 systemd[1]: px-alive.service: Failed with result 'timeout'.

19:57:28 px-alive[99696]: starting pid=99696 dry=False
19:57:28 px-alive[99696]: GPIO lease active (voice PID 96693) — parking in lease_wait
19:58:27 systemd[1]: px-alive.service: start operation timed out. Terminating.
19:58:27 px-alive[99696]: received signal 15 — shutting down
19:58:27 systemd[1]: px-alive.service: Failed with result 'timeout'.

Two consecutive restart attempts (restart counter 1→2→3) were killed by
systemd's start-timeout while legitimately parked waiting on
state/gpio_lease.json (owner: px-wake-listen's voice-turn PID 96693, a real,
actively-renewing lease, not stale). A third attempt at 19:58:57 succeeded and
ran cleanly for ~48 minutes. A later park (20:47:58, again behind the same
voice PID's lease) did not time out and was still parked several minutes in
when observed, so the failure is intermittent rather than universal — the
EXTEND_TIMEOUT_USEC heartbeat during park appears to not always be
sufficient/firing.

Why this matters

Each timeout-kill is currently masked by Restart=always + 10s +
StartLimitIntervalSec=0, so it self-heals and nothing user-visible breaks
today. But it means the #219 Track B contract ("bounded startup, 44.7s
typical") doesn't yet guarantee a legitimate park survives to READY under real
lease contention (a busy voice session doing several tool calls in a short
window) — it just guarantees the eventual restart loop recovers. That's a
weaker property than what the design doc/CLAUDE.md describe.

Suggested next step

Instrument or trace whether lease_wait's heartbeat-sending loop is actually
invoked on every poll iteration during a park (vs. only at park-entry), and
whether the interval between heartbeats can exceed systemd's effective
watchdog-extension window under load. Reproduce by holding a lease for >90s
while px-alive is (re)starting and watching for the timeout.

Not currently causing user-visible harm (self-heals via restart), so not
urgent — filed for tracking per #219's closeout review.

[adrianwedd]

Grooming 2026-08-26 — still reproducing, at a rate worth noting

$ journalctl -u px-alive --since -14d | grep -c 'start operation timed out'
59

59 in 14 days — roughly four a day. The body's assessment that this is
"intermittent rather than universal" and self-heals via Restart=always still
holds, and nothing user-visible breaks. But at four a day it is not a rare edge:
the EXTEND_TIMEOUT_USEC heartbeat is failing to cover a legitimate park
routinely, not occasionally.

The suggested next step in the body is unchanged and still the right one —
determine whether lease_wait's heartbeat is sent on every poll iteration or
only at park entry, and whether the interval can exceed systemd's extension
window under load.

Worth flagging one interaction that did not exist when this was filed: with
#300's launcher still uninstalled, GPIO tools are failing to elevate at all, so
the lease-contention pattern on the live robot right now is not
representative. Measure this after #300 is deployed, or the sample is
contaminated.