diff --git a/api/v1alpha1/groupversion_info.go b/api/v1alpha1/groupversion_info.go index 4aece76..684c739 100644 --- a/api/v1alpha1/groupversion_info.go +++ b/api/v1alpha1/groupversion_info.go @@ -185,4 +185,7 @@ const ( // reclaimed, or exited). Disappearance alone does not say WHY, so this is the // neutral term rather than "Preempted". PodReasonTerminated = "Terminated" + // PodReasonReadinessTimeout: the instance never reported ready inside the virtual + // node's deadline, so we gave up on it (see defaultReadyDeadline). + PodReasonReadinessTimeout = "ReadinessTimeout" ) diff --git a/docs/status.md b/docs/status.md index 94d4c6d..ac469e9 100644 --- a/docs/status.md +++ b/docs/status.md @@ -28,6 +28,7 @@ enters the system. - [fake](#fake) - [Logs and exec](#logs-and-exec) - [What is not observable](#what-is-not-observable) +- [The readiness deadline](#the-readiness-deadline) --- @@ -46,6 +47,7 @@ teardown. | `Running` | `Running` | `applyState` ← `InstanceRunning` | yes | `Bound` | | `Failed` | `ProvisionFailed` | `CreatePod` | no | `Terminated` (via `isTerminal`) | | `Failed` | `Failed` | `applyState` ← `InstanceFailed` | yes | `Terminated` | +| `Failed` | `ReadinessTimeout` | `applyReadinessTimeout`, poll loop | yes, still running | `Terminated` | | `Failed` | `Terminated` | `applyState` ← `InstanceTerminated` | gone | `Terminated` | | `Succeeded` | `Terminated` | `DeletePod` | gone | `Terminated` | @@ -289,3 +291,34 @@ condition, and container readiness into one atomic write, so in Nebula `PodRunning` implies `Ready=True` implies all containers ready. The readiness bar lives entirely in each adapter's `toState`; a Pod is never `Running` but not-ready. + +--- + +## The readiness deadline + +A readiness signal that never arrives is the one failure nothing else bounds: the instance +exists, the provider reports nothing wrong, and the Pod sits at `Initializing` billing a GPU +forever. So ten minutes (`defaultReadyDeadline`) after an instance is first observed +`InstancePending`, one still reporting it goes `Failed` / `ReadinessTimeout`. + +The clock starts at `Initializing`, not at `Provision` — that call has its own deadline and +can legitimately run for minutes. Any other state resets it, so a demoted instance gets a +fresh budget. + +Failing the Pod is the whole action; teardown and replacement are the ordinary terminal-Pod +path (reap → `DeletePod` → `Terminate`, then the owner places a replacement). + +- **The reason is not `Failed`.** The provider never reported a failure, so it points at the + workload's probe rather than the instance. +- **A bare, un-owned Pod is not reaped**, so nothing terminates its instance — the one + terminal reason where the Pod is dead and the instance alive. It leaked before too, by + never going terminal at all. +- **Replacement is unbounded**, one provision per ten minutes: a replacement Pod carries no + lineage from the one it replaced, so there is nowhere to keep the count. +- **A manager restart grants a fresh budget**, the clock being in memory. Persisting it would + fail a healthy Pod on every restart. + +There is no flag, and ten minutes is deliberately far longer than any legitimate boot, +because the deadline cannot tell "never ready" from "still queued for a GPU" (both are +`InstancePending` — see [queued vs. booting](#what-is-not-observable)): a Pod killed while +queued only sends its replacement to the back of the same queue. diff --git a/pkg/vnode/handler.go b/pkg/vnode/handler.go index 7ebf1dc..c8823b9 100644 --- a/pkg/vnode/handler.go +++ b/pkg/vnode/handler.go @@ -57,6 +57,10 @@ const defaultBlocklistTTL = 30 * time.Second // expires and they stampede the same just-freed candidate together. const blocklistJitter = 30 * time.Second +// defaultReadyDeadline bounds how long a pod may sit Initializing before the virtual node +// gives up on it. +const defaultReadyDeadline = 10 * time.Minute + // Blocklister records a failed placement so the placement controller fails over to // the next candidate instead of hot-looping on a provider that just said no. The // write half of pkg/failover.Blocklist; a nil blocklist is a no-op. @@ -115,9 +119,11 @@ type Handler struct { notify func(*corev1.Pod) - // nowFn and pollEvery are seams for tests. - nowFn func() metav1.Time - pollEvery time.Duration + // nowFn, pollEvery and readyDeadline are seams for tests. readyDeadline is + // defaultReadyDeadline in production and <=0 disables the deadline entirely. + nowFn func() metav1.Time + pollEvery time.Duration + readyDeadline time.Duration // jitterFn returns the delay added to a block's base TTL (see recordBlock). A seam // so tests can pin it to 0 and assert an exact TTL. @@ -142,7 +148,7 @@ type trackedPod struct { // persistCredential. patchedMeta podMeta - // provisionStart is when THIS process began provisioning. It arms the one + // provisioningAt is when THIS process began provisioning. It arms the one // metrics.InstanceReadyDuration observation the poll loop makes on the first // Running, and is consumed by it, so zero means "do not observe" for either reason: // @@ -156,11 +162,22 @@ type trackedPod struct { // Known bias: a provision still in flight across a restart never contributes, so the // histogram under-samples the slowest boots. Fixing it means persisting the start // time, a write on the provisioning path we have not taken. - provisionStart time.Time + provisioningAt time.Time + + // initializingAt is when the instance was first observed Initializing, and arms the + // readiness deadline (see readyExpired). Deliberately NOT provisioningAt: it measures + // the boot alone, so a provision that took minutes does not eat the budget. + // + // Level-triggered, not one-shot like provisioningAt: it is cleared whenever the + // instance is not Pending, so the clock tracks the CURRENT Initializing spell. A pod + // re-adopted after a restart therefore gets a full budget from its first observed tick, + // which is the safe direction — the alternative, exempting it forever, disables the + // deadline for exactly the pods a restart left stuck. + initializingAt time.Time // placement is what this pod was provisioned against. Two readers: the poll loop files // the ready duration under the same dimensions as the provision counters, and DeletePod - // takes the region the instance is reachable in. Set only where provisionStart is armed. + // takes the region the instance is reachable in. Set only where provisioningAt is armed. placement } @@ -171,7 +188,7 @@ type trackedPod struct { // stays the durable record; this is the historical one. // // The zero value means "unknown" and is what every path that never provisioned stores. Its -// readers degrade rather than guess: no ready sample is filed (provisionStart is zero on +// readers degrade rather than guess: no ready sample is filed (provisioningAt is zero on // those same paths), and teardown falls back to reading the claim. type placement struct { region string @@ -231,13 +248,14 @@ func NewHandler( poll = defaultPollInterval } return &Handler{ - prov: prov, - client: client, - blocklist: blocklist, - cluster: cluster, - tracked: make(map[string]*trackedPod), - nowFn: metav1.Now, - pollEvery: poll, + prov: prov, + client: client, + blocklist: blocklist, + cluster: cluster, + tracked: make(map[string]*trackedPod), + nowFn: metav1.Now, + pollEvery: poll, + readyDeadline: defaultReadyDeadline, // rand/v2's top-level source is auto-seeded and safe for concurrent use, so // every handler draws an independent jitter without shared seeding. jitterFn: func() time.Duration { return time.Duration(rand.Int64N(int64(blocklistJitter))) }, @@ -344,12 +362,12 @@ func (h *Handler) CreatePod(ctx context.Context, pod *corev1.Pod) error { "capacityType", req.CapacityType, "region", req.Region, "envVars", len(req.Env), "timeout", timeout.String()) - // Two clocks for two different waits: provisionStart measures the end-to-end wait a + // Two clocks for two different waits: provisioningAt measures the end-to-end wait a // user feels (until the instance reports Running; handed to store below), callStart // only the Provision call. Not interchangeable — the emit between them is a // synchronous notify that can issue an API write, which would otherwise be charged // to the provider's latency. - provisionStart := time.Now() + provisioningAt := time.Now() // Carried into store so the poll loop's ready observation is filed under the same region // and tier as the counters below, whatever the NodeClaim says by then. place := placement{region: req.Region, tier: req.CapacityType} @@ -401,7 +419,7 @@ func (h *Handler) CreatePod(ctx context.Context, pod *corev1.Pod) error { // tracked copy carries it, published by the emit below, re-offered every tick until a // write lands. Its reader is the NodeClaim controller (see InstanceIDAnnotation). setInstanceID(pod, res.InstanceID) - h.store(pod, claim, res.InstanceID, provisionStart, place) + h.store(pod, claim, res.InstanceID, provisioningAt, place) // The TOKEN cannot ride the Pod (readable with `get pod`, unencrypted in etcd), so it // gets its own write — the only place it exists, since the provider mints it once and @@ -553,7 +571,7 @@ func (h *Handler) GetPod(ctx context.Context, namespace, name string) (*corev1.P pod := &corev1.Pod{ObjectMeta: metav1.ObjectMeta{Namespace: namespace, Name: name}} applyState(pod, inst.State, inst.Endpoint, h.nowFn()) // Zero start: this process never provisioned it, so the real start time is gone and - // the ready-duration is not observable (see trackedPod.provisionStart) — hence no + // the ready-duration is not observable (see trackedPod.provisioningAt) — hence no // placement either, since nothing here will be filed under it. h.store(pod, claim, inst.ID, time.Time{}, placement{}) log.Info("re-adopted live instance after cold tracking map (VK restart)", @@ -673,6 +691,15 @@ func (h *Handler) reconcileOnce(ctx context.Context) { applyState(tp.pod, provider.InstanceTerminated, "", h.nowFn()) default: matched++ + if waited, over := h.readyExpired(tp, inst.State); over { + // Failing the Pod is the whole action: teardown follows from the + // terminal phase, via the reap (see readyExpired). + log.Info("readiness deadline exceeded; failing the pod", + "pod", key(tp.pod.Namespace, tp.pod.Name), "instanceID", tp.instance, + "waited", waited.Round(time.Second).String(), "deadline", h.readyDeadline.String()) + applyReadinessTimeout(tp.pod, waited, h.nowFn()) + break + } applyState(tp.pod, inst.State, inst.Endpoint, h.nowFn()) // The observed address, for a provider that cannot know it before boot. // Empty for one that published at create, which must not clear it. @@ -716,6 +743,43 @@ func (h *Handler) reconcileOnce(ctx context.Context) { } } +// readyExpired maintains the Initializing clock and reports whether it has run +// past the deadline, with how long the pod has been there. +// +// It anchors on the FIRST observation of InstancePending, not on provisioningAt: the +// provision call is bounded separately (see defaultProvisionTimeout), so measuring from +// there would spend the readiness budget on a box that had barely started booting. Any +// other state RESETS the clock rather than merely pausing it — a demoted pod gets a fresh +// budget, and Failed/Terminated keep the more specific reason the provider gave. +// +// The caller only fails the pod; teardown follows from the terminal phase, via the reap. +// +// KNOWN GAP: a bare pod (no controlling owner) is deliberately retained by the reaper as a +// record, and the claim's backstop only fires once the Pod object is gone — so its instance +// keeps billing until a human deletes the Pod. Not a regression (an unreadable readiness +// signal leaked the same instance before, by never going terminal at all), and not fixed: +// closing it means terminating from here, by claim name when the id is unknown. +// +// Measured with time.Since rather than h.nowFn for the reason observeReady gives. +// +// Callers must hold h.mu. +func (h *Handler) readyExpired(tp *trackedPod, state provider.InstanceState) (time.Duration, bool) { + if state != provider.InstancePending { + tp.initializingAt = time.Time{} + return 0, false + } + if h.readyDeadline <= 0 { + return 0, false + } + // First tick at Initializing: start the clock, never expire on the same tick. + if tp.initializingAt.IsZero() { + tp.initializingAt = time.Now() + return 0, false + } + waited := time.Since(tp.initializingAt) + return waited, waited > h.readyDeadline +} + // observeReady records the end-to-end provisioning wait the first time an instance // reports Running. The poll loop is the only place that number exists, since a // provider's create returns long before the instance is usable. @@ -724,17 +788,17 @@ func (h *Handler) reconcileOnce(ctx context.Context) { // pin to a fixed instant, and subtracting a real start time from a pinned now would give // a nonsense duration. // -// ONE-SHOT — it consumes provisionStart, whose zero value covers both "never armed" and -// "already recorded" (see trackedPod.provisionStart). That guard also keeps the poll loop +// ONE-SHOT — it consumes provisioningAt, whose zero value covers both "never armed" and +// "already recorded" (see trackedPod.provisioningAt). That guard also keeps the poll loop // cheap: labels are rendered behind it, so at most once per pod, never per tick. // // Callers must hold h.mu. func (h *Handler) observeReady(tp *trackedPod, state provider.InstanceState) { - if state != provider.InstanceRunning || tp.provisionStart.IsZero() { + if state != provider.InstanceRunning || tp.provisioningAt.IsZero() { return } - metrics.ObserveReady(h.metricLabels(tp.pod, tp.region, tp.tier), time.Since(tp.provisionStart)) - tp.provisionStart = time.Time{} // spent; never observe this pod again + metrics.ObserveReady(h.metricLabels(tp.pod, tp.region, tp.tier), time.Since(tp.provisioningAt)) + tp.provisioningAt = time.Time{} // spent; never observe this pod again } // setEndpoint stamps a reachable address onto the Pod's annotation — the one assignment @@ -802,12 +866,12 @@ func statusSignature(pod *corev1.Pod) string { return string(pod.Status.Phase) + "|" + pod.Status.Reason + "|" + string(ready) + "|" + pod.Status.PodIP } -// store records/updates the tracked pod under lock. provisionStart arms the -// ready-duration observation (see trackedPod.provisionStart) and place is part of what that +// store records/updates the tracked pod under lock. provisioningAt arms the +// ready-duration observation (see trackedPod.provisioningAt) and place is part of what that // observation is filed under; pass the zero values from any path that cannot know them — // a re-adoption, or an already-terminal pod. func (h *Handler) store( - pod *corev1.Pod, claim, instance string, provisionStart time.Time, place placement, + pod *corev1.Pod, claim, instance string, provisioningAt time.Time, place placement, ) { h.mu.Lock() defer h.mu.Unlock() @@ -815,7 +879,7 @@ func (h *Handler) store( pod: pod.DeepCopy(), claimName: claim, instance: instance, - provisionStart: provisionStart, + provisioningAt: provisioningAt, placement: place, } } diff --git a/pkg/vnode/handler_test.go b/pkg/vnode/handler_test.go index 5de0050..e105eee 100644 --- a/pkg/vnode/handler_test.go +++ b/pkg/vnode/handler_test.go @@ -1492,6 +1492,137 @@ func TestReconcileOnce_AbsentInstanceIsTerminated(t *testing.T) { } } +func TestReconcileOnce_ReadinessDeadlineFailsPod(t *testing.T) { + // An instance the provider keeps reporting Pending forever — Modal's probe never + // reporting pass. Past the deadline the Pod goes terminal, which is the whole action: + // teardown is the reap's job, exactly as for every other terminal reason. + fp := &fakeProvider{provisionID: "inst-1"} + h := NewHandler(fp, nil, nil, openCluster()) + _ = h.CreatePod(context.Background(), testPod("default", "p1")) + + fp.list = []provider.Instance{{ + ID: "inst-1", ClaimName: "default-p1", State: provider.InstancePending, + }} + // The first Pending tick only starts the clock, so the pod must survive it. + h.reconcileOnce(context.Background()) + if got, _ := h.GetPod(context.Background(), "default", "p1"); got.Status.Reason != reasonInitializing { + t.Fatalf("reason = %q on the first Initializing tick, want %q", got.Status.Reason, reasonInitializing) + } + rewindInitializing(t, h, "default", "p1", 11*time.Minute) + h.reconcileOnce(context.Background()) + + got, err := h.GetPod(context.Background(), "default", "p1") + if err != nil { + t.Fatalf("GetPod: %v", err) + } + if got.Status.Phase != corev1.PodFailed { + t.Fatalf("phase = %q, want Failed past the readiness deadline", got.Status.Phase) + } + // Must NOT be the generic Failed reason: the provider never reported a failure, and the + // distinction is what tells an operator to look at the probe (see PodReasonReadinessTimeout). + if got.Status.Reason != reasonReadinessTimeout { + t.Fatalf("reason = %q, want %q", got.Status.Reason, reasonReadinessTimeout) + } + if isPodReadyStatus(got) { + t.Fatal("expected Ready=False on a pod that never became ready") + } + + // The next tick must not revisit it: the pod is terminal now, so the poll loop freezes it + // and the deadline's verdict (not a later Terminated from the same still-listed instance) + // is what survives. + h.reconcileOnce(context.Background()) + again, _ := h.GetPod(context.Background(), "default", "p1") + if again.Status.Reason != reasonReadinessTimeout { + t.Fatalf("reason = %q after a second tick, want %q to stick", again.Status.Reason, reasonReadinessTimeout) + } +} + +func TestReconcileOnce_ReadinessDeadlineSparesRunningInstance(t *testing.T) { + // The deadline applies to Initializing only. A long-lived Running pod is past it by + // construction, and killing one would be the single worst failure this feature could have. + fp := &fakeProvider{provisionID: "inst-1"} + h := NewHandler(fp, nil, nil, openCluster()) + _ = h.CreatePod(context.Background(), testPod("default", "p1")) + + fp.list = []provider.Instance{{ + ID: "inst-1", ClaimName: "default-p1", State: provider.InstanceRunning, + }} + h.reconcileOnce(context.Background()) + h.reconcileOnce(context.Background()) + + got, _ := h.GetPod(context.Background(), "default", "p1") + if got.Status.Phase != corev1.PodRunning { + t.Fatalf("phase = %q, want Running", got.Status.Phase) + } + if got.Status.Reason != reasonRunning { + t.Fatalf("reason = %q, want %q — the deadline must not touch a ready pod", got.Status.Reason, reasonRunning) + } +} + +func TestReadyExpired_ClockStartsAtInitializingNotAtProvision(t *testing.T) { + // The provision call has its own timeout, so its duration must not eat the readiness + // budget: a Provision that took an hour still leaves the box a full budget to boot in. + fp := &fakeProvider{} + h := NewHandler(fp, nil, nil, openCluster()) + tp := &trackedPod{pod: testPod("default", "p1"), provisioningAt: time.Now().Add(-time.Hour)} + + if _, over := h.readyExpired(tp, provider.InstancePending); over { + t.Fatal("a long provision must not expire the readiness deadline") + } + if tp.initializingAt.IsZero() { + t.Fatal("the first Initializing observation must start the clock") + } + + // Now blow the Initializing clock alone: that IS the deadline. + tp.initializingAt = tp.initializingAt.Add(-11 * time.Minute) + if _, over := h.readyExpired(tp, provider.InstancePending); !over { + t.Fatal("a pod initializing past the deadline must expire") + } +} + +func TestReadyExpired_RunningResetsTheClock(t *testing.T) { + // The clock tracks the CURRENT Initializing spell. A pod that reported Running and is + // later demoted to Pending must get a fresh budget, not be failed on its first tick back. + fp := &fakeProvider{} + h := NewHandler(fp, nil, nil, openCluster()) + tp := &trackedPod{pod: testPod("default", "p1"), initializingAt: time.Now().Add(-11 * time.Minute)} + + if _, over := h.readyExpired(tp, provider.InstanceRunning); over { + t.Fatal("Running must never expire") + } + if !tp.initializingAt.IsZero() { + t.Fatal("Running must reset the clock") + } + if _, over := h.readyExpired(tp, provider.InstancePending); over { + t.Fatal("the first tick back at Initializing must start a fresh budget") + } +} + +// rewindInitializing backdates a tracked pod's Initializing clock so the deadline is already +// blown, keeping the test deterministic rather than sleeping past a shortened one. +func rewindInitializing(t *testing.T, h *Handler, namespace, name string, by time.Duration) { + t.Helper() + h.mu.Lock() + defer h.mu.Unlock() + tp, ok := h.tracked[key(namespace, name)] + if !ok { + t.Fatalf("pod %s is not tracked", key(namespace, name)) + } + if tp.initializingAt.IsZero() { + t.Fatal("precondition: an Initializing tick must have started the clock") + } + tp.initializingAt = tp.initializingAt.Add(-by) +} + +func isPodReadyStatus(pod *corev1.Pod) bool { + for _, c := range pod.Status.Conditions { + if c.Type == corev1.PodReady { + return c.Status == corev1.ConditionTrue + } + } + return false +} + func TestReconcileOnce_ListErrorLeavesStatusUntouched(t *testing.T) { // A List error must not advance anything. It means the fleet is half-known, and // the only unsafe reading is "absent" — which maps to Terminated, a terminal diff --git a/pkg/vnode/metrics_test.go b/pkg/vnode/metrics_test.go index c75b474..a6448fa 100644 --- a/pkg/vnode/metrics_test.go +++ b/pkg/vnode/metrics_test.go @@ -157,7 +157,7 @@ func TestCreatePod_UnreachableProviderNotCountedAsCapacity(t *testing.T) { } // The ready duration is observed on the FIRST tick that reports Running and never -// again, because provisionStart is consumed. Without that, every subsequent tick would +// again, because provisioningAt is consumed. Without that, every subsequent tick would // add a sample with an ever-growing value — measuring the pod's age, not its boot. func TestReconcileOnce_ObservesReadyDurationExactlyOnce(t *testing.T) { ready := labelsFor("", "") diff --git a/pkg/vnode/status.go b/pkg/vnode/status.go index d5692cd..be3efe2 100644 --- a/pkg/vnode/status.go +++ b/pkg/vnode/status.go @@ -17,7 +17,9 @@ limitations under the License. package vnode import ( + "fmt" "net" + "time" corev1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -31,13 +33,14 @@ import ( // them, operators match on them), so they live in api/v1alpha1 — see that const block // for what each means. const ( - reasonProvisioning = nebulav1alpha1.PodReasonProvisioning - reasonInitializing = nebulav1alpha1.PodReasonInitializing - reasonRunning = nebulav1alpha1.PodReasonRunning - reasonProvisionFailed = nebulav1alpha1.PodReasonProvisionFailed - reasonConfigError = nebulav1alpha1.PodReasonConfigError - reasonFailed = nebulav1alpha1.PodReasonFailed - reasonTerminated = nebulav1alpha1.PodReasonTerminated + reasonProvisioning = nebulav1alpha1.PodReasonProvisioning + reasonInitializing = nebulav1alpha1.PodReasonInitializing + reasonRunning = nebulav1alpha1.PodReasonRunning + reasonProvisionFailed = nebulav1alpha1.PodReasonProvisionFailed + reasonConfigError = nebulav1alpha1.PodReasonConfigError + reasonFailed = nebulav1alpha1.PodReasonFailed + reasonTerminated = nebulav1alpha1.PodReasonTerminated + reasonReadinessTimeout = nebulav1alpha1.PodReasonReadinessTimeout ) // applyState projects a provider Instance state onto the Pod status, since the Pod is @@ -101,6 +104,25 @@ func applyState(pod *corev1.Pod, state provider.InstanceState, endpoint string, } } +// applyReadinessTimeout fails a Pod whose instance never became ready in time. +// +// Not a case in applyState because no provider state stands behind it: the instance was +// last observed Pending and, as far as the provider is concerned, fine. This is OUR +// verdict, so it must not read as a provider-reported failure — see +// PodReasonReadinessTimeout. +func applyReadinessTimeout(pod *corev1.Pod, waited time.Duration, now metav1.Time) { + msg := fmt.Sprintf("external instance did not become ready within %s", waited.Round(time.Second)) + setPhase(pod, corev1.PodFailed, reasonReadinessTimeout, msg, now) + setReady(pod, corev1.ConditionFalse, now) + setContainerStatuses(pod, corev1.ContainerState{ + Terminated: &corev1.ContainerStateTerminated{ + Reason: reasonReadinessTimeout, + Message: msg, + FinishedAt: now, + }, + }, false) +} + // setContainerStatuses mirrors the one instance's state onto every container in the spec. // The READY column, `kubectl wait`, and anything keying off container readiness read // Status.ContainerStatuses, so an empty array reads as 0/N even with Ready=True. There is