diff --git a/docs/metrics.md b/docs/metrics.md index 3e48560..8d27eb5 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -51,7 +51,7 @@ Prometheus endpoint with vk-cocoon-specific metrics: | `cocoon_vk_vm_inspect_transient_fail_total` | Counter | Transient VM inspect failures tolerated by the status refresher | | `cocoon_vk_pod_evict_failure_total` | Counter | Failed pod evictions | | `cocoon_vk_reconcile_adopt_by_name_total` | Counter | Startup reconcile adoptions matched by VM name | -| `cocoon_vk_stale_create_reconcile_total{outcome}` | Counter | Creating placeholders routed through the stale-create verb at startup (`outcome=collected\|busy\|not-creating\|not-found\|error`) | +| `cocoon_vk_stale_create_reconcile_total{outcome}` | Counter | Stale-create verb attempts by startup reconcile and its bounded watcher (`outcome=collected\|busy\|not-creating\|not-found\|error`) | | `cocoon_vk_hibernate_evidence_total{verdict}` | Counter | Fresh boots intercepted by hibernate evidence (`verdict=restored\|image_conflict\|source_conflict\|unavailable`) | | `cocoon_vk_startup_resume_total{op}` | Counter | Interrupted operations re-dispatched by startup reconcile (`op=hibernate\|post_clone\|ready_wait\|classify_drop_nic`) | diff --git a/docs/reconcile.md b/docs/reconcile.md index b7472ac..6f9e6d6 100644 --- a/docs/reconcile.md +++ b/docs/reconcile.md @@ -17,10 +17,13 @@ On every restart vk-cocoon: deadlocks its pod. `collected`/`not-found` free the name for a clean recreate; `busy` (an in-flight clone still owns the record) and transient verb or inspect errors hand the record to a bounded - background watcher that indexes it for adoption once it reaches - `running`, or applies the orphan policy if it dies without ever - running; a record that already left `creating` is adopted only when - `running`. Outcomes are counted on + background watcher. Each watcher tick re-invokes the verb: + `collected`/`not-found` free the name for a clean recreate; otherwise + an inspect indexes a committed `running` VM or applies the orphan + policy to a terminal record. An unresolved `creating`/`created` state + or transient error remains under bounded retry. A record that already + left `creating` is adopted only when `running`. Every verb attempt is + counted on `cocoon_vk_stale_create_reconcile_total`. 4. Adopts each pod with a `vm.cocoonstack.io/id` annotation by matching the VMID against the runtime list. diff --git a/provider/cocoon/create_test.go b/provider/cocoon/create_test.go index e3af2a4..34e9da7 100644 --- a/provider/cocoon/create_test.go +++ b/provider/cocoon/create_test.go @@ -1689,6 +1689,10 @@ type fakeRuntime struct { netResizeCalls []netResizeCall netResizeErr error + // netResizeNeedsStart fails NetResize until Start ran — a dead VMM whose record still reads running. + netResizeNeedsStart bool + + startCalls []string // mu guards snapshots, imagesPresent, and the call ledgers so // singleflight tests can drive concurrent ensure* callers under -race. @@ -1704,8 +1708,10 @@ type fakeRuntime struct { onRemove func() staleCreateOutcomes map[string]vm.StaleCreateOutcome // by vmID; absent → collected - staleCreateCalls []string - staleCreateErr error + // staleCreateSeq is consumed per vmID before staleCreateOutcomes — scripts an owner that exits mid-watch. + staleCreateSeq map[string][]vm.StaleCreateOutcome + staleCreateCalls []string + staleCreateErr error // onExec, when set, fires at Exec entry — lets tests block or mutate state mid-exec. onExec func() removeErr error @@ -1780,10 +1786,16 @@ func (f *fakeRuntime) Remove(_ context.Context, vmID string) error { } func (f *fakeRuntime) ReconcileStaleCreate(_ context.Context, vmID string) (vm.StaleCreateOutcome, error) { + f.mu.Lock() + defer f.mu.Unlock() f.staleCreateCalls = append(f.staleCreateCalls, vmID) if f.staleCreateErr != nil { return "", f.staleCreateErr } + if seq := f.staleCreateSeq[vmID]; len(seq) > 0 { + f.staleCreateSeq[vmID] = seq[1:] + return seq[0], nil + } if o, ok := f.staleCreateOutcomes[vmID]; ok { return o, nil } @@ -1899,7 +1911,12 @@ func (f *fakeRuntime) ImageImport(ctx context.Context, name string) (io.WriteClo return nopWriteCloser{}, wait, nil } -func (f *fakeRuntime) Start(_ context.Context, _ string) error { return nil } +func (f *fakeRuntime) Start(_ context.Context, vmID string) error { + f.mu.Lock() + defer f.mu.Unlock() + f.startCalls = append(f.startCalls, vmID) + return nil +} type netResizeCall struct { vmID string @@ -1911,6 +1928,9 @@ func (f *fakeRuntime) NetResize(ctx context.Context, vmID string, target int) er return err } f.netResizeCalls = append(f.netResizeCalls, netResizeCall{vmID: vmID, target: target}) + if f.netResizeNeedsStart && len(f.started()) == 0 { + return fmt.Errorf("cocoon vm net %s: vm is not running: vm not running", vmID) + } return f.netResizeErr } @@ -1977,6 +1997,18 @@ func (f *fakeRuntime) registerSnapshot(name string) { f.snapshots[name] = &vm.Snapshot{Name: name} } +func (f *fakeRuntime) staleCalls() []string { + f.mu.Lock() + defer f.mu.Unlock() + return slices.Clone(f.staleCreateCalls) +} + +func (f *fakeRuntime) started() []string { + f.mu.Lock() + defer f.mu.Unlock() + return slices.Clone(f.startCalls) +} + type nopWriteCloser struct{} func (nopWriteCloser) Write(p []byte) (int, error) { return len(p), nil } diff --git a/provider/cocoon/reconcile.go b/provider/cocoon/reconcile.go index 8e9ac1b..ef60d3f 100644 --- a/provider/cocoon/reconcile.go +++ b/provider/cocoon/reconcile.go @@ -124,29 +124,18 @@ func (p *Provider) reconcileStaleCreates(ctx context.Context, vms []vm.VM) []vm. } g.Go(func() error { outcome, err := p.Runtime.ReconcileStaleCreate(ctx, v.ID) + recordStaleCreateOutcome(outcome, err) if err != nil { - metrics.StaleCreateReconcileTotal.WithLabelValues("error").Inc() logger.Errorf(ctx, err, "reconcile creating placeholder %s (%s); watching for commit", v.ID, v.Name) p.watchBusyCreate(v.ID) return nil } - metrics.StaleCreateReconcileTotal.WithLabelValues(string(outcome)).Inc() switch outcome { case vm.StaleCreateNotCreating: - fresh, inspectErr := p.Runtime.Inspect(ctx, v.ID) - switch { - case errors.Is(inspectErr, vm.ErrVMNotFound): - // Gone between the verb and the inspect. - case inspectErr != nil: - logger.Errorf(ctx, inspectErr, "re-inspect %s after not-creating; watching for commit", v.ID) + if fresh, settled := p.classifySettledCreate(ctx, v.ID); !settled { p.watchBusyCreate(v.ID) - case fresh.State == vm.StateRunning: + } else if fresh != nil { keep[i] = fresh - case inFlightCreate(fresh.State): - p.watchBusyCreate(v.ID) - default: - logger.Warnf(ctx, "placeholder %s (%s) left creating as %s without running; applying orphan policy", v.ID, v.Name, fresh.State) - p.handleOrphan(ctx, fresh) } case vm.StaleCreateBusy: logger.Warnf(ctx, "creating placeholder %s (%s) is owned by an in-flight operation; watching for commit", v.ID, v.Name) @@ -167,8 +156,9 @@ func (p *Provider) reconcileStaleCreates(ctx context.Context, vms []vm.VM) []vm. return kept } -// watchBusyCreate polls an unclassified creating record: the event watcher -// only reacts to deletions and stops, so a clone that commits is invisible. +// watchBusyCreate re-invokes the reclaim verb on an unclassified creating +// record: only the verb tells a live owner from one that died holding the +// name, and nothing else re-delivers either outcome. func (p *Provider) watchBusyCreate(vmID string) { p.goBackground(func() { ctx := p.lifecycleCtx @@ -179,21 +169,24 @@ func (p *Provider) watchBusyCreate(vmID string) { if !commonk8s.SleepCtx(ctx, delay) { return } - v, err := p.Runtime.Inspect(ctx, vmID) - switch { - case errors.Is(err, vm.ErrVMNotFound): - return - case err == nil && v.State == vm.StateRunning: - logger.Infof(ctx, "in-flight create %s (%s) committed; indexing for adoption", vmID, v.Name) - p.indexOrphanByName(v) + outcome, err := p.Runtime.ReconcileStaleCreate(ctx, vmID) + recordStaleCreateOutcome(outcome, err) + if err != nil { + logger.Errorf(ctx, err, "re-reconcile creating placeholder %s", vmID) + } else if outcome == vm.StaleCreateCollected || outcome == vm.StaleCreateNotFound { + logger.Infof(ctx, "in-flight create %s resolved as %s; CreatePod recreates", vmID, outcome) return - case err == nil && !inFlightCreate(v.State): - logger.Warnf(ctx, "in-flight create %s (%s) ended %s without running; applying orphan policy", vmID, v.Name, v.State) - p.handleOrphan(ctx, v) + } + // A failing verb must not strand a clone that did commit. + if fresh, settled := p.classifySettledCreate(ctx, vmID); settled { + if fresh != nil { + logger.Infof(ctx, "in-flight create %s (%s) committed; indexing for adoption", vmID, fresh.Name) + p.indexOrphanByName(fresh) + } return } if time.Now().After(deadline) { - logger.Warnf(ctx, "in-flight create %s did not leave creating within budget; giving up", vmID) + logger.Warnf(ctx, "in-flight create %s did not resolve within budget; giving up", vmID) return } delay = min(delay*2, maxDelay) @@ -201,6 +194,29 @@ func (p *Provider) watchBusyCreate(vmID string) { }) } +// classifySettledCreate resolves a record past the verb: (vm, true) committed +// and adoptable, (nil, true) settled with nothing to adopt, (nil, false) still +// transitional — ask again. +func (p *Provider) classifySettledCreate(ctx context.Context, vmID string) (*vm.VM, bool) { + logger := log.WithFunc("Provider.classifySettledCreate") + fresh, err := p.Runtime.Inspect(ctx, vmID) + switch { + case errors.Is(err, vm.ErrVMNotFound): + return nil, true + case err != nil: + logger.Errorf(ctx, err, "re-inspect creating placeholder %s; watching for commit", vmID) + return nil, false + case fresh.State == vm.StateRunning: + return fresh, true + case inFlightCreate(fresh.State): + return nil, false + default: + logger.Warnf(ctx, "placeholder %s (%s) left creating as %s without running; applying orphan policy", vmID, fresh.Name, fresh.State) + p.handleOrphan(ctx, fresh) + return nil, true + } +} + // reconcileStaleHibernate clears stale VMID/IP from a hibernated pod whose // VM is already gone, so wake can start clean. func (p *Provider) reconcileStaleHibernate(ctx context.Context, pod *corev1.Pod) { @@ -290,3 +306,11 @@ func podItems(list *corev1.PodList) []corev1.Pod { func inFlightCreate(state string) bool { return state == vm.StateCreating || state == vm.StateCreated } + +func recordStaleCreateOutcome(outcome vm.StaleCreateOutcome, err error) { + label := string(outcome) + if err != nil { + label = "error" + } + metrics.StaleCreateReconcileTotal.WithLabelValues(label).Inc() +} diff --git a/provider/cocoon/reconcile_test.go b/provider/cocoon/reconcile_test.go index c5be004..adaf505 100644 --- a/provider/cocoon/reconcile_test.go +++ b/provider/cocoon/reconcile_test.go @@ -28,8 +28,8 @@ func TestStartupReconcileSkeletonCollectedNotAdopted(t *testing.T) { if err := p.StartupReconcile(t.Context()); err != nil { t.Fatalf("StartupReconcile: %v", err) } - if len(rt.staleCreateCalls) != 1 || rt.staleCreateCalls[0] != "skel-vmid" { - t.Errorf("reconcile-stale-create calls = %v, want [skel-vmid]", rt.staleCreateCalls) + if calls := rt.staleCalls(); len(calls) != 1 || calls[0] != "skel-vmid" { + t.Errorf("reconcile-stale-create calls = %v, want [skel-vmid]", calls) } if got := p.vmByName("vk-ns-demo-0"); got != nil { t.Errorf("skeleton must not be indexed by name, got %#v", got) @@ -136,6 +136,49 @@ func TestStartupReconcileBusyCreateDeadOnArrivalGetsOrphanPolicy(t *testing.T) { } } +func TestWatchBusyCreateReclaimsAfterOwnerDies(t *testing.T) { + // The owner is alive at startup (busy) and dies without committing: the + // record stays creating forever, and only re-asking the verb can free the name. + rt := &fakeRuntime{ + listVMs: []vm.VM{{ID: "inflight-vmid", Name: "vk-ns-demo-0", State: vm.StateCreating}}, + staleCreateSeq: map[string][]vm.StaleCreateOutcome{ + "inflight-vmid": {vm.StaleCreateBusy, vm.StaleCreateBusy, vm.StaleCreateCollected}, + }, + inspectVM: &vm.VM{ID: "inflight-vmid", Name: "vk-ns-demo-0", State: vm.StateCreating}, + } + p := newTestProvider(t) + p.NodeName = "cocoon-pool" + p.Runtime = rt + p.Clientset = fake.NewSimpleClientset() + p.deferredRecheckInitialDelay = time.Millisecond + p.deferredRecheckMaxDelay = 2 * time.Millisecond + p.deferredRecheckBudget = 2 * time.Second + + if err := p.StartupReconcile(t.Context()); err != nil { + t.Fatalf("StartupReconcile: %v", err) + } + // The startup pass is call 1; the watcher must keep asking past it. + deadline := time.Now().Add(2 * time.Second) + for time.Now().Before(deadline) && len(rt.staleCalls()) < 3 { + time.Sleep(2 * time.Millisecond) + } + if calls := rt.staleCalls(); len(calls) < 3 { + t.Fatalf("verb calls = %v, want the watcher to re-invoke until the record resolves", calls) + } + // collected ends the watch: the count must not keep climbing. + time.Sleep(50 * time.Millisecond) + p.Close() + if calls := rt.staleCalls(); len(calls) != 3 { + t.Errorf("verb calls = %v, want the watch to stop once the record was collected", calls) + } + if got := p.vmByName("vk-ns-demo-0"); got != nil { + t.Errorf("reclaimed record must not be indexed, got %#v", got) + } + if rt.removedID != "" { + t.Errorf("vk must not rm the record itself (the verb owns reclaim), removed %q", rt.removedID) + } +} + func TestStartupReconcileSkeletonNotCreatingReinspectsAndAdopts(t *testing.T) { pod := newPodWithSpec(meta.VMSpec{VMName: "vk-ns-demo-0", Mode: "clone"}) pod.Spec.NodeName = "cocoon-pool" diff --git a/provider/cocoon/resume.go b/provider/cocoon/resume.go index d0a6c8f..0dd1f91 100644 --- a/provider/cocoon/resume.go +++ b/provider/cocoon/resume.go @@ -65,12 +65,12 @@ func (p *Provider) dispatchResume(key string, pod *corev1.Pod, v *vm.VM, op stri switch op { case resumeOpHibernate: run(func() { - // Boot a crashed VM first; nothing re-delivers the hibernate later. - if v.State != vm.StateRunning { - if err := p.Runtime.Start(p.lifecycleCtx, v.ID); err != nil { - p.failOp(p.lifecycleCtx, pod, "ResumeStartFailed", "reconcile", err) - return - } + // Boot unconditionally: the record still reads running after a + // SIGKILLed VMM, and Start no-ops on a live VM. Nothing re-delivers + // the hibernate later. + if err := p.Runtime.Start(p.lifecycleCtx, v.ID); err != nil { + p.failOp(p.lifecycleCtx, pod, "ResumeStartFailed", "reconcile", err) + return } if err := p.hibernate(p.lifecycleCtx, pod, v); err != nil { return diff --git a/provider/cocoon/resume_test.go b/provider/cocoon/resume_test.go index 585db22..b6fb0cb 100644 --- a/provider/cocoon/resume_test.go +++ b/provider/cocoon/resume_test.go @@ -236,6 +236,46 @@ func TestStartupDispatchOwedWork(t *testing.T) { } } +func TestStartupResumeHibernateStartsVMWhoseRecordStillReadsRunning(t *testing.T) { + // A SIGKILLed VMM leaves the record reading running: gating Start on the + // listed state skips the boot and every hibernate step fails not-running. + const ( + vmName = "vk-ns-demo-0" + vmID = "resume-vmid" + ) + pod := newPodWithSpec(meta.VMSpec{ + VMName: vmName, + Mode: "clone", + OS: string(cocoonv1.OSWindows), + Backend: string(cocoonv1.BackendCloudHypervisor), + }) + pod.Spec.NodeName = "cocoon-pool" + meta.VMRuntime{VMID: vmID, IP: "10.0.0.9"}.Apply(pod) + meta.HibernateState(true).Apply(pod) + + rt := &fakeRuntime{ + listVMs: []vm.VM{{ID: vmID, Name: vmName, State: vm.StateRunning, IP: "10.0.0.9"}}, + netResizeNeedsStart: true, + } + p := newTestProvider(t) + p.NodeName = "cocoon-pool" + p.Runtime = rt + p.Clientset = fake.NewSimpleClientset(pod) + + if err := p.StartupReconcile(t.Context()); err != nil { + t.Fatalf("StartupReconcile: %v", err) + } + awaitLifecycle(t, p, "ns", "demo-0", meta.LifecycleStateHibernated) + p.Close() + + if got := rt.started(); len(got) != 1 || got[0] != vmID { + t.Errorf("start calls = %v, want [%s]", got, vmID) + } + if rt.snapshotSaveCount != 1 { + t.Errorf("snapshot saves = %d, want 1", rt.snapshotSaveCount) + } +} + func TestStartupDispatchResumesSACWhenDoneMarkerPredatesIt(t *testing.T) { // post-clone-state=done is written before SAC runs, so done alone must // not skip the SAC pass: a failing dialer proves it was re-attempted. diff --git a/provider/cocoon/update_test.go b/provider/cocoon/update_test.go index 387daca..ec73e9c 100644 --- a/provider/cocoon/update_test.go +++ b/provider/cocoon/update_test.go @@ -336,7 +336,9 @@ func TestFinalizeDropNICWakeSkipsLifecycleWhenHibernateRequested(t *testing.T) { }() time.AfterFunc(10*time.Millisecond, func() { - meta.HibernateState(true).Apply(pod) + hib := pod.DeepCopy() + meta.HibernateState(true).Apply(hib) + p.trackPod(hib, nil) p.setVMIP("ns", "demo-0", v.ID, "172.20.1.228") })