diff --git a/pkg/daemon/rxwatchdog.go b/pkg/daemon/rxwatchdog.go index c057eefd..2880f012 100644 --- a/pkg/daemon/rxwatchdog.go +++ b/pkg/daemon/rxwatchdog.go @@ -48,6 +48,17 @@ const ( // rxWatchdogTickInterval is how often the watchdog samples counters. rxWatchdogTickInterval = 30 * time.Second + // suspendGapThreshold is how late a tick must be before the watchdog + // concludes this process was not running — a laptop sleeping, a paused + // VM, a migrated hypervisor guest. + // + // 4x the tick interval: far beyond scheduler jitter or a slow tick, but + // still under the shortest realistic lid-close. Deliberately measured + // from observed ticker lateness rather than any OS power API, so it + // works identically on macOS, Linux and inside a VM, and needs no + // platform-specific code (there was none in the tree at all). + suspendGapThreshold = 4 * rxWatchdogTickInterval + // rxSilenceThreshold is how long PktsRecv must stall (with tx active) // before the first soft recovery fires. rxSilenceThreshold = 3 * time.Minute @@ -113,6 +124,19 @@ type rxWatchdogState struct { recvSeen uint64 // PktsRecv at lastProgress sentAtProgress uint64 // PktsSent at lastProgress softAttempts int // consecutive soft recoveries this silence + + // suspendSeen records that the host suspended during this process's + // lifetime. It permanently unlocks the "never progressed" guard. + // + // That guard withholds the hard exit when PktsRecv has not advanced + // once this process, on the theory that restarting would reproduce the + // same state and boot-loop. Sound for a host that never had working + // inbound — and wrong after a resume, where the transport worked + // before the gap and a restart is exactly what recovers it. In the + // field this guard was the dominant blocker: of 344 withheld restarts + // on one laptop, 301 were "never progressed" and only 4 were the + // registry check. + suspendSeen bool } // rxWatchdogAction names what a tick did — returned for tests and logs. @@ -143,16 +167,83 @@ func (d *Daemon) rxWatchdogLoop() { } ticker := time.NewTicker(rxWatchdogTickInterval) defer ticker.Stop() + lastTick := time.Now() for { select { case <-d.stopCh: return case <-ticker.C: - d.rxWatchdogTick(st, time.Now()) + now := time.Now() + if gap := now.Sub(lastTick); gap >= suspendGapThreshold { + d.rxWatchdogResume(st, now, gap) + } + lastTick = now + d.rxWatchdogTick(st, now) } } } +// rxWatchdogResume handles coming back from a host suspend (laptop lid +// closed, VM paused, hypervisor migration). +// +// This is the gap the watchdog had. On resume every UDP path is stale — +// the NAT mapping the beacon punched is gone, the peer sessions are dead, +// and the pooled registry conn is half-open. Nothing in the daemon noticed: +// there was no suspend/resume awareness anywhere in the tree (no +// IORegisterForSystemPower, no wake notification, nothing), so recovery had +// to wait for the ordinary rx-silence path — which then deadlocked against +// its own safety guard (see the active probe in rxWatchdogTick). +// +// Detection is deliberately clock-agnostic: a ticker set to fire every +// rxWatchdogTickInterval that instead fires suspendGapThreshold late means +// this process was not running. Whether that was a laptop sleeping, a +// paused VM, or brutal CPU starvation does not matter — in every case the +// transport state predating the gap is untrustworthy and re-establishing it +// is both correct and cheap. +// +// Two actions, neither of which restarts anything: +// +// 1. Re-punch and re-register: RegisterWithBeacon refreshes the NAT +// mapping (its discover reply doubles as an inbound probe) and the +// registry gets a fresh conn, since the pooled one did not survive the +// suspend and has no liveness ping of its own. +// 2. Reset the wedge baseline. The pre-suspend counters describe a +// different epoch: PktsRecv/PktsSent are frozen at their pre-sleep +// values while lastProgress is hours old, so the very first tick after +// resume would otherwise read as a multi-hour rx silence and burn soft +// attempts on a wedge that had not been given a chance to recover yet. +func (d *Daemon) rxWatchdogResume(st *rxWatchdogState, now time.Time, gap time.Duration) { + defer recoverLayer("L4", "rxWatchdogResume", d.bus, nil) + + slog.Warn("host resumed from suspend — re-establishing transport", + "gap", gap.Truncate(time.Second).String(), + "tick_interval", rxWatchdogTickInterval.String()) + d.publishEvent("tunnel.host_resumed", map[string]any{ + "gap_seconds": int64(gap.Seconds()), + }) + + d.tunnels.RegisterWithBeacon() + if d.reg() != nil { + // The pooled registry conn cannot have survived the suspend, and it + // has no half-open detection of its own, so force a fresh one rather + // than waiting for a request to hang on the dead socket. + if err := d.forceReconnectRegistry(); err != nil { + slog.Warn("registry reconnect after resume failed", "error", err) + } else { + d.reRegister() + } + } + + // Fresh epoch: re-baseline so the first post-resume tick measures + // recovery, not the suspend. + st.recvSeen = atomic.LoadUint64(&d.tunnels.PktsRecv) + st.sentAtProgress = atomic.LoadUint64(&d.tunnels.PktsSent) + st.lastProgress = now + st.softAttempts = 0 + st.suspendSeen = true + d.consecutiveDialTimeouts.Store(0) +} + // rxWatchdogTick runs one watchdog iteration. Extracted for testability — // production drives it from rxWatchdogLoop; tests drive it directly. // @@ -263,9 +354,14 @@ func (d *Daemon) rxWatchdogTick(st *rxWatchdogState, now time.Time) (action rxWa } uptime := now.Sub(d.startTime) switch { - case st.recvSeen == 0: + case st.recvSeen == 0 && !st.suspendSeen: // Never received a tunnel packet this process — a restart would // reproduce the same state (boot loop). Keep soft-recovering. + // + // Skipped once the host has suspended: after a resume, "no inbound + // yet this process" is a symptom of the gap, not evidence that + // inbound can never work here, and a restart is precisely what + // clears it. slog.Warn("inbound path silent and never progressed — withholding restart, will keep soft-recovering", "silent_for", silence.Truncate(time.Second).String()) case registryAge < 0 || registryAge > rxWedgeRegistryFresh: diff --git a/pkg/daemon/zz_rx_watchdog_suspend_test.go b/pkg/daemon/zz_rx_watchdog_suspend_test.go new file mode 100644 index 00000000..b6c8a0a7 --- /dev/null +++ b/pkg/daemon/zz_rx_watchdog_suspend_test.go @@ -0,0 +1,120 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package daemon + +import ( + "sync/atomic" + "testing" + "time" +) + +// TestSuspendUnlocksNeverProgressedGuard reproduces the field failure: a +// laptop resumes from sleep, inbound is dead, and the watchdog refuses to +// escalate forever because PktsRecv never advanced this process. +// +// On one laptop's daemon.log, 301 of 344 withheld restarts were this guard +// ("never progressed"); only 4 were the registry check. The operator had to +// restart the daemon by hand every time. +// +// The guard is correct for a host whose inbound never worked — restarting +// would boot-loop. It is wrong after a host suspend, where the transport +// worked before the gap and a restart is exactly what recovers it. +func TestSuspendUnlocksNeverProgressedGuard(t *testing.T) { + // Must not be parallel: this stubs the global rxWatchdogExit, and the + // escalation path below really would call os.Exit(86) otherwise. + exitCode := swapExitForTest(t) + now := time.Now() + + // No inbound has ever been delivered this process, but we are + // transmitting hard — the post-resume signature. + newWedged := func() (*Daemon, *rxWatchdogState) { + d := newRxWatchdogTestDaemon(t) + atomic.StoreUint64(&d.tunnels.PktsRecv, 0) + atomic.StoreUint64(&d.tunnels.PktsSent, 5000) + d.lastRegistryOKNano.Store(now.UnixNano()) + d.startTime = now.Add(-2 * rxWedgeMinUptime) + + st := &rxWatchdogState{ + lastProgress: now.Add(-10 * rxSilenceThreshold), + recvSeen: 0, + sentAtProgress: 0, + } + return d, st + } + + // Without a suspend the guard must still hold — a genuinely broken + // host must not boot-loop. + d, st := newWedged() + var action rxWatchdogAction + for i := 0; i < rxWatchdogSoftMax+1; i++ { + action = d.rxWatchdogTick(st, now) + } + if action == rxActionExit { + t.Fatal("exited despite never having received inbound and no suspend — " + + "this is the boot-loop the guard exists to prevent") + } + + // After a suspend, the same state must escalate to the restart. + d, st = newWedged() + st.suspendSeen = true + for i := 0; i < rxWatchdogSoftMax+1; i++ { + action = d.rxWatchdogTick(st, now) + } + if action != rxActionExit { + t.Fatalf("post-suspend wedge did not escalate to restart: got %q — "+ + "this is the bug that forced a manual `pilotctl daemon restart` after every lid-close", action) + } + if *exitCode != rxWedgeExitCode { + t.Fatalf("exit code = %d, want %d (the value launchd/systemd respawn on)", *exitCode, rxWedgeExitCode) + } +} + +// TestResumeReBaselinesAndMarksSuspend pins what the resume handler does: +// it re-baselines the wedge counters (the pre-suspend epoch is meaningless) +// and records that a suspend happened so the guard above unlocks. +func TestResumeReBaselinesAndMarksSuspend(t *testing.T) { + d := newRxWatchdogTestDaemon(t) + atomic.StoreUint64(&d.tunnels.PktsRecv, 4242) + atomic.StoreUint64(&d.tunnels.PktsSent, 9999) + + now := time.Now() + st := &rxWatchdogState{ + lastProgress: now.Add(-8 * time.Hour), // slept overnight + recvSeen: 10, + sentAtProgress: 20, + softAttempts: 2, + } + + d.rxWatchdogResume(st, now, 8*time.Hour) + + if !st.suspendSeen { + t.Error("suspendSeen not set — the never-progressed guard stays locked") + } + if st.softAttempts != 0 { + t.Errorf("softAttempts = %d, want 0: the pre-suspend attempts describe a different epoch", st.softAttempts) + } + if !st.lastProgress.Equal(now) { + t.Error("lastProgress not re-baselined — the first post-resume tick would read as an 8h rx silence") + } + if st.recvSeen != 4242 || st.sentAtProgress != 9999 { + t.Errorf("counters not re-baselined: recvSeen=%d sentAtProgress=%d", st.recvSeen, st.sentAtProgress) + } +} + +// TestSuspendGapThresholdIgnoresOrdinaryJitter guards the detector against +// firing on a merely-late tick. Recovery is cheap but not free — it +// re-punches NAT and forces a fresh registry connection. +func TestSuspendGapThresholdIgnoresOrdinaryJitter(t *testing.T) { + if suspendGapThreshold <= rxWatchdogTickInterval { + t.Fatal("threshold must exceed the tick interval or every tick is a suspend") + } + // A tick arriving at 2x the interval is slow, not a suspend. + if 2*rxWatchdogTickInterval >= suspendGapThreshold { + t.Errorf("threshold %v too tight: a merely slow tick (2x interval) would be read as a host suspend", + suspendGapThreshold) + } + // A lid-close is minutes at least; the threshold must be well under it. + if suspendGapThreshold > 5*time.Minute { + t.Errorf("threshold %v too loose: short suspends would go undetected", suspendGapThreshold) + } +}