Repository navigation
fix(scheduler): release the macOS slot on the provisioning-deadline path - #197
Conversation
…ath (#196) The fleet's mac served ZERO macOS jobs for ~28 hours while reporting `status: ok`, `active_jobs: 0` and answering /healthz with 200. Five macOS jobs queued in that window; none were provisioned, and the first of them aged out at GitHub's 24-hour queue timeout without ever running. An ephemerd restart fixed it instantly — the same code path then provisioned in 54 seconds, so the VM boot failure that started it was a one-off transient. The outage was entirely what happened afterwards. The mechanism. A macOS VM wedged before its runner became reachable. PR #178's provisioning watchdog fired on schedule and logged "macOS VM stuck in provisioning past deadline; force-stopping VM to reclaim the slot". It force-stopped the VM (the guest ignored the graceful request: "macOS VM did not stop gracefully, forcing") and then did a bare `<-resCh` to wait for the reachability goroutine to unwind — on the assumption that killing the VM always drops the guest connection and unblocks it. It did not. The wait never returned, so waitForMacRunnerBounded never returned, so handleMacOSJob never reached the `<-s.macSem` that the log line had just promised. The slot the watchdog existed to reclaim was reclaimed for the VM and never for the semaphore. Nothing showed it. The job had never reached trackRunning, so len(s.running) was 0 and every health signal — active_jobs, /healthz, `ephemerd jobs`, the orphan sweep — reported an idle, healthy node. And a job blocking on a full semaphore logged nothing at all, so the log went silent for 28 hours. This is the shape PR #190 already fixed on the local and Linux paths: release the slot as soon as the job stops being demand, never coupled to teardown completing. Same treatment here. - waitForMacRunnerBounded now stops the VM off-thread and bounds the unwind wait (awaitUnwind, 30s), then returns regardless. A wedged guest wait is a leaked goroutine nothing in this process can kill; blocking on it turned that into a leaked concurrency slot, which costs the node its entire macOS capacity. - Every macOS teardown that runs while a slot or a wait-goroutine could be held goes through stopVMBounded. This also closes the second instance of the same bug: the caller's error path called macVM.Stop() again, and darwinMacOSVM.Stop is a sync.Once — a second caller blocks until the first returns, so the "cleanup" Stop hung on the wedged one while still holding the slot. - The macOS wait-goroutine releases the moment the job is untracked instead of at the end, behind macVM.Stop() (up to 15s, unbounded when the force-stop wedges) and a ReleaseJob API call on context.Background() with no deadline. - All three dispatch paths now acquire through slotToken: an idempotent release with a deferred backstop, so no future error return can skip it and a panic cannot either. handleMacOSJob had six hand-written `<-s.macSem` returns; one of them was unreachable. Observability, both gaps filed with the issue: - status/healthz gain held_slots, slot_capacity and a per-pool breakdown, read straight off the semaphores so they count capacity charged to UNTRACKED work. active_jobs and max_concurrent are unchanged. held == capacity with active_jobs 0 is the outage, visible. - A dispatch that blocks on a full pool now logs after 30s and every 5 minutes thereafter, and escalates to Error ("suspected slot leak") once it has waited 15 minutes for a pool whose held slots no tracked job accounts for. That doubles as the leak watchdog: a held slot only matters when something is waiting for it, so the check lives on the waiting path and costs nothing on an idle node. #178's deadline behaviour is unchanged — the VM is still force-stopped — and the #151 busy-veto is untouched.
|
Adversarial review: needs changes — not merging yet. The core of the fix is confirmed sound, but three MAJORs remain. Verified correct: exactly-once release on all three dispatch paths ( MAJOR 1 — an unbounded MAJOR 2 — release-before-teardown opens a same-job re-dispatch race. The comment at MAJOR 3 — the abandoned-VM trade is unbounded. Each abandoned provision leaks three goroutines (WaitForRunner, Minors: the leak escalation compares a per-pool Fixes in progress on the branch. |
…ed on The leak watchdog added with the #196 fix compares a PER-POOL held count against a GLOBAL tracked-job count: `held := len(sem)` is one pool, but `tracked := s.ActiveJobs()` is `len(s.running)` across every pool. Mixed units, and the mistake fails in the one direction that matters — it SUPPRESSES the alarm. On the node this was written for that is not hypothetical. The fleet's mac runs three pools: local runners, Linux jobs dispatched into its embedded VM, and macOS VMs. It serves Linux work more or less continuously. So for the whole 28 hours its macOS slot was leaked there was almost always some tracked job somewhere, and one is enough: `trackedJobs == 0` never held, so the escalation stayed at Warn and the single log line that would have named the outage — "blocked on a concurrency slot that no tracked job accounts for — suspected slot leak" — was never going to be emitted no matter how long the queued macOS jobs waited. The denominator now matches the numerator. trackedInPool(pool) counts only the running jobs whose slot came from that pool, classified by poolOf: macosVM != nil is macos, a non-empty dispatched name is linux, everything else is local — the same routing handleQueued uses to pick the semaphore in the first place. A leaked macOS slot is now reported at Error regardless of what the Linux pool is doing. The log key is renamed tracked_jobs -> pool_tracked_jobs so the number cannot be misread as the node-wide count; active_jobs, HeldSlots and SlotUsage are untouched. Also corrects the acquireSlot fast-path comment, which claimed the path was "allocation-free" while returning &slotToken{}. It is timer- and log-free, which is the property that actually matters; one small struct per job that is about to boot a VM is not worth claiming otherwise. Tests: - TestSlotLeakEscalationIsScopedToThePool: a tracked LOCAL job plus a macOS slot held by nothing tracked must still escalate to Error. Fails against the old rule (observed: level=WARN, "waiting for a free concurrency slot", pool_tracked_jobs=1). - TestTrackedInPool: one job per pool, each counted against its own pool, with ActiveJobs() still 3. - TestSlotWaitSeverity's table is renamed to say the third column is per-pool, so it stops reading as an endorsement of the global count.
Three problems, one mechanism: the #196 fix decided that a macOS VM stop which does not return must never pin the caller. It then applied that decision to exactly one caller. 1. THREE UNBOUNDED Stop() CALLS REMAINED, and the worst of them is on the event loop. sweepOrphanRunners is invoked SYNCHRONOUSLY from the `case <-cleanupTicker.C:` arm of Run's select — the scheduler's only event loop. A tracked macOS job nominated as an orphan whose Vz stop wedges is the exact failure #196 documented on metal, and it did not cost a slot there, it cost the daemon: no queued/in_progress/completed handling for ANY platform, and no drain on SIGTERM, while /healthz kept answering 200. Strictly worse than the leak the PR set out to fix, one call away. handleCompleted's bare Stop() parks the completed-event handler forever and with it the deferred sweepOrphanRunners that reconciles the runner ledger after every completion. destroyAll's bare Stop() is the force-kill arm of drain(), reached only after ShutdownTimeout has ALREADY expired — a wedge there means drain never returns, Run never returns, and the operator has to escalate SIGTERM to SIGKILL by hand, which defeats the entire point of having a shutdown timeout. All three now go through stopVMBounded. There is no longer any macOS stop in this package that may block its caller; stopVMAsync is the single place macVM.Stop() is called at all. 2. THE REDUNDANT SECOND STOP on the provisioning-deadline path. waitForMacRunnerBounded force-stops the VM when the deadline fires (#178, unchanged), and the caller's error path then stopped the same VM again. darwinMacOSVM.Stop is `stopOnce.Do(m.stop)`, so a second caller does not return early — it BLOCKS until the first invocation returns. Against the wedged guest that is the whole subject of #196 that is a full teardown grace (30s) of dead time on a path that still has a ghost JIT runner to deregister, plus a third goroutine parked inside the Once behind the other two. waitForMacRunnerBounded now reports whether it already stopped the VM and the caller skips its own stop when it did. 3. THE ABANDONED-VM TRADE HAD NO BOUND AND NO REPORTING. Walking away from a wedged stop is right — a leaked goroutine is far cheaper than a leaked slot, which costs the node its entire macOS capacity. But it is not free. Each abandonment leaves goroutines retaining a live *darwinMacOSVM and, expensively, a STILL-RUNNING macOS guest holding its full configured RAM and its disk clone. Only a daemon restart reclaims it. What used to bound this was the semaphore, by accident: leak the only slot and the node provisions zero further macOS VMs, so at most one guest could ever be stranded. Releasing the slot is precisely what removed that accidental cap — an abandoned VM is untracked and holds no slot, so MaxMacOSVMs does not charge for it either. A repeatably-wedging guest would therefore keep provisioning until Virtualization.framework refused (it allows only about two concurrent macOS guests on Apple Silicon) or the host OOMed. So the bound is explicit now. abandonedMacVMs counts VMs whose teardown was walked away from, keyed per attempt, charged in abandonVM and discharged if the stop ever does return (a Vz stop can be merely slow; a node that recovers must not need a restart to serve macOS again). At defaultMacAbandonedVMCap (2) the macOS pool refuses to provision, logging at Error with the count, the cap and what to do about it. The gate is checked before the semaphore wait and again after it, for the same reason the #154 cordon is re-checked in admitDispatch: a dispatch can be parked on a full pool for the entire life of the job ahead of it, which is exactly the window in which a teardown gets abandoned. Rejection follows the #154 cordon convention exactly: clear the pending stamp, leave the seen stamp to age out via seenTTL, leave the job queued on the platform so a healthy node can take it immediately. Observability: status and /healthz gain abandoned_macos_vms and abandoned_macos_vm_cap next to the held_slots fields, with abandoned_macos_vm_details on /healthz (job id, VM instance id, reason, age). held_slots showed the outage; this shows what the fix for it costs. proto fields are new numbers (10, 11); nothing existing moved. #178's deadline and force-stop are unchanged and #151's busy-veto is untouched. Tests, each verified to fail with its fix reverted: - TestSweepOrphanRunners_WedgedMacOSVMCannotBlockTheEventLoop — reverted: "sweepOrphanRunners did not return within 5s". - TestHandleCompleted_WedgedMacOSVMCannotBlockTheHandler — reverted: "handleCompleted did not return within 5s". - TestDrain_WedgedMacOSVMCannotBlockShutdown — reverted: "drain did not return within 10s". - TestMacOSPoolCordonsPastTheAbandonedVMCap — with the cordon disabled it provisioned a second VM past the cap and stranded two guests; also proves the cordon lifts when an abandoned stop finally returns. - TestHandleMacOSJob_DeadlinePathStopsTheVMExactlyOnce — with the skip removed: "Stop called 2 times", and AbandonedMacOSVMs()=2 for ONE wedged VM, i.e. a single wedge consuming the node's whole abandoned budget. - TestStatusAndHealthzReportAbandonedMacOSVMs. All deadline-guarded, so a regression is a failure rather than a hang.
…nce id Releasing the macOS slot before teardown (#196) opened a same-job re-dispatch race, and the comment that said it was safe had the invariant exactly backwards. The comment claimed: "every VM, its clone, and its shared directory are keyed by job ID, so a fresh dispatch cannot touch anything this teardown still owns." Everything being keyed by job ID is not what makes a fresh dispatch safe — it is precisely what makes it collide. Nothing carried a per-attempt discriminator: jobDir <data>/vm/macos/jobs/<jobID> (macosvm_darwin.go:49) clonePath <data>/vm/macos/jobs/<jobID>.img (macosvm_darwin.go:93) auxPath <data>/vm/macos/jobs/<jobID>.aux (macosvm_darwin.go:94) artifacts artifacts.ArtifactsDir(dataDir, jobID) and the failure paths now call unsee() — which clears BOTH seen and pending — before teardown, so the same job ID can immediately re-enter handleQueued. The poll re-emits a still-queued job about every 30s (webhook mode gets there via the catch-up poll or a redelivery), admitDispatch admits it, and maxProvisionAttempts allows several passes. The sequence: attempt 1 hits the provisioning deadline, releases the slot, and walks away from a Stop() still wedged in Virtualization.framework — its guest is alive with the .img and .aux files open. Attempt 2 takes the freed slot and apfsCopies over those same files, then writes its JIT config into the same share. Minutes later attempt 1's abandoned stop returns and runs os.Remove(clonePath) + os.Remove(auxPath) + os.RemoveAll(jobDir) (macosvm_darwin.go:851-865), deleting attempt 2's running disk and its .jit_config. Attempt 2's runner can never register, so it times out on its own deadline and strands another guest doing it. Self-sustaining, and the same applies to artifacts.Cleanup(artifactsDir) on every error branch. Approach. Two were available: refuse to re-provision a job ID that has an abandoned-but-unconfirmed-dead VM, or give each attempt disjoint paths. The second is smaller and provably safe — disjointness is a property of the names, not of a check somebody has to remember to keep correct — and it is strictly better for availability, since attempt 2 actually runs instead of waiting on a guest that may never die. It also needs no change to pkg/vm/macosvm_darwin.go: darwinMacOSVM derives every path it owns from the id string the scheduler hands NewMacOSVM, and that id is used for nothing but paths and log fields. So macVMInstanceID(jobID) returns "<jobID>-<4 random hex bytes>". The job id stays in the name because it is what an operator greps for; the suffix is what makes attempts disjoint. Random rather than a counter so a daemon restart cannot re-issue an id whose files are still on disk from before it. The same id keys the artifacts dir, is stored on runningJob.macVMID, and is what every teardown site reports to the abandoned-VM registry, so the log and status name the specific VM rather than just the job. The new invariant, and the corrected comment: a fresh dispatch of the same job ID is safe not because paths are shared-but-unreachable, but because every path a teardown touches belongs to ONE attempt — the per-attempt VM instance id (share, clones, artifacts) or the per-claim runner name (ReleaseJob) — so a late teardown can only ever delete its own files. Tests, verified by reverting macVMInstanceID to fmt.Sprintf("%d", jobID): - TestHandleMacOSJob_RedispatchOfTheSameJobGetsDisjointResources drives two attempts at one job ID through handleMacOSJob against a fake VM that creates real files under the darwinMacOSVM layout and deletes them in Stop(). Reverted, it reports the shared id and then: "attempt 2's JIT config after attempt 1's late teardown is gone (.../vm/macos/jobs/100817345293/.jit_config)" "attempt 2's disk clone after attempt 1's late teardown is gone (.../vm/macos/jobs/100817345293.img)" which is the production failure, reproduced. - TestMacVMInstanceIDDiscriminatesAttempts — reverted: "instance id \"100817345293\" does not lead with the job id" (no suffix at all). NOTE FOR MAC-SIDE VERIFICATION: pkg/vm/macosvm_darwin.go is darwin-only cgo and does not build here, so it is deliberately untouched. The change relies on its documented behaviour that jobDir/clonePath/auxPath derive from the constructor's id argument and nothing else parses those names.
…easeJob Nothing in the suite tested the ORDER of the release and the teardown, only that the slot came back eventually. Delete the explicit slot.release() on the macOS provisioning-failure path or in the job wait-goroutine, lean on the deferred backstop instead, and everything still passed — because every teardown bound is compressed to 50ms in tests and mockProvider.ReleaseJob returns instantly, so "released now" and "released at function exit" look identical. In production they are not remotely identical. What stands between the job ending and the next macOS job starting on the backstop-only version is a VM stop that may never return plus a GitHub API call issued on context.Background() with no deadline at all. That gap is the whole subject of issue #196; a test suite that cannot see it will not stop it coming back. mockProvider gains a releaseHook that runs inside ReleaseJob, so a test can hold the provider call open and assert on the semaphore WHILE the teardown is still in flight. TestSlotIsFreeWhileTeardownIsStillInFlight uses it on both paths that matter. Verified by reverting each release in turn: - drop slot.release() on the provisioning-deadline path: "macSem held=1 while the ghost-runner deregistration was still in flight, want 0" - drop slot.release() in the wait-goroutine after untracking: "macSem held=1 while the finished job's runner was still being deregistered, want 0" Both pass with the release restored, and both are deadline-guarded so a regression fails rather than hangs.
|
All six findings fixed — four commits pushed ( MAJOR 1 — every macOS teardown is now bounded. MAJOR 2 — per-attempt VM instance id. MAJOR 3 — abandoned-VM registry with a cap. Charged on abandon (with a non-blocking re-check so a stop landing in the race isn't charged), discharged when a slow stop finally returns, cap 2 (Vz allows ~2 concurrent guests on Apple Silicon and each stranded one holds its full RAM). At the cap Minors: leak escalation is now pool-scoped ( Revert-verified — every fix observed failing without it. Two worth quoting. The event-loop one, which I re-ran myself: And MAJOR 2's, which reproduced the production failure:
Needs Mac-side confirmation: |
|
Round 2 review: safe to merge. All three MAJORs verified fixed, not just claimed:
Lock ordering proven acyclic; proto fields 7–11 are additive with no tag removed; mayfly's Merging for v0.2.11. Follow-ups, none blocking:
|
1 participant
Fixes #196. The mac node served zero macOS jobs for ~28 hours while reporting
status: ok,active_jobs: 0,/healthz200 — every queued macOS job sat until GitHub cancelled it at the 24h timeout.The actual mechanism (sharper than the issue's first guess)
The issue supposed the force-stop reclaimed the VM but skipped the release. It's more specific:
waitForMacRunnerBoundednever returned.That
<-resChis unbounded, and its comment encodes an assumption that failed on metal — the log showsmacOS VM did not stop gracefully, forcing: the guest ignored the stop, soWaitForRunnernever unwound and the function parked forever, still holdingmacSem. Decisive evidence is negative:handleMacOSJob's error branch logsmacOS VM runner not reachable, and that line never appears anywhere in the 28-hour window.A second, independent leak on the same path: the error branch calls
macVM.Stop()again before<-s.macSem, anddarwinMacOSVM.StopisstopOnce.Do— a second caller blocks until the first returns. So even with the first bug fixed, the retry would hang on the wedged Stop while holding the slot. Both are fixed; both are pinned by tests.With
max_concurrent = 1the pool was then permanently unable to admit work, and because the job was already untracked,len(s.running)was 0 — so every health signal read healthy. Nothing logs when a dispatch blocks on the semaphore, which is why the log went silent apart from token refreshes.Fix
Follows #190's precedent (never couple slot release to teardown): the VM stop runs off-thread (
stopVMAsync), the unwind is bounded (awaitUnwind), and the slot is released before teardown on every macOS path. All three dispatch paths now share one idempotentslotTokenso a token and a bare<-s.semcan't coexist in the same function. If a wedged Vz stop never returns, that one goroutine is leaked deliberately — the correct trade against pinning a pool's only slot — and it's logged.Sibling leak also fixed: the macOS wait-goroutine released via
defer <-s.macSemat the very end, behindStop()(15s graceful, unbounded when wedged) and aReleaseJobGitHub call with no deadline. Same delay class #190 fixed for local/linux. Audit result: Windows has no separate path (it useshandleLocalJob, already correct); retry/reprovision paths re-enter viahandleQueuedand never acquire directly. Post-fix there are exactly 3 acquires, all viaacquireSlot, and zero bare channel drains.Observability — the reason this hid for 28h
held_slots/slot_capacity/ per-poolslotsadded to/healthz, theStatusRPC, andephemerd status(additive only; existing fields untouched).held == capacitywithactive_jobs: 0is the outage, visible at a glance — previously indistinguishable from idle.waiting for a free concurrency slot pool=… held=… capacity=… tracked_jobs=…), repeating every 5m, escalating to ERROR (suspected slot leak) once blocked ≥15m with slots held and nothing tracked. Uncontended acquires take a fast path and are provably silent (tested).Testing
13 new tests in
pkg/scheduler/slots_test.go, all deadline-guarded so a regression fails rather than hangs. The key one uses awedgedMacVMwhoseWaitForRunnerandStopnever return — the existingblockingMacVMunblocked onStop, i.e. it encoded the very assumption that failed in production.TestHandleMacOSJob_ReleasesExactlyOncePerOutcomechecks deadline/create-failure/cancel/success and asserts capacity in both directions, so a missed release (starvation) and a double release (over-fill) both fail.Verified by reverting the fix and re-running — both the author and I did this independently:
go vetclean;pkg/scheduler+cmd/ephemerdsuites green. Proto regenerated with the repo's exact protoc 3.14.0 / protoc-gen-go v1.25.0 (byte-identical regen confirmed before editing).Caveats
pkg/vm/macosvm_darwin.gois unchanged, and all slot logic lives inpkg/scheduler, which compiles and tests cross-platform against thevm.MacOSVMinterface — butGOOS=darwinvet can't run here (cgo/vz), so the darwin side isn't typechecked on this box. No-raceeither (no cgo); worth a CI race pass. Mac-side smoke test should confirm: happy path unchanged; a forced wedge now reachesmacOS VM runner not reachable(the line missing in production) and the next job provisions; andheld_slotsreturns to 0 after.