From 9ff60a62396a553ff2f33dc7af321bc7a00c3dff Mon Sep 17 00:00:00 2001 From: Zoltan Csizmadia Date: Sat, 19 Sep 2026 11:06:19 -0500 Subject: [PATCH] fix: the health probe gets a third answer, and stops holding the lock Closes #437. #440 bounded the COM call; this is the rest. Engine.Running returns (bool, error) ------------------------------------ Both implementations used to collapse 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 read as "the engine is down" and provoked a start of an engine that was almost certainly running. That is also why the bound could not simply be added to tick: bounding a two-valued Running converts "slow" into "down", which is the same bug with a timer attached. The third answer had to come first. (false, nil) now means "definitely not running". Anything the probe could not determine is an error, and tick does nothing at all that round rather than guess -- lastUp keeps the last reading worth trusting, and the next tick asks again. Provisioner keeps both shapes. EngineRunning stays for the waitFor polls, where "cannot tell" and "not yet" both correctly mean keep waiting; EngineRunningErr is for the caller whose next move is to start something. Same probe, the error no longer discarded on the path that needs it. The probe runs outside s.mu --------------------------- tick held the mutex across Engine.Running with the supervisor's process-lifetime context, so a service that stopped answering parked the reconciler INSIDE the lock: every Demand() blocked, meaning every docker connection hung rather than failing; LifecycleSnapshot froze, so the tray could not even show the supervisor was stuck; and the poke loop never ran again. Now: probe outside, decide inside, with a 60s ceiling on the probe itself. Generous on purpose -- 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. Moving it out opens a window where a Demand can cold-start the engine between the probe and the decision, leaving tick holding a reading that no longer describes the machine. startGen closes it: tick captures the counter before probing and gives up the round if it moved. Start is idempotent so the stale case was survivable anyway, but "engine is down; starting it" logged about an engine somebody just started is how an operator stops believing the log. Verification ------------ Three negative controls, each run both ways: probe error ignored -> Start called 41 times in 400ms against a RUNNING engine probe back inside mu -> "Demand blocked behind a probe in flight" (from #440) bound gone -> the COM test times out Plus TestDefiniteDownStillStartsTheEngine, so the fix cannot have bought safety by quietly disabling the supervisor. --- cmd/skrog/supervise.go | 7 +- cmd/skrog/wslcsupervise.go | 20 ++- internal/provision/provision.go | 14 ++ internal/supervise/idle_test.go | 22 ++- internal/supervise/poke_test.go | 9 +- internal/supervise/supervise.go | 61 +++++++- internal/supervise/supervise_hooks_test.go | 2 +- internal/supervise/supervise_test.go | 172 +++++++++++++++++++-- 8 files changed, 276 insertions(+), 31 deletions(-) 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 +}