Startup convergence still strands a VM in five paths after a vk restart (fault-injection follow-up to #55/#56/#57)

[tonicmuroq]

Fault-injection pass over the startup-convergence work from #55 / #56 / #57 (follow-up to #54). Most of it holds up; five paths still leave a VM stranded after a vk restart, and four of them cannot recover without manual intervention.

None of them lose guest state — every recovery below was verified with a marker-file ledger inside the guest (a uniquely-named file created before each hibernate, listed after each wake), and all nine markers survived every wedge. These are availability bugs.

Setup

vk-cocoon	v0.3.5-4-g40d80bb (rev 40d80bbb64e2d70ca9d90cafcee5978b909ac2c1)
cocoon	v0.5.7-2-g0ba410f (rev 0ba410f1b8f553070364901a7a9e994ebfa3df18) — reconcile-stale-create exists only on master, not in any release
Guest	cloud-hypervisor + Windows, drop-NIC class, DHCP

Note on method, because it decides the outcome: systemctl stop / systemctl restart and kill -KILL <MainPID> leave different damage. Under stop/restart the in-flight cocoon child dies within 1s — not from systemd (KillMode=process only stops systemd sweeping the cgroup) but from vk itself, since signal.NotifyContext(SIGINT, SIGTERM) cancels the ctx and every cocoon call is exec.CommandContext. Under kill -KILL nobody kills the child: the in-process watchdog never runs, and the child lingers ~4s before dying on its next write to the closed stdout/stderr pipe. RestartSec=5s sits inside that lag, which is what makes problem 1 reachable. (systemctl kill defaults to --kill-who=all and kills the child too, hiding the race — signal the main PID directly.)

1. watchBusyCreate never re-invokes the reclaim verb — VM never recovers

Trigger: kill -KILL on vk while cocoon vm clone is in flight (any crash: OOM, node failure). Reproduced twice.

reconcileStaleCreates runs once, at startup. The clone child is still alive at that instant, so cocoon vm reconcile-stale-create answers busy and the record goes to watchBusyCreate. The child then dies. That loop only calls Runtime.Inspect; it never re-invokes the verb. creating satisfies inFlightCreate(), so it polls until defaultDeferredRecheckBudget (30 min) expires, logs did not leave creating within budget; giving up, and abandons the record — which still owns the VM name.

stale_create_reconcile_total{outcome="busy"} 1
Error: reserve VM record: vm name "vk-staging-cocoonset-vm-XXXX-0" already exists (id: NMA2LDSIW5ZIM54D4UMFSDYTR5)   # every CreatePod retry
wake_total{result="failed"} → 33 and climbing
CocoonSet=Failed, pod=Pending, no VMID, no IP

#55 did not remove this deadlock, it moved it one race window later.

Fix direction: the poll loop must periodically re-invoke the verb. Only the verb distinguishes "owner still alive" from "owner died leaving the record in creating" — VM state alone cannot.

Escape hatch: cocoon vm reconcile-stale-create <VMID> -o json → {"outcome":"collected"}, after which the next CreatePod retry succeeds.

2. An interrupted snapshot save leaves the guest paused at the hypervisor level

Trigger: systemctl stop (or restart) while cocoon snapshot save is in flight — i.e. the everyday operational path.

snapshot save pauses the guest, dumps memory, resumes. Cut in the middle, cloud-hypervisor stays Paused forever. dispatchOwedWork correctly re-enters hibernate (startup_resume_total{op="hibernate"}=1, WRN resuming interrupted hibernate), but every attempt dies on the first step:

ERR drop NIC pre-hibernate ...: cocoon vm net <ID>: exit status 1
    (output: Error: vm is paused (snapshot or hibernate in flight); retry after it completes)
hibernate_total{phase="netresize",result="failed"}     # +1 per attempt
hibernate_total{phase="dhcp_release",result="failed"}  # guest exec also fails, exit -1

Two things make this hard to diagnose: cocoon vm inspect reports state: running while the hypervisor reports Paused, and cocoon vm has no pause/resume subcommand. snapshots__records / __names / __tombstones were all empty, so this is not a pending-snapshot name lock.

Fix direction: probe the hypervisor state before re-entering hibernate() and unpause first, or make dropNICForHibernate self-heal on vm is paused. Separately, cocoon vm inspect should report Paused honestly.

Escape hatch:

S=/var/lib/cocoon/run/cloudhypervisor/<VMID>/api.sock
sudo curl -s -X PUT --unix-socket $S http://localhost/api/v1/vm.resume   # 204

3. A save killed mid-flight leaves a snapshot the retry cannot replace

Trigger: kill -KILL 6s into cocoon snapshot save. The orphaned child survives and finishes the save (snapshot landed 2s after vk died). The resumed hibernate then fails on every attempt:

Error: save snapshot: snapshot name "vk-staging-cocoonset-vm-XXXX-0" already in use by MPT5A6ZS2FNZWQGFN24AZLREWQ

SnapshotSave's recovery branch keys on the substring already exists; cocoon says already in use by, so the rm-and-retry never engages.

But the trigger is not simply "a same-named snapshot exists." Killing vk 28ms after the save child exited cleanly leaves an equally same-named finalized snapshot, and there the resumed save succeeded on the first try and replaced it — no error, no retry. So something about the record a save leaves when its parent dies mid-flight makes it non-replaceable, while a cleanly-exited save's record is replaceable. I did not trace this into cocoon's source, so please don't treat the already exists branch as dead code on the strength of the first case alone.

Fix direction: broaden the match to cover already in use by, and make the recovery rm by ID rather than by name (a name lookup cannot resolve a half-committed record). Worth understanding the record-state difference before settling on the fix.

Escape hatch: cocoon snapshot rm <name> by hand for the finalized case; the retry then succeeds immediately.

4. A hibernate owed on a crashed VM is never dispatched

#56's commit message states "a hibernate owed on a crashed VM boots it first instead of never firing". That did not happen.

Trigger: stop vk during dropNICForHibernate (hibernate owed, no save has run yet), kill -9 the cloud-hypervisor process so the record goes to stopped, then start vk.

startup_resume_total          # NO SAMPLES AT ALL — the resume was never dispatched
ERR drop NIC pre-hibernate ...: cocoon vm net <ID>: exit status 1
    (output: Error: vm is not running: vm <ID> pid 42405 not cloud-hypervisor: vm not running)
hibernate_total{phase="netresize",result="failed"} 14
hibernate_total{phase="dhcp_release",result="failed"} 14

CocoonSet ended Failed, no ResumeStartFailed event. The VM was never started. Start itself is fine — a manual cocoon vm start <ID> brought it back first try, and after clearing lifecycle-state=failed the hibernate completed normally (netresize / snapshot / push / remove all ok).

Fix direction: the guard exists in dispatchResume but the path was not entered. Worth checking whether handleVMGone, or the adoption of a stopped record, drops the pod from the tracked table before dispatchOwedWork reads it.

5. lifecycle-state=failed parks the pod, and silently blocks unrelated operations

Every failure above converges here: after a few retries vk writes lifecycle-state=failed, and then nothing drives the pod — the resume no longer fires and the operator leaves a non-terminal pod alone. Recovery needs the annotation deleted by hand.

It also blocks operations that have nothing to do with the original failure. A leftover failed from an earlier test made a subsequent spec.nodeName patch a no-op: the CocoonSet sat in Failed, the migration never started, and neither the vk nor the operator log said why. Removing the annotation let the migration begin immediately.

Fix direction: whatever writes failed should also define how the pod leaves that state. Fixing 1–4 without this still leaves an operator-only exit.

What held up

Worth recording so the fixes don't regress it:

• create interrupted (vm clone in flight) + systemctl restart → record reclaimed (outcome="collected"), VM recreated, exactly one VM, orphan_vm_total=0
• delete interrupted (vm rm --force in flight, 144ms in) + systemctl restart → VM/pod/CocoonSet all gone, unrelated snapshots untouched
• wake interrupted by systemctl restart, and by kill -KILL 28ms after the clone committed → both recovered; the latter went through classify_drop_nic correctly
• push interrupted (kill -KILL 28ms after the save child exited) → resume re-saved, re-pushed, settled Suspended
• post-clone-state=running → {op="post_clone"}; =done → {op="ready_wait"}; =failed → correctly parked with zero dispatch; empty lifecycle-state with a marker present → still dispatched
• post-clone marker dies with its VM incarnation (a hand-injected stale done was gone after the hibernate)
• resume claim mutual exclusion works: a counter-operation inside the claim window is rejected with ProviderUpdateFailed: resumed operation still in flight for <ns>/<name> and succeeds on retry once released. Note this surfaces only as a pod event, not a log line
• double restart: the in-flight resume logged post-clone setup canceled after 1.745s (provider shutdown), the new process re-derived the same owed work from the annotations and completed. No double execution, no skipped work
• classify_drop_nic budget exhaustion (tested with a local build cut to 25s, AR blocked via /etc/hosts): ResumeClassifyFailed fired at exactly the budget and the error carries (refusing fresh boot) — the fail-closed contract holds
• bounded fan-out: startup reconcile: 10 pods adopted 28 ms after process start. startupFanOut=8 is not a bottleneck at this scale
• cross-node migrate with the source-side push interrupted: resume re-ran hibernate, old pod deleted, recreated on the target, VM live; pull 38.6s, vm_boot{mode=clone} 115.7s including a cold base pull

Coverage gap worth flagging

The #54 protection that matters most — never fresh-boot over a hibernate snapshot — has no end-to-end coverage from outside vk-cocoon, and hibernate_evidence_total stayed all-zero through every run. Three mechanisms block it:

1. the operator always stamps restore-from-hibernate when it recreates the pod of a suspended CocoonSet, so CreatePod short-circuits before deriveRestoreFromEvidence;
2. deleting the CocoonSet also deletes the registry :hibernate tag, so "keep the tag, drop the pod" is not reachable that way;
3. a hand-built pod is rejected by admission (pods.mutate.cocoonstack.io: cocoon pods must be managed by a CocoonSet).

gcloud artifacts docker tags add also refuses to copy a tag across image names inside one repository, so the tag cannot be cloned onto a spare VM name. This needs in-repo tests. The same applies to the created-state trap and the not-creating race, which need millisecond-scale timing.

Related: the image identity guard lives only in deriveRestoreFromEvidence, so an operator-set marker skips it. Changing spec.agent.image while a :hibernate snapshot exists restored the old image with no event and no metric.

Observability

Small things that made every diagnosis above harder than it needed to be:

• stale_create_reconcile_total, startup_resume_total and hibernate_evidence_total are process-local, so they reset on the very event they describe. Anything that wedges across a restart is invisible unless scraped in the window.
• Both wedges emit log lines only — no Kubernetes event, no dedicated metric. Nothing outside the node can tell a VM is stuck.
• wake_total{result="failed"} is inflated by the CreatePod retry storm (33 in one wedge), so wake success rate is not trustworthy after any create failure.
• classifyNICRecovery calls hibernateEvidence directly, so the evidence lookup on the resume path is not counted on hibernate_evidence_total at all.

[tonicmuroq]

Update: four of the five paths are fixed, one is deferred

All fixes were re-verified by re-running the original fault injections against fresh builds on internal-cocoon-node-7 (vk-cocoon v0.3.5-4-g40d80bb + cocoon v0.5.7-2-g0ba410f, both with the patches applied). The guest marker ledger was checked after every wake and stayed intact throughout, so nothing below traded availability for data.

#	Path	PR	Verified
1	watchBusyCreate never re-invokes the reclaim verb	#59	stale_create_reconcile goes busy=2 → collected=1; the record resolves in 6s
2	An interrupted snapshot save leaves the guest paused	cocoonstack/cocoon#176	hibernate_total{netresize,ok}, hibernate runs to Suspended
3	A save killed mid-flight leaves an unreplaceable snapshot	#60 + cocoonstack/cocoon#177	1 attempt, snapshot_save_total{ok}=1, no lifecycle-state=Failed write
4	A hibernate owed on a crashed VM is never dispatched	#59	startup_resume_total{hibernate}=1, VM boots, hibernate completes
5	lifecycle-state=failed parks the pod	—	deferred, see below

1 — watchBusyCreate re-invokes the verb (vk-cocoon#59)

The poll loop now calls ReconcileStaleCreate each tick and short-circuits on collected/not-found. It stays additive: a record that reaches running is still adopted whatever the verb answers, so a verb that keeps failing cannot strand a committed clone — an earlier verb-only draft regressed exactly that case.

Reproducing it needed a shortened RestartSec. With the default 5s the orphaned clone child usually dies first, the verb answers collected on the first call, and the bug is not reachable. That is worth knowing for any regression test: the window is "vk is back before the orphaned child dies".

07:20:24  placeholder CLADJ… is owned by an in-flight operation; watching for commit
07:20:25-29  CreatePod retries: reserve VM record: vm name … already exists (id: CLADJ…)
07:20:30  in-flight create CLADJ… resolved as collected; CreatePod recreates

2 — the orphaned pause is converged (cocoon#176)

ensureNotPaused became convergeOrphanedPause: it resumes and returns a re-read vm.info. This is safe rather than optimistic — every pause window in cocoon runs under the VM ops lock end to end (prepareSnapshot, prepareRestore), clone resumes a record still in creating which runningVMClientWithRecord rejects, and all three ensureNotPaused callers already hold that same lock. A caller holding the lock therefore cannot be racing a live capture.

Note pauseVM already carried the mirror-image fix ("swallows CH's Paused→Paused 500 so a stuck-paused VM recovers"). The capture path anticipated stuck-paused VMs; the device path did not.

3 — the held name is now recoverable (vk-cocoon#60 + cocoon#177)

The open question in the original report is resolved: the already exists branch was never dead code — it was firing and working. The two rejections come from lookups that disagree about pending records:

	lookup	sees a pending holder	wording
save preflight EnsureSnapshotNameFree	Inspect → lookupRecord, which rejects r.Pending	no	already exists
store insertRecord	raw name index	yes	already in use by <ID>

So a cleanly-exited save leaves a finalized holder, the preflight catches it, and vk's rm-and-retry recovers silently — which is why it looked like a first-try success in the logs. A SIGKILLed save leaves a pending holder that is invisible to the preflight, so the save runs the entire capture and only then fails on a string vk did not match.

Three changes: vk matches both phrases, removes by the holder's ID parsed from the message (name resolution is not guaranteed to reach a pending record), and cocoon's preflight now reads the name index so the rejection lands in under a second instead of after a multi-GB dump.

A fourth issue only showed up once the first three were in: the rm then raced the dead save's own child. vk kills its cocoon children by cancelling their context, which never happens under SIGKILL (KillMode=process leaves the cgroup alone too), so the child outlives vk by seconds holding the snapshot's flock. snapshot rm uses a non-blocking TryLock and refused outright:

name held by XY7T3JIQHJ25KUVDJCJK5V3OSL and rm failed:
  Error: rm: snapshot XY7T… is in use by an active clone/restore/export

The flock is correct here — it is owned by the fd, so "lock held" is exactly equivalent to "that save process is still alive", with no timeout involved. The bug was vk treating a self-clearing transient as terminal. The wait now lives inside SnapshotSave (lease-held refusal retried up to 30s; every other rm failure still reported on the first attempt), which took it from 3 attempts / 2 Failed writes to 1 attempt / 0.

Two diagnostic warts found on the way, not addressed: the refusal names the read holders (clone/restore/export) while an interrupted save's build lease reports identically, and <ID>.lease files are deliberately never deleted (removing the inode would split exclusion for a live waiter), so they accumulate — node-7 had 33 for 1 live snapshot, 0 bytes each.

4 — the boot is now unconditional (vk-cocoon#59)

dispatchResume no longer gates Start on the VM state from the startup List snapshot. Start is idempotent (PrepareStart no-ops on a live VM and converges a crashed one via convergeCrashedStart), so gating on a stored field buys nothing.

A correction to the original report. It claimed the record "still reads running after a SIGKILLed VMM" and that this is why Start was skipped. The first half is supported — runningVMClientWithRecord's pid %d not cloud-hypervisor branch is only reachable when rec.State == running, so that state does occur — but on the verification run the record read stopped, which the old guard also handled. So this run does not isolate the guard as the cause, and the record's post-kill state is evidently not deterministic. The change is still right (it removes the dependence on a field that can lie either way), but the original observation of startup_resume_total having no samples at all remains unexplained.

Not fixed

Problem 5 — lifecycle-state=failed parks the CocoonSet. Deferred deliberately; the fix is operator-side and changes reconcile behaviour for every VM in the cluster.

The mechanism is confirmed: cocoonset/reconciler.go returns on a terminal main pod before the suspend branch, reconcileMigration, reconcileWake, applyUnsuspend and createMainAgent. handleFailedMainAgent's only escape is pod-spec drift, and podSpecMatchesAgent does not compare spec.NodeName (node placement belongs to migration), so a pinned set has no path to its target node at all — and neither log says why.

None of the 11 sites that write the annotation is a terminal verdict; they all mean "this attempt failed" (drop-NIC failed, DHCP wait timed out, an AR push blipped). It is sticky within a generation, so one transient failure parks the set indefinitely.

The obvious fix — demote it to a report and let explicit intent through — has a landmine. The branches below the early return skip terminal pods on the stated assumption that "terminal pods carry no VM state", which is false for a failed hibernate: the VM is still live and unsnapshotted. Letting everything through would let a set report Suspended with a running, unsaved VM. That needs its own decision, so the local change is narrowed to letting migration take its turn, and is not proposed here yet.

Also unaddressed:

• The retry loop that recovers from a failure is the failure record itself. Attempts 2 and 3 in the problem-3 run came through UpdatePod, driven by vk's own failOp → markLifecycleState(Failed) → pod patch → informer → UpdatePod. The operator logged nothing for that pod in the window. So failure recovery is currently emergent, not designed; anything that changes how failed is written or re-delivered can remove it silently. (Problem 3's fix no longer depends on it, but the other paths still do.)
• The evidence-path coverage gap and the image-guard asymmetry from the original report — still no end-to-end coverage, still needs in-repo tests.
• All four observability gaps from the original report, including that the three new counters are process-local and reset on the very event they describe.