diff --git a/cmd/skrog/supervise.go b/cmd/skrog/supervise.go index 42ac4e5..1cd308c 100644 --- a/cmd/skrog/supervise.go +++ b/cmd/skrog/supervise.go @@ -40,8 +40,11 @@ type engineAdapter struct { caRead bool } -func (e *engineAdapter) Running(ctx context.Context) bool { - return e.p.EngineRunning(ctx, e.opts) +func (e *engineAdapter) Running(ctx context.Context) (bool, error) { + // The error half matters here and only here (#437): the reconciler starts + // the engine when this says false, so a probe that merely failed must not + // be reported as a stopped engine. + return e.p.EngineRunningErr(ctx, e.opts) } // Start brings the engine up with the settings as they are now, not as they diff --git a/cmd/skrog/wslcsupervise.go b/cmd/skrog/wslcsupervise.go index d03ecdd..5db79c2 100644 --- a/cmd/skrog/wslcsupervise.go +++ b/cmd/skrog/wslcsupervise.go @@ -47,16 +47,26 @@ type wslcEngineAdapter struct { // Both halves matter. A session whose VM came back after idle-termination has // a tmpfs root, so it is running with no agent -- reporting that as healthy // would leave the supervisor content while every docker call failed. -func (e *wslcEngineAdapter) Running(ctx context.Context) bool { +func (e *wslcEngineAdapter) Running(ctx context.Context) (bool, error) { + // No session configured is a definite "not running", not a failed probe. if e.session == "" { - return false + return false, nil } + // Both probes distinguish "the answer is no" from "I could not ask" + // (#437). Folding an error into false told the reconciler the engine was + // down, and its response to that is to start one. ok, err := e.local.HasSession(ctx, e.session) - if err != nil || !ok { - return false + if err != nil { + return false, fmt.Errorf("checking for the wslc session: %w", err) + } + if !ok { + return false, nil } running, err := e.local.AgentRunning(ctx, e.session) - return err == nil && running + if err != nil { + return false, fmt.Errorf("checking the agent in session %s: %w", e.session, err) + } + return running, nil } // Start resolves a session -- creating one if nothing is running -- and places diff --git a/internal/provision/provision.go b/internal/provision/provision.go index 62638a3..1da8fd3 100644 --- a/internal/provision/provision.go +++ b/internal/provision/provision.go @@ -942,6 +942,20 @@ func (p *Provisioner) EngineRunning(ctx context.Context, opts Options) bool { return running } +// EngineRunningErr is EngineRunning without the lie that a failed probe means +// a stopped engine (#437). +// +// Collapsing the error into false is right for a `waitFor` poll, which is what +// most callers are: they are asking "is it up YET", and "cannot tell" and "not +// yet" both mean keep waiting. It is wrong for the supervisor, whose next move +// after seeing false is to START the engine — so a probe that merely failed +// would have it start one that is probably already running. +// +// Same probe, both answers kept. Use this where the difference matters. +func (p *Provisioner) EngineRunningErr(ctx context.Context, opts Options) (bool, error) { + return p.engineRunning(ctx, opts.withDefaults()) +} + // StopEngine terminates the engine's own distro — and nothing else. This is // the only stop primitive Skrog has on purpose: `wsl --shutdown` stops every // distro on the machine, including Docker Desktop's and the user's own, and is diff --git a/internal/supervise/idle_test.go b/internal/supervise/idle_test.go index 983c9cd..30e8975 100644 --- a/internal/supervise/idle_test.go +++ b/internal/supervise/idle_test.go @@ -128,14 +128,14 @@ func TestIdleRespectsRecentTraffic(t *testing.T) { func TestDemandColdStartsIdleEngine(t *testing.T) { s, e, _, dir := idleSup(t) runTicks(s, 3, 60*time.Millisecond) // idle it - if e.Running(context.Background()) { + if engineUp(e) { t.Fatal("precondition: engine should be idle-stopped") } if err := s.Demand(context.Background()); err != nil { t.Fatalf("Demand: %v", err) } - if !e.Running(context.Background()) { + if !engineUp(e) { t.Error("Demand did not start the engine") } if supervise.ReadEngineState(dir) != supervise.EngineActive { @@ -160,7 +160,7 @@ func TestPokeWakesIdleEngine(t *testing.T) { t.Fatal(err) } runTicks(s, 1, 0) - if !e.Running(context.Background()) { + if !engineUp(e) { t.Error("deleting the idle marker did not wake the engine") } } @@ -215,7 +215,7 @@ func TestDemandRefusesWhenDesiredStopped(t *testing.T) { // down: the stop clears the file but not this process's memory. s, e, _, dir := idleSup(t) runTicks(s, 3, 60*time.Millisecond) // idle-stop it - if e.Running(context.Background()) { + if engineUp(e) { t.Fatal("precondition: engine should be idle-stopped") } @@ -231,7 +231,7 @@ func TestDemandRefusesWhenDesiredStopped(t *testing.T) { if err := s.Demand(context.Background()); err == nil { t.Fatal("Demand woke an explicitly stopped engine") } - if e.Running(context.Background()) { + if engineUp(e) { t.Fatal("engine started despite desired=stopped") } if starts, _ := e.counts(); starts != 0 { @@ -249,7 +249,7 @@ func TestDemandRefusesWhenDesiredStopped(t *testing.T) { t.Fatal(err) } runTicks(s, 1, 0) - if !e.Running(context.Background()) { + if !engineUp(e) { t.Error("engine did not start after skrog start's desired=running") } } @@ -266,7 +266,7 @@ func TestTickClearsIdleFlagOnStoppedAndDown(t *testing.T) { // Demand) must bring the engine up. supervise.WriteDesired(dir, supervise.DesiredRunning) runTicks(s, 1, 0) - if !e.Running(context.Background()) { + if !engineUp(e) { t.Error("stale idleStopped flag still suppressing the reconciler") } } @@ -311,3 +311,11 @@ func TestIdleVetoedByBusySignal(t *testing.T) { t.Error("engine idled while Busy reported in-flight work (shared socket / containers)") } } + +// engineUp is the boolean half of Engine.Running, for assertions that only +// care whether the engine ended up running. The error half is exercised +// directly in the probe tests (#437). +func engineUp(e supervise.Engine) bool { + up, _ := e.Running(context.Background()) + return up +} diff --git a/internal/supervise/poke_test.go b/internal/supervise/poke_test.go index 6814f49..798afd5 100644 --- a/internal/supervise/poke_test.go +++ b/internal/supervise/poke_test.go @@ -14,9 +14,12 @@ type pokeEngine struct { probes atomic.Int32 } -func (e *pokeEngine) Running(context.Context) bool { e.probes.Add(1); return e.running.Load() } -func (e *pokeEngine) Start(context.Context) error { e.starts.Add(1); e.running.Store(true); return nil } -func (e *pokeEngine) Stop(context.Context) error { e.running.Store(false); return nil } +func (e *pokeEngine) Running(context.Context) (bool, error) { + e.probes.Add(1) + return e.running.Load(), nil +} +func (e *pokeEngine) Start(context.Context) error { e.starts.Add(1); e.running.Store(true); return nil } +func (e *pokeEngine) Stop(context.Context) error { e.running.Store(false); return nil } // The point of #398: the supervisor must notice `skrog start` in well under // the health interval, because up to a full interval of a 6.6-9.4 s start was diff --git a/internal/supervise/supervise.go b/internal/supervise/supervise.go index 9655eb4..16b9e04 100644 --- a/internal/supervise/supervise.go +++ b/internal/supervise/supervise.go @@ -14,7 +14,18 @@ import ( // and wsl packages already offer, and lets the loop be tested without WSL. type Engine interface { // Running reports whether the engine socket answers. - Running(ctx context.Context) bool + // + // The error is the third answer, and it is load-bearing (#437). Before it + // existed, both implementations collapsed a failed probe into false — and + // the reconciler's next move after false is to START the engine. So a + // wedged wslservice, a WSL update mid-flight, or any transient probe + // failure read as "the engine is down" and provoked a start of an engine + // that was probably running fine. + // + // Return (false, nil) only for "definitely not running". Anything you + // could not determine is an error, and the reconciler will do nothing at + // all that tick rather than guess. + Running(ctx context.Context) (bool, error) // Start brings the engine up (idempotent; provisioner.StartEngine). Start(ctx context.Context) error // Stop terminates the engine's own distro — and only that distro. Stopping @@ -107,6 +118,11 @@ type Supervisor struct { // mu serializes tick and Demand: a cold start must not race the // reconciler's own view of why the engine is down. mu sync.Mutex + // startGen counts engine starts. tick probes OUTSIDE mu (#437), so a + // Demand can cold-start the engine in the window between the probe and + // the decision; the counter is how tick notices its reading went stale + // and defers to the next one. Guarded by mu. + startGen uint64 // idleStopped mirrors the engine-state file; kept in memory so the tick // can tell "down because I idled it" from "down unexpectedly" without // re-reading, and re-adopted from the file after a supervisor restart. @@ -240,12 +256,51 @@ func (s *Supervisor) readIntent() intent { } } +// probeTimeout bounds one health probe. Generous: a cold `wsl.exe --list` on a +// loaded machine is not fast, and this is a ceiling for a probe that has +// stopped answering, not a latency target. +const probeTimeout = 60 * time.Second + func (s *Supervisor) tick(ctx context.Context) { + // The probe runs OUTSIDE mu, and bounded (#437). + // + // It used to run under the lock with the supervisor's process-lifetime + // context, so a wslservice that stopped answering parked the reconciler + // forever WHILE HOLDING mu: every Demand() blocked, so every docker + // command hung instead of failing, LifecycleSnapshot froze so the tray + // could not even show the supervisor was stuck, and the poke loop never + // ran again. The COM funnel made it worse, since every COM caller now + // queues behind one thread. + s.mu.Lock() + gen := s.startGen + s.mu.Unlock() + + probeCtx, cancel := context.WithTimeout(ctx, probeTimeout) + up, probeErr := s.Engine.Running(probeCtx) + cancel() + s.mu.Lock() defer s.mu.Unlock() + if probeErr != nil { + // "Cannot tell" is not "down". Doing nothing leaves lastUp at the + // last reading we trust, and the next tick asks again — which is + // right, because the alternative is starting an engine that is + // probably running. + s.log().Warn("engine health probe failed; skipping this tick", "error", probeErr) + return + } + if s.startGen != gen { + // A Demand cold-started the engine while we were probing, so `up` is + // describing a machine that no longer exists. Acting on it would log + // "engine is down" about an engine somebody just started, and call + // Start a second time. Start is idempotent, so this is a tidiness fix + // rather than a correctness one -- but a spurious start in the log is + // how an operator loses trust in the log. + return + } + desired := ReadDesired(s.Config.StateDir) - up := s.Engine.Running(ctx) s.lastUp.Store(up) switch { @@ -279,6 +334,7 @@ func (s *Supervisor) tick(ctx context.Context) { } s.failures = 0 s.nextTry = time.Time{} + s.startGen++ // #437: a concurrent probe's reading is now stale s.upSince = time.Now() s.lifecycle.EngineStarts++ if s.lifecycle.IdleStops > 0 && s.lifecycle.LastWakeAt.Before(s.lifecycle.LastIdleStopAt) { @@ -444,6 +500,7 @@ func (s *Supervisor) Demand(ctx context.Context) error { } s.failures = 0 s.nextTry = time.Time{} + s.startGen++ // #437: a tick probing right now is holding a stale reading // Cleared only after a successful start, so a second connection arriving // mid-start blocks on the mutex and then sees a running engine, rather // than racing ahead to dial an engine that is not up yet. diff --git a/internal/supervise/supervise_hooks_test.go b/internal/supervise/supervise_hooks_test.go index 87c6615..187d560 100644 --- a/internal/supervise/supervise_hooks_test.go +++ b/internal/supervise/supervise_hooks_test.go @@ -73,7 +73,7 @@ func TestHookOnIdleStop(t *testing.T) { waitFor(t, 3*time.Second, func() bool { return rec.has(supervise.HookOnIdleStop) }, "on-idle-stop hook did not fire") - if e.Running(ctx) { + if engineUp(e) { t.Error("engine should be idle-stopped") } } diff --git a/internal/supervise/supervise_test.go b/internal/supervise/supervise_test.go index 9bbce67..c12d0bd 100644 --- a/internal/supervise/supervise_test.go +++ b/internal/supervise/supervise_test.go @@ -17,14 +17,38 @@ type fakeEngine struct { mu sync.Mutex running bool startErr error - starts int - stops int + // probeErr makes the health probe fail rather than answer -- the "cannot + // tell" case the reconciler must not read as "down" (#437). + probeErr error + // probeEntered is signalled when Running starts, and probeGate blocks it + // there -- together they let a test hold a probe in flight and check what + // else can still make progress (#437). + probeEntered chan struct{} + probeGate chan struct{} + starts int + stops int + probes int } -func (f *fakeEngine) Running(context.Context) bool { +func (f *fakeEngine) Running(context.Context) (bool, error) { f.mu.Lock() - defer f.mu.Unlock() - return f.running + f.probes++ + entered, gate, running, perr := f.probeEntered, f.probeGate, f.running, f.probeErr + f.mu.Unlock() + + if entered != nil { + select { + case entered <- struct{}{}: + default: + } + } + if gate != nil { + <-gate + } + if perr != nil { + return false, perr + } + return running, nil } func (f *fakeEngine) Start(context.Context) error { @@ -91,7 +115,7 @@ func TestStartsDownEngine(t *testing.T) { defer cancel() go sup.Run(ctx) - waitFor(t, 3*time.Second, func() bool { s, _ := e.counts(); return s >= 1 && e.Running(ctx) }, + waitFor(t, 3*time.Second, func() bool { s, _ := e.counts(); return s >= 1 && engineUp(e) }, "engine was never started") } @@ -108,7 +132,7 @@ func TestRestartsAfterCrash(t *testing.T) { time.Sleep(100 * time.Millisecond) // a few healthy ticks e.setRunning(false) // crash - waitFor(t, 3*time.Second, func() bool { return e.Running(ctx) }, + waitFor(t, 3*time.Second, func() bool { return engineUp(e) }, "engine was not restarted after a crash") } @@ -125,7 +149,7 @@ func TestHonorsDesiredStopped(t *testing.T) { defer cancel() go sup.Run(ctx) - waitFor(t, 3*time.Second, func() bool { return !e.Running(ctx) }, + waitFor(t, 3*time.Second, func() bool { return !engineUp(e) }, "engine was not stopped despite desired=stopped") // And it must STAY stopped across many ticks. @@ -146,12 +170,12 @@ func TestStopThenStartRoundTrip(t *testing.T) { if err := supervise.WriteDesired(dir, supervise.DesiredStopped); err != nil { t.Fatal(err) } - waitFor(t, 3*time.Second, func() bool { return !e.Running(ctx) }, "did not stop") + waitFor(t, 3*time.Second, func() bool { return !engineUp(e) }, "did not stop") if err := supervise.WriteDesired(dir, supervise.DesiredRunning); err != nil { t.Fatal(err) } - waitFor(t, 3*time.Second, func() bool { return e.Running(ctx) }, "did not start again") + waitFor(t, 3*time.Second, func() bool { return engineUp(e) }, "did not start again") } func TestBackoffLimitsStartAttempts(t *testing.T) { @@ -195,7 +219,7 @@ func TestBackoffResetsOnRecovery(t *testing.T) { time.Sleep(100 * time.Millisecond) // healthy ticks observe it e.setRunning(false) // fresh crash - waitFor(t, 3*time.Second, func() bool { return e.Running(ctx) }, + waitFor(t, 3*time.Second, func() bool { return engineUp(e) }, "fresh crash after recovery was not repaired promptly") } @@ -228,3 +252,129 @@ func TestGarbageDesiredStateReadsAsRunning(t *testing.T) { t.Errorf("garbage state read as %q, want running", got) } } + +// A probe that FAILS must not be read as a stopped engine (#437). +// +// Before Running grew an error, both real implementations collapsed a failed +// probe into false — and the reconciler's response to false is Engine.Start. +// So a wedged wslservice, a WSL update mid-flight, or any transient probe +// failure provoked a start of an engine that was very likely running. +// +// This is also why the bounded probe could not be added first: bounding a +// two-valued Running converts "slow" into "down", which is the same bug with +// a timer attached. +func TestProbeFailureIsNotTreatedAsAStoppedEngine(t *testing.T) { + dir := t.TempDir() + if err := supervise.WriteDesired(dir, supervise.DesiredRunning); err != nil { + t.Fatal(err) + } + e := &fakeEngine{running: true, probeErr: errors.New("wslservice is not answering")} + s := &supervise.Supervisor{ + Engine: e, + Config: supervise.Config{StateDir: dir, Interval: 10 * time.Millisecond}, + } + + ctx, cancel := context.WithTimeout(context.Background(), 400*time.Millisecond) + defer cancel() + s.Run(ctx) + + e.mu.Lock() + probes, starts, stops := e.probes, e.starts, e.stops + e.mu.Unlock() + + if probes == 0 { + t.Fatal("the engine was never probed; the test proves nothing") + } + if starts != 0 { + t.Errorf("Start called %d time(s) after a FAILED probe: a probe that could not "+ + "answer was read as a stopped engine", starts) + } + if stops != 0 { + t.Errorf("Stop called %d time(s) on an unknown reading", stops) + } +} + +// ...and a probe that genuinely reports "down" must still start the engine, or +// the fix above would have bought safety by disabling the supervisor. +func TestDefiniteDownStillStartsTheEngine(t *testing.T) { + dir := t.TempDir() + if err := supervise.WriteDesired(dir, supervise.DesiredRunning); err != nil { + t.Fatal(err) + } + e := &fakeEngine{running: false} // definite: (false, nil) + s := &supervise.Supervisor{ + Engine: e, + Config: supervise.Config{StateDir: dir, Interval: 10 * time.Millisecond}, + } + + ctx, cancel := context.WithTimeout(context.Background(), 400*time.Millisecond) + defer cancel() + s.Run(ctx) + + e.mu.Lock() + starts := e.starts + e.mu.Unlock() + if starts == 0 { + t.Error("a definite (false, nil) did not start the engine") + } +} + +// A probe in flight must not block Demand (#437). +// +// tick used to hold s.mu across Engine.Running with the supervisor's +// process-lifetime context. A wslservice that stopped answering therefore +// parked the reconciler INSIDE the lock, and Demand takes the same lock — so +// every docker connection through demandDialer hung rather than failing, +// LifecycleSnapshot froze so the tray could not show the supervisor was stuck, +// and the poke loop never ran again. +// +// The probe now runs outside the lock. This holds one in flight and checks +// that Demand still gets the mutex. +func TestDemandIsNotBlockedByAProbeInFlight(t *testing.T) { + dir := t.TempDir() + if err := supervise.WriteDesired(dir, supervise.DesiredRunning); err != nil { + t.Fatal(err) + } + e := &fakeEngine{ + running: true, + probeEntered: make(chan struct{}, 1), + probeGate: make(chan struct{}), + } + s := &supervise.Supervisor{ + Engine: e, + Config: supervise.Config{StateDir: dir, Interval: 10 * time.Millisecond}, + } + + ctx, cancel := context.WithCancel(context.Background()) + runDone := make(chan struct{}) + go func() { defer close(runDone); s.Run(ctx) }() + + // Wait for a probe to be in flight, then leave it wedged. + select { + case <-e.probeEntered: + case <-time.After(5 * time.Second): + cancel() + <-runDone + t.Fatal("no probe started; the test proves nothing") + } + + // Demand must not wait behind it. The engine is not idle, so Demand does + // nothing but take the lock and return — which is exactly the assertion: + // it could take the lock at all. + demanded := make(chan error, 1) + go func() { demanded <- s.Demand(context.Background()) }() + + select { + case <-demanded: + case <-time.After(5 * time.Second): + close(e.probeGate) + cancel() + <-runDone + t.Fatal("Demand blocked behind a probe in flight: the reconciler is holding " + + "s.mu across Engine.Running, so a wedged wslservice hangs every docker command (#437)") + } + + close(e.probeGate) + cancel() + <-runDone +}