From 776526b8bd7b10a874e1318162788a4b7cdfcc3f Mon Sep 17 00:00:00 2001 From: Craig Johnston Date: Wed, 5 Aug 2026 14:59:45 +1000 Subject: [PATCH 1/5] floatingip: unwind assignment bookkeeping and requeue on AssignIP failure reconcileAssignment optimistically records an assignment before calling provider.AssignIP: status.nodeProviderID = providerID i.providerIDToIP[providerID] = ip On failure neither write is unwound, and because orderedSet.Front() is a pop and the deferred requeue only replays retryIPs/retryProviders - which the error branch never appends to - both the IP and the node are dropped from their queues. The node is then leaked permanently: * EnableNodes sees the stale providerIDToIP entry, logs "enabling node; already assigned to ip", deletes the IP from assignableIPs and returns early, so it never adds the node to assignableNodes. * reconcileIPStatus partially recovers - it observes the IP is unowned, clears status.nodeProviderID and re-adds the IP to assignableIPs - but it cannot requeue the node, because the assignableNodes.Add call is guarded by providerIDToNodeName[providerID] and providerID is "" by that point. * EnableNodes can never help again, since the node is already present in providerIDToNodeName. With assignableNodes permanently empty, the reconcileAssignment loop guard (assignableIPs.Len() != 0 && assignableNodes.Len() != 0) is never satisfied, so no further attempt is ever made at any backoff. Only a process restart rebuilds the queues. Observed in production: a single transient HTTP 422 from the DigitalOcean API on a freshly-created droplet left a Reserved IP bound to nothing for 2h31m, with the pool reporting every IP as "unassigned". Restarting the controller bound the IPs within 45 seconds. Unwind both writes and requeue the IP and the node so the pair is retried on the existing schedule. status.state and status.assignmentErrors are deliberately left set: the failure did happen and must stay visible in the CRD status and in the ip_assignment_errors metric. The "assignment error" case in TestIPControllerReconcileAssignment asserted that providerIDToIP retained the mapping after a failed assignment, i.e. it encoded this defect as expected behaviour; it now asserts the mapping is unwound and both sides requeued. --- pkg/floatingip/ip_controller.go | 10 ++ pkg/floatingip/ip_controller_test.go | 135 +++++++++++++++++++++++++-- 2 files changed, 139 insertions(+), 6 deletions(-) diff --git a/pkg/floatingip/ip_controller.go b/pkg/floatingip/ip_controller.go index 71bf880..60d8e10 100644 --- a/pkg/floatingip/ip_controller.go +++ b/pkg/floatingip/ip_controller.go @@ -569,6 +569,16 @@ func (i *ipController) reconcileAssignment(ctx context.Context) { status.message = fmt.Sprintf("assigning IP to node: %s", err) status.assignmentErrors++ log.WithError(err).Error("assigning IP to node") + + // Unwind optimistic bookkeeping and requeue both sides + delete(i.providerIDToIP, providerID) + status.nodeProviderID = oldProviderID + if oldProviderID != "" { + i.providerIDToIP[oldProviderID] = ip + } + retryIPs = append(retryIPs, ip) + retryProviders = append(retryProviders, providerID) + if nRetry == nil { nRetry = &retry{ retrySchedule: status.retrySchedule, diff --git a/pkg/floatingip/ip_controller_test.go b/pkg/floatingip/ip_controller_test.go index 2f46748..269a721 100644 --- a/pkg/floatingip/ip_controller_test.go +++ b/pkg/floatingip/ip_controller_test.go @@ -30,6 +30,7 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/util/uuid" + flipopv1alpha1 "github.com/digitalocean/flipop/pkg/apis/flipop/v1alpha1" "github.com/digitalocean/flipop/pkg/log" "github.com/digitalocean/flipop/pkg/provider" ) @@ -357,12 +358,20 @@ func TestIPControllerReconcileAssignment(t *testing.T) { }, }, { - name: "assignment error", - assignableIPs: []string{"192.168.1.1"}, - assignableNodes: []string{"mock://1"}, - expectProviderIDToIP: map[string]string{"mock://1": "192.168.1.1"}, - responses: []assignIPRes{{ip: "192.168.1.1", providerID: "mock://1", err: errors.New("nope")}}, - expectIPRetry: true, // We always retry, because of assign + name: "assignment error", + assignableIPs: []string{"192.168.1.1"}, + assignableNodes: []string{"mock://1"}, + // A failed assignment must not leave a phantom IP<->node mapping behind, and + // both the IP and the node must be requeued so the pair is retried. This + // previously expected providerIDToIP to retain {"mock://1": "192.168.1.1"} + // and requeued neither side, which is the OPTI-3818 defect: the node leaked + // out of assignableNodes permanently, so reconcileAssignment could never run + // again and the IP was stranded. + expectProviderIDToIP: map[string]string{}, + expectAssignableIPs: []string{"192.168.1.1"}, + expectAssignableNodes: []string{"mock://1"}, + responses: []assignIPRes{{ip: "192.168.1.1", providerID: "mock://1", err: errors.New("nope")}}, + expectIPRetry: true, // We always retry, because of assign setup: func(i *ipController) { i.ipToStatus["192.168.1.1"] = &ipStatus{} }, @@ -422,6 +431,120 @@ func TestIPControllerReconcileAssignment(t *testing.T) { } } +func TestIPControllerAssignmentRetriesAfterTransientError(t *testing.T) { + ctx := context.Background() + ip := "192.168.1.1" + providerID := "mock://1" + assignCallCount := 0 + + i := newIPController(logrus.New(), nil, nil) + i.updateProviders(&provider.MockIPProvider{ + AssignIPFunc: func(_ context.Context, ipArg string, providerIDArg string) error { + assignCallCount++ + require.Equal(t, ip, ipArg) + require.Equal(t, providerID, providerIDArg) + if assignCallCount == 1 { + return provider.NewRetryError(errors.New("transient error"), provider.RetryFast) + } + return nil + }, + IPToProviderIDFunc: func(_ context.Context, ipArg string) (string, error) { + return "", nil + }, + }, nil, "", 0) + + // Pin the clock so the retry deadlines below are deterministic. + i.now = func() time.Time { return fakeNow } + + // Populate ipToStatus and ips as existing tests do + i.ips = []string{ip} + i.ipToStatus[ip] = &ipStatus{} + + // Register the node via EnableNodes to exercise the stale-read path at line 676 + i.EnableNodes(&corev1.Node{ + ObjectMeta: metav1.ObjectMeta{Name: "node-1", UID: uuid.NewUUID()}, + Spec: corev1.NodeSpec{ProviderID: providerID}, + }) + + // Add IP to assignable queue + i.assignableIPs.Add(ip, true) + + // First reconcile - should fail with transient error. + // Drive the full reconcile() cycle, because reconcileIPStatus runs first in + // production and is what refreshes each IP's retry deadline. + i.reconcile(ctx) + + // Assert the failure was recorded + status := i.ipToStatus[ip] + require.Equal(t, flipopv1alpha1.IPStateError, status.state) + require.Equal(t, provider.RetryFast, status.retrySchedule) + require.Equal(t, uint(1), status.assignmentErrors) + + // CRITICAL ASSERTION: the node was requeued - this is the leaked invariant + require.Greater(t, i.assignableNodes.Len(), 0, "node should have been requeued after assignment failure") + + // Also verify the IP is in assignableIPs (it should have been requeued) + require.Greater(t, i.assignableIPs.Len(), 0, "IP should have been requeued after assignment failure") + + // Advance time past the retry deadline + i.now = func() time.Time { + return fakeNow.Add(2 * time.Second) + } + + // Second reconcile - should succeed + i.reconcile(ctx) + + // Assert AssignIP was called TWICE + require.Equal(t, 2, assignCallCount, "AssignIP should be called twice (fail then succeed)") + + // Assert the IP reached InProgress or Active + status = i.ipToStatus[ip] + require.Contains(t, []flipopv1alpha1.IPState{flipopv1alpha1.IPStateInProgress, flipopv1alpha1.IPStateActive}, status.state) + + // Assert providerIDToIP is correctly set + require.Equal(t, ip, i.providerIDToIP[providerID]) +} + +func TestIPControllerAssignmentFailureUnwindsBookkeeping(t *testing.T) { + ctx := context.Background() + ip := "192.168.1.1" + providerID := "mock://1" + oldProviderID := "mock://old" + + i := newIPController(logrus.New(), nil, nil) + i.updateProviders(&provider.MockIPProvider{ + AssignIPFunc: func(_ context.Context, ipArg string, providerIDArg string) error { + return errors.New("permanent error") + }, + IPToProviderIDFunc: func(_ context.Context, ipArg string) (string, error) { + return "", nil + }, + }, nil, "", 0) + + // Pin the clock for determinism. + i.now = func() time.Time { return fakeNow } + + // Set up initial state with an old assignment + i.ips = []string{ip} + i.ipToStatus[ip] = &ipStatus{nodeProviderID: oldProviderID} + i.providerIDToIP[oldProviderID] = ip + + // Add the IP and new node to assignable queues + i.assignableIPs.Add(ip, true) + i.assignableNodes.Add(providerID, true) + + // Reconcile - should fail + i.reconcileAssignment(ctx) + + // CRITICAL INVARIANT: after a FAILED AssignIP, providerIDToIP must NOT contain providerID + _, exists := i.providerIDToIP[providerID] + require.False(t, exists, "providerIDToIP should not contain the new providerID after failed assignment") + + // CRITICAL INVARIANT: status.nodeProviderID must be unchanged from its prior value + status := i.ipToStatus[ip] + require.Equal(t, oldProviderID, status.nodeProviderID, "nodeProviderID should be unwound to old value after failed assignment") +} + func TestIPControllerDisableNodes(t *testing.T) { tcs := []struct { name string From acf8efe0b47ad948e7b3ae4482600661f82e3927 Mon Sep 17 00:00:00 2001 From: Craig Johnston Date: Wed, 5 Aug 2026 15:00:07 +1000 Subject: [PATCH 2/5] provider/digitalocean: treat a 422 for an unowned IP as fast-retryable On HTTP 422 AssignIP probes the IP's current owner to distinguish "already assigned to us" (success) from "the target node already holds another IP" (ErrNodeInUse). If neither matches it falls through to a bare `return err`, which ErrorToRetrySchedule maps to RetrySlow - 1m, 5m, 10m, then 10m forever. A freshly-created droplet is therefore indistinguishable from a permanent failure. DigitalOcean returns 422 Droplet already has a pending event for a droplet that is still settling, which was observed roughly 35 seconds after droplet creation during a node rotation. That condition clears within seconds, so it belongs on RetryFast (1s, 1s, 5s, 5s, 10s ...) rather than a schedule measured in minutes. When the lookup succeeds and reports the IP is owned by nobody, the 422 cannot be an ownership conflict, so return a fast-retryable error. The iErr == nil guard matters: without it a failed IPToProviderID call that happens to yield an empty owner would be misclassified as transient. A 422 naming a different owner is deliberately unchanged and still reaches RetrySlow - that is a genuine conflict needing external resolution, and retrying it quickly would only add API load. --- pkg/provider/digitalocean.go | 10 ++++ pkg/provider/digitalocean_422_test.go | 72 +++++++++++++++++++++++++++ 2 files changed, 82 insertions(+) create mode 100644 pkg/provider/digitalocean_422_test.go diff --git a/pkg/provider/digitalocean.go b/pkg/provider/digitalocean.go index 4002532..f4026b0 100644 --- a/pkg/provider/digitalocean.go +++ b/pkg/provider/digitalocean.go @@ -201,6 +201,16 @@ func (do *digitalOcean) AssignIP(ctx context.Context, ip, providerID string) (er if curProvider != "" && curProvider == providerID { return nil // Already set to us. This is success. } + if iErr == nil && curProvider == "" { + // The IP is owned by nobody, so the 422 is not an ownership + // conflict. The droplet is simply not yet able to accept the + // IP - typically "Droplet already has a pending event" on a + // freshly-created droplet. That clears in seconds, so this + // must be fast-retryable rather than falling through to the + // bare error below, which ErrorToRetrySchedule treats as + // RetrySlow (1m/5m/10m, then 10m forever). + return NewRetryError(err, RetryFast) + } if iErr == nil { // It's likely the node already has an IP. Verify that, and return an // appropriate error. diff --git a/pkg/provider/digitalocean_422_test.go b/pkg/provider/digitalocean_422_test.go new file mode 100644 index 0000000..c60e243 --- /dev/null +++ b/pkg/provider/digitalocean_422_test.go @@ -0,0 +1,72 @@ +// SPDX-License-Identifier: Apache-2.0 +// +// Copyright 2021 Digital Ocean, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package provider + +import ( + "context" + "errors" + "net/http" + "testing" + + "github.com/digitalocean/godo" + "github.com/golang/mock/gomock" + "github.com/stretchr/testify/require" + + "github.com/digitalocean/flipop/pkg/log" + "github.com/digitalocean/flipop/pkg/provider/mock_godo" +) + +// TestDigitalOceanAssignIP422UnownedIsFastRetryable covers the case where DigitalOcean +// rejects a Reserved IP assignment with a 422 because the target droplet was only just +// created and still has a pending event. The IP itself is owned by nobody, so this is a +// transient condition which clears in seconds - it must not be reported as an error +// which defers the next attempt by RetrySlow (1m/5m/10m, then 10m forever). +func TestDigitalOceanAssignIP422UnownedIsFastRetryable(t *testing.T) { + ctx := context.Background() + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + ipActionsService := mock_godo.NewMockFloatingIPActionsService(ctrl) + ipsService := mock_godo.NewMockFloatingIPsService(ctrl) + + ip := "192.168.1.1" + providerID := "digitalocean://123456789" + + ipActionsService.EXPECT().Assign(gomock.Any(), ip, 123456789).Return( + nil, + &godo.Response{Response: &http.Response{StatusCode: http.StatusUnprocessableEntity}}, + errors.New("422 Droplet already has a pending event"), + ) + + // The IP is owned by nobody, so the 422 is not an ownership conflict. + ipsService.EXPECT().Get(gomock.Any(), ip).Return( + &godo.FloatingIP{Droplet: nil}, + &godo.Response{}, + nil, + ) + + do := &digitalOcean{ + ipActionsService: ipActionsService, + ipsService: ipsService, + log: log.NewTestLogger(t), + } + + err := do.AssignIP(ctx, ip, providerID) + require.Error(t, err) + require.Equal(t, RetryFast, ErrorToRetrySchedule(err), + "a 422 for an IP owned by nobody must be fast-retryable") +} From ae49b95297057c5f0eb137c6890999ecafb03256 Mon Sep 17 00:00:00 2001 From: Craig Johnston Date: Wed, 5 Aug 2026 16:12:29 +1000 Subject: [PATCH 3/5] floatingip: requeue a node whose IP is removed out of band reconcileIPStatus guards the reassignment requeue on providerID - the IP's *new* owner - but the thing it requeues is expectedProviderID, the node that lost the IP. When an IP is taken away entirely, providerID is "" and the lookup fails, so the evicted node is never returned to assignableNodes. reconcileAssignment's loop guard needs both queues non-empty, so no assignment is ever attempted again and the IP is stranded until the process restarts. Reproduced on rts-sgp-1-dev-cluster against 7db46fe by unassigning one Reserved IP through the DigitalOcean API. flipop noticed within its 5m status refresh and logged "ip address is available for assignment" for both pool IPs, then "no IPs assigned; skipping DNS update" once a minute indefinitely, with zero "assigning IP to node" attempts and no error. A rollout restart rebound the IP in ~85s. This is a second, independent path to the same end state as the 422 defect: no AssignIP call fails here, because none is ever made. Guard on expectedProviderID instead, which also covers the original case of the IP being claimed by another node, since the evicted node needs a replacement either way. Also stop writing i.providerIDToIP[""] = ip for an unowned IP. That empty key is read back as expectedIP on the next pass and produced a bogus "node assignment mismatch" that reset an unrelated pool IP to error - observed in the same dev run against 144.126.241.39. --- pkg/floatingip/ip_controller.go | 41 +++++++++++++-------- pkg/floatingip/ip_controller_test.go | 53 ++++++++++++++++++++++++++++ 2 files changed, 79 insertions(+), 15 deletions(-) diff --git a/pkg/floatingip/ip_controller.go b/pkg/floatingip/ip_controller.go index 60d8e10..21ebd1f 100644 --- a/pkg/floatingip/ip_controller.go +++ b/pkg/floatingip/ip_controller.go @@ -446,27 +446,38 @@ func (i *ipController) reconcileIPStatus(ctx context.Context) { } } - expectedIP := i.providerIDToIP[providerID] - if expectedIP != "" && expectedIP != ip { - log.WithField("expected_ip", expectedIP). - Warn("node assignment mismatch; updating cache to reflect provider") - i.assignableIPs.Add(expectedIP, false) - // mark the node's old IP for immediate retry. - i.ipToStatus[expectedIP] = &ipStatus{ - state: flipopv1alpha1.IPStateError, - retry: retry{retrySchedule: provider.RetryFast}, - message: "state unknown; cache / provider mismatch", - nodeProviderID: "", // reset + // Only record a new owner if there actually is one. Writing the empty + // key here means the next pass reads it back as expectedIP and reports a + // bogus assignment mismatch against an unrelated pool IP. + if providerID != "" { + expectedIP := i.providerIDToIP[providerID] + if expectedIP != "" && expectedIP != ip { + log.WithField("expected_ip", expectedIP). + Warn("node assignment mismatch; updating cache to reflect provider") + i.assignableIPs.Add(expectedIP, false) + // mark the node's old IP for immediate retry. + i.ipToStatus[expectedIP] = &ipStatus{ + state: flipopv1alpha1.IPStateError, + retry: retry{retrySchedule: provider.RetryFast}, + message: "state unknown; cache / provider mismatch", + nodeProviderID: "", // reset + } } + i.providerIDToIP[providerID] = ip } - i.providerIDToIP[providerID] = ip delete(i.providerIDToIP, expectedProviderID) - if evictedNodeName, ok := i.providerIDToNodeName[providerID]; ok { + // The node which held this IP no longer does, whether it was claimed by + // another node or released entirely. If it is still active it needs a + // replacement, so return it to the assignable queue. This was previously + // guarded on providerID - the IP's *new* owner - so an IP removed out of + // band, leaving it owned by nobody, left the node unqueued and no + // assignment was ever attempted again. + if evictedNodeName, ok := i.providerIDToNodeName[expectedProviderID]; ok { log.WithFields(logrus.Fields{ "node": evictedNodeName, - "ip": expectedIP, - }).Info("nodes ip was claimed by other node; marking for reassignment") + "ip": ip, + }).Info("node no longer holds its ip; marking for reassignment") i.assignableNodes.Add(expectedProviderID, true) } } diff --git a/pkg/floatingip/ip_controller_test.go b/pkg/floatingip/ip_controller_test.go index 269a721..05f3c4a 100644 --- a/pkg/floatingip/ip_controller_test.go +++ b/pkg/floatingip/ip_controller_test.go @@ -545,6 +545,59 @@ func TestIPControllerAssignmentFailureUnwindsBookkeeping(t *testing.T) { require.Equal(t, oldProviderID, status.nodeProviderID, "nodeProviderID should be unwound to old value after failed assignment") } +// TestIPControllerRequeuesNodeWhenIPRemovedExternally covers a Reserved IP being taken +// away from an active node out of band - a manual/API unassign, or a provider-side +// change. flipop must notice the IP is free AND return the node to the assignable queue, +// otherwise reconcileAssignment can never run for it again. +// +// Reproduced on dev against 7db46fe: the IPs were reported "available for assignment" +// while the controller sat idle, logging "no IPs assigned" once a minute forever, with +// zero assignment attempts, until the pod was restarted. +func TestIPControllerRequeuesNodeWhenIPRemovedExternally(t *testing.T) { + ctx := context.Background() + ip := "192.168.1.1" + providerID := "mock://1" + + i := newIPController(logrus.New(), nil, nil) + i.updateProviders(&provider.MockIPProvider{ + // The provider reports the IP as owned by nobody. + IPToProviderIDFunc: func(_ context.Context, _ string) (string, error) { + return "", nil + }, + AssignIPFunc: func(_ context.Context, _ string, _ string) error { + return nil + }, + }, nil, "", 0) + i.now = func() time.Time { return fakeNow } + + // Steady state: the IP is assigned to an active node, so neither queue holds it. + i.ips = []string{ip} + i.ipToStatus[ip] = &ipStatus{nodeProviderID: providerID, state: flipopv1alpha1.IPStateActive} + i.providerIDToIP[providerID] = ip + i.providerIDToNodeName[providerID] = "node-1" + require.Equal(t, 0, i.assignableNodes.Len(), "precondition: node is not queued") + + i.reconcileIPStatus(ctx) + + // The IP is free again... + require.True(t, i.assignableIPs.IsSet(ip), "IP should be assignable once unowned") + require.Empty(t, i.ipToStatus[ip].nodeProviderID, "stale node claim should be cleared") + // ...and the node that lost it must be queued for a replacement. Without this the + // reconcileAssignment loop guard (assignableIPs and assignableNodes both non-empty) + // can never be satisfied and the IP is stranded permanently. + require.True(t, i.assignableNodes.IsSet(providerID), + "node that lost its IP must be requeued for assignment") + + // And the empty providerID must not have been recorded as an owner, or the next pass + // reads it back as expectedIP and reports a bogus assignment mismatch. + _, junk := i.providerIDToIP[""] + require.False(t, junk, "must not record an owner for an unowned IP") + + // End to end: the following assignment pass rebinds the IP without intervention. + i.reconcileAssignment(ctx) + require.Equal(t, ip, i.providerIDToIP[providerID], "IP should be reassigned to the node") +} + func TestIPControllerDisableNodes(t *testing.T) { tcs := []struct { name string From 35666efdfcd44cec26a68b90b858e4a1509d7cf3 Mon Sep 17 00:00:00 2001 From: Craig Johnston Date: Wed, 5 Aug 2026 17:07:10 +1000 Subject: [PATCH 4/5] floatingip: assert an assignment failure never schedules a past wake-up run() sleeps until i.nextRetry, and retryTimerDuration() turns any timestamp at or before now into 0, so scheduling a past wake-up busy-loops the controller. Nothing asserted that invariant, because the existing tests drive reconcile() directly and never observe the timer. This does NOT reproduce the hot loop seen on dev (CPU pegged at its 250m limit, ~1,280 reconciles/sec, ~77k log lines a minute); that needs a DigitalOcean action to be in flight so IPToProviderID returns ErrInProgress, which the mock provider does not model. It does pin the two invariants that matter: the wake-up is always in the future, and a failed assignment is retried rather than skipped forever. --- pkg/floatingip/ip_controller_test.go | 52 ++++++++++++++++++++++++++++ 1 file changed, 52 insertions(+) diff --git a/pkg/floatingip/ip_controller_test.go b/pkg/floatingip/ip_controller_test.go index 05f3c4a..d1edc68 100644 --- a/pkg/floatingip/ip_controller_test.go +++ b/pkg/floatingip/ip_controller_test.go @@ -598,6 +598,58 @@ func TestIPControllerRequeuesNodeWhenIPRemovedExternally(t *testing.T) { require.Equal(t, ip, i.providerIDToIP[providerID], "IP should be reassigned to the node") } +// TestIPControllerAssignmentErrorDoesNotSpin asserts that a failed assignment always +// leaves the next wake-up in the future. reconcile() lowers i.nextRetry via i.retry(), +// and run() converts it with retryTimerDuration(), which returns 0 for any timestamp in +// the past - so scheduling a past wake-up busy-loops the controller. +// +// Observed on dev: ~1,280 reconciles/sec, CPU pegged at the 250m limit, and because the +// gate skipped the IP on every pass the bind was never retried at all. +func TestIPControllerAssignmentErrorDoesNotSpin(t *testing.T) { + ctx := context.Background() + ip := "192.168.1.1" + providerID := "mock://1" + var calls int + + i := newIPController(logrus.New(), nil, nil) + i.updateProviders(&provider.MockIPProvider{ + AssignIPFunc: func(_ context.Context, _ string, _ string) error { + calls++ + return errors.New("422 Droplet already has a pending event") + }, + IPToProviderIDFunc: func(_ context.Context, _ string) (string, error) { + return "", nil + }, + }, nil, "", 0) + + now := fakeNow + i.now = func() time.Time { return now } + i.ips = []string{ip} + i.ipToStatus[ip] = &ipStatus{} + i.EnableNodes(&corev1.Node{ + ObjectMeta: metav1.ObjectMeta{Name: "node-1", UID: uuid.NewUUID()}, + Spec: corev1.NodeSpec{ProviderID: providerID}, + }) + i.assignableIPs.Add(ip, true) + + // Drive several cycles, advancing the clock to each scheduled wake-up exactly as + // run() would. Any past wake-up means a spin. + for cycle := 0; cycle < 6; cycle++ { + i.reconcile(ctx) + // run() sleeps until i.nextRetry. A wake-up at or before "now" means + // retryTimerDuration() yields 0 and the controller reconciles again + // immediately - a busy loop. (retryTimerDuration itself reads the real wall + // clock rather than i.now(), so it cannot be asserted on directly here.) + require.True(t, i.nextRetry.After(now), + "cycle %d scheduled an immediate wake-up (nextRetry=%s now=%s); run() would busy-loop", + cycle, i.nextRetry, now) + now = i.nextRetry + } + + // And the failure must still be retried rather than silently skipped forever. + require.Greater(t, calls, 1, "assignment should be retried across cycles") +} + func TestIPControllerDisableNodes(t *testing.T) { tcs := []struct { name string From afff39c9315d4e3a6389ae25680296eec0cd5f9b Mon Sep 17 00:00:00 2001 From: Craig Johnston Date: Thu, 6 Aug 2026 13:35:23 +1000 Subject: [PATCH 5/5] floatingip: defer assignment only on a retry deadline that has not elapsed Both retry gates in reconcileAssignment were inverted. They deferred when the retry deadline HAD elapsed and then handed that already-past timestamp to i.retry(): if !status.nextRetry.IsZero() && !status.nextRetry.After(now) { retryIPs = append(retryIPs, ip) i.retry(status.nextRetry) continue } run() sleeps until i.nextRetry, so it re-enters reconcile() at or just after the deadline it was given - an elapsed deadline is the normal state on wake-up. retryTimerDuration() maps any past timestamp to 0, so run() reconciles again immediately, the gate skips again, and the controller busy-loops without ever retrying the bind. Upstream never reached this because the error branch dropped the IP and node from their queues entirely (fixed in the preceding commit); requeueing them makes the gates reachable. Observed on dev after that fix: ~1,280 reconciles/s, CPU pegged at the 250m limit, 173,963 log lines in 60s, zero assignment attempts. Naively flipping the IP gate to a plain After(now) is also wrong. reconcileIPStatus reuses status.nextRetry for the routine healthyRetrySchedule (5m) refresh and sets it on every healthy IP immediately before reconcileAssignment runs, so an unqualified check defers every IP and nothing is ever assigned. Gate on IPStateError as well, which is what the comment always claimed the check meant. The node gate needs no such qualifier: providerIDToRetry only ever holds nodes whose assignment failed, and the entry is deleted on success. Tests: * TestIPControllerRunDoesNotSpinOnPersistentFailure drives the real run() loop against the real clock - the only level at which this bug is visible, since the spin is a disagreement between the deadlines reconcile() schedules and the timer run() derives from them. It counts reconcile passes via the clock rather than via the provider, because a wedged controller skips the provider calls on every pass and provider call counts stay flat. 966,295 clock reads in 1.5s before, a handful after. * TestIPControllerElapsedNodeRetryDoesNotSpin and TestIPControllerElapsedIPRetryDoesNotSpin cover each gate in isolation. * TestIPControllerPendingIPRetryIsDeferred and TestIPControllerHealthyIPIsAssignable pin the converse, so the fix cannot regress into "never defer" or "always defer". Also seed the fake clocks in these tests, and in TestIPControllerAssignmentRetriesAfterTransientError, from time.Now(). RetrySchedule.Next() builds its deadlines from the real clock rather than i.now(), so a fakeNow (2021) base leaves every deadline years in the future, no retry gate is ever reached, and such tests pass vacuously. That is why the first attempt at a spin regression test went green against the wedged build. Generated with [Devin](https://devin.ai) Co-Authored-By: Devin <158243242+devin-ai-integration[bot]@users.noreply.github.com> --- pkg/floatingip/ip_controller.go | 14 +- pkg/floatingip/ip_controller_test.go | 211 ++++++++++++++++++++++---- pkg/provider/digitalocean_422_test.go | 42 +++++ 3 files changed, 234 insertions(+), 33 deletions(-) diff --git a/pkg/floatingip/ip_controller.go b/pkg/floatingip/ip_controller.go index 21ebd1f..668e1ad 100644 --- a/pkg/floatingip/ip_controller.go +++ b/pkg/floatingip/ip_controller.go @@ -527,9 +527,14 @@ func (i *ipController) reconcileAssignment(ctx context.Context) { ip := i.assignableIPs.Front() // If this IP was previously involved in an error we shouldn't attempt to try again before - // its retry timestamp. + // its retry timestamp. The deadline must be compared with After(): deferring on an + // *elapsed* deadline and then handing that past timestamp to i.retry() makes + // retryTimerDuration() return 0, so run() reconciles again immediately and spins. + // The error state has to be part of the test as well - reconcileIPStatus reuses + // nextRetry for the routine healthyRetrySchedule refresh and sets it on every healthy + // IP just before this runs, so an unqualified check would defer them all. status := i.ipToStatus[ip] - if !status.nextRetry.IsZero() && !status.nextRetry.After(now) { + if status.state == flipopv1alpha1.IPStateError && status.nextRetry.After(now) { retryIPs = append(retryIPs, ip) i.retry(status.nextRetry) continue @@ -538,9 +543,10 @@ func (i *ipController) reconcileAssignment(ctx context.Context) { providerID := i.assignableNodes.Front() // Similarly, if this node was involved in an error we should wait until after its retry - // timestamp has elapsed. + // timestamp has elapsed. providerIDToRetry only ever holds nodes whose assignment + // failed, and the entry is deleted on success, so no state qualifier is needed here. nRetry, ok := i.providerIDToRetry[providerID] - if ok && !nRetry.nextRetry.IsZero() && !nRetry.nextRetry.After(now) { + if ok && nRetry.nextRetry.After(now) { retryIPs = append(retryIPs, ip) retryProviders = append(retryProviders, providerID) i.retry(nRetry.nextRetry) diff --git a/pkg/floatingip/ip_controller_test.go b/pkg/floatingip/ip_controller_test.go index d1edc68..eb9183a 100644 --- a/pkg/floatingip/ip_controller_test.go +++ b/pkg/floatingip/ip_controller_test.go @@ -19,6 +19,7 @@ package floatingip import ( "context" "errors" + "sync" "testing" "time" @@ -453,8 +454,12 @@ func TestIPControllerAssignmentRetriesAfterTransientError(t *testing.T) { }, }, nil, "", 0) - // Pin the clock so the retry deadlines below are deterministic. - i.now = func() time.Time { return fakeNow } + // Pin the clock so the retry deadlines below are deterministic. It has to be seeded + // from the real clock: RetrySchedule.Next() builds deadlines from time.Now(), not + // i.now(), so a fakeNow base would leave every deadline years away and "advancing + // past the retry deadline" below would be a no-op. + clockBase := time.Now() + i.now = func() time.Time { return clockBase } // Populate ipToStatus and ips as existing tests do i.ips = []string{ip} @@ -486,9 +491,9 @@ func TestIPControllerAssignmentRetriesAfterTransientError(t *testing.T) { // Also verify the IP is in assignableIPs (it should have been requeued) require.Greater(t, i.assignableIPs.Len(), 0, "IP should have been requeued after assignment failure") - // Advance time past the retry deadline + // Advance time past the retry deadline (RetryFast starts at 1s). i.now = func() time.Time { - return fakeNow.Add(2 * time.Second) + return clockBase.Add(2 * time.Second) } // Second reconcile - should succeed @@ -598,23 +603,21 @@ func TestIPControllerRequeuesNodeWhenIPRemovedExternally(t *testing.T) { require.Equal(t, ip, i.providerIDToIP[providerID], "IP should be reassigned to the node") } -// TestIPControllerAssignmentErrorDoesNotSpin asserts that a failed assignment always -// leaves the next wake-up in the future. reconcile() lowers i.nextRetry via i.retry(), -// and run() converts it with retryTimerDuration(), which returns 0 for any timestamp in -// the past - so scheduling a past wake-up busy-loops the controller. +// newSpinTestController builds a controller with one pool IP and one enabled node whose +// assignment always fails, wired to a fake clock pinned to the real one. // -// Observed on dev: ~1,280 reconciles/sec, CPU pegged at the 250m limit, and because the -// gate skipped the IP on every pass the bind was never retried at all. -func TestIPControllerAssignmentErrorDoesNotSpin(t *testing.T) { - ctx := context.Background() +// The clock must be seeded from time.Now(): RetrySchedule.Next() builds its deadlines from +// the real clock rather than i.now(), so a fakeNow-based clock (2021) leaves every retry +// deadline years in the future, no retry gate is ever reached, and the assertions below +// hold vacuously. +func newSpinTestController(ctx context.Context, now time.Time, calls *int) (*ipController, string, string) { ip := "192.168.1.1" providerID := "mock://1" - var calls int i := newIPController(logrus.New(), nil, nil) i.updateProviders(&provider.MockIPProvider{ AssignIPFunc: func(_ context.Context, _ string, _ string) error { - calls++ + *calls++ return errors.New("422 Droplet already has a pending event") }, IPToProviderIDFunc: func(_ context.Context, _ string) (string, error) { @@ -622,7 +625,6 @@ func TestIPControllerAssignmentErrorDoesNotSpin(t *testing.T) { }, }, nil, "", 0) - now := fakeNow i.now = func() time.Time { return now } i.ips = []string{ip} i.ipToStatus[ip] = &ipStatus{} @@ -631,23 +633,174 @@ func TestIPControllerAssignmentErrorDoesNotSpin(t *testing.T) { Spec: corev1.NodeSpec{ProviderID: providerID}, }) i.assignableIPs.Add(ip, true) + return i, ip, providerID +} + +// TestIPControllerElapsedNodeRetryDoesNotSpin covers the node retry gate. +// +// run() sleeps until i.nextRetry, so it re-enters reconcile() at (or just after) the +// deadline it was given - meaning an elapsed deadline is the normal state on wake-up. The +// gate treated "elapsed" as "not due yet": it skipped the node and called i.retry() with +// that already-past timestamp, so retryTimerDuration() returned 0 and run() reconciled +// again immediately, forever, without ever retrying the bind. +// +// Observed on dev: ~1,280 reconciles/sec, CPU pegged at its 250m limit, 173,963 log lines +// in 60s, and zero assignment attempts. +func TestIPControllerElapsedNodeRetryDoesNotSpin(t *testing.T) { + ctx := context.Background() + var calls int + now := time.Now() + i, _, providerID := newSpinTestController(ctx, now, &calls) + + // State as run() finds it on wake-up: a prior failure whose deadline has just passed. + i.providerIDToRetry[providerID] = &retry{ + retrySchedule: provider.RetryFast, + attempts: 1, + nextRetry: now.Add(-time.Second), + } + + i.reconcile(ctx) + + require.Equal(t, 1, calls, "an elapsed retry deadline is due; the assignment must be attempted") + require.True(t, i.nextRetry.After(now), + "scheduled an immediate wake-up (nextRetry=%s now=%s); retryTimerDuration() returns 0 and run() busy-loops", + i.nextRetry, now) +} + +// TestIPControllerElapsedIPRetryDoesNotSpin covers the same inversion on the IP retry +// gate. reconcileIPStatus() refreshes status.nextRetry to now+healthyRetrySchedule on +// every pass, so this gate is only reachable through reconcileAssignment() directly. +func TestIPControllerElapsedIPRetryDoesNotSpin(t *testing.T) { + ctx := context.Background() + var calls int + now := time.Now() + i, ip, providerID := newSpinTestController(ctx, now, &calls) + i.assignableNodes.Add(providerID, true) - // Drive several cycles, advancing the clock to each scheduled wake-up exactly as - // run() would. Any past wake-up means a spin. - for cycle := 0; cycle < 6; cycle++ { - i.reconcile(ctx) - // run() sleeps until i.nextRetry. A wake-up at or before "now" means - // retryTimerDuration() yields 0 and the controller reconciles again - // immediately - a busy loop. (retryTimerDuration itself reads the real wall - // clock rather than i.now(), so it cannot be asserted on directly here.) - require.True(t, i.nextRetry.After(now), - "cycle %d scheduled an immediate wake-up (nextRetry=%s now=%s); run() would busy-loop", - cycle, i.nextRetry, now) - now = i.nextRetry + i.ipToStatus[ip] = &ipStatus{ + state: flipopv1alpha1.IPStateError, + retry: retry{retrySchedule: provider.RetryFast, nextRetry: now.Add(-time.Second)}, } - // And the failure must still be retried rather than silently skipped forever. - require.Greater(t, calls, 1, "assignment should be retried across cycles") + i.reconcileAssignment(ctx) + + require.Equal(t, 1, calls, "an elapsed retry deadline is due; the assignment must be attempted") + require.True(t, i.nextRetry.After(now), + "scheduled an immediate wake-up (nextRetry=%s now=%s); retryTimerDuration() returns 0 and run() busy-loops", + i.nextRetry, now) +} + +// TestIPControllerRunDoesNotSpinOnPersistentFailure is the end-to-end form of the two +// tests above, and the only one that exercises the layer where the bug actually bit: +// run()'s retryTimer. It uses the real clock deliberately - the spin was a disagreement +// between the deadlines reconcile() schedules and the timer run() derives from them, so a +// fake clock cannot see it. +// +// RetryFast begins 1s, 1s, 5s, so a correctly backing-off controller manages a couple of +// attempts in this window. The wedged build managed ~1,280 reconciles/sec. +func TestIPControllerRunDoesNotSpinOnPersistentFailure(t *testing.T) { + if testing.Short() { + t.Skip("uses a real 1.5s timer") + } + ctx, cancel := context.WithCancel(context.Background()) + ip := "192.168.1.1" + providerID := "mock://1" + + var mu sync.Mutex + var assigns, clockReads int + + i := newIPController(logrus.New(), nil, nil) + // Count reconcile passes via the clock rather than via the provider: when the + // controller wedges it skips the provider calls entirely on every pass, so provider + // call counts stay flat while the loop burns CPU. + i.now = func() time.Time { + mu.Lock() + defer mu.Unlock() + clockReads++ + return time.Now() + } + i.updateProviders(&provider.MockIPProvider{ + AssignIPFunc: func(_ context.Context, _ string, _ string) error { + mu.Lock() + defer mu.Unlock() + assigns++ + // Fast-retryable, as a 422 for an unowned IP now classifies. A bare error + // would map to RetrySlow (1m) and never retry inside this window. + return provider.NewRetryError( + errors.New("422 Droplet already has a pending event"), provider.RetryFast) + }, + IPToProviderIDFunc: func(_ context.Context, _ string) (string, error) { + return "", nil + }, + }, nil, "", 0) + + i.ips = []string{ip} + i.ipToStatus[ip] = &ipStatus{} + i.EnableNodes(&corev1.Node{ + ObjectMeta: metav1.ObjectMeta{Name: "node-1", UID: uuid.NewUUID()}, + Spec: corev1.NodeSpec{ProviderID: providerID}, + }) + i.assignableIPs.Add(ip, true) + + i.start(ctx) + time.Sleep(1500 * time.Millisecond) + cancel() + i.stop() + + mu.Lock() + defer mu.Unlock() + // Generous ceilings: the point is orders of magnitude, not an exact count. A healthy + // controller reconciles a handful of times here; the wedged build did ~1,900. + require.Less(t, clockReads, 200, "controller is hot-spinning (%d clock reads in 1.5s)", clockReads) + require.Less(t, assigns, 20, "controller is hot-spinning on AssignIP (%d calls in 1.5s)", assigns) + // ...but it must still be making progress, not wedged. + require.GreaterOrEqual(t, assigns, 2, "controller should have retried the failed assignment") +} + +// TestIPControllerPendingIPRetryIsDeferred is the converse: a deadline still in the future +// must defer, and must not be "fixed" by simply dropping the gate. It also guards the +// naive inversion - healthyRetrySchedule reuses status.nextRetry for the routine status +// refresh, so a gate that ignored the error state would defer every healthy IP forever. +func TestIPControllerPendingIPRetryIsDeferred(t *testing.T) { + ctx := context.Background() + var calls int + now := time.Now() + i, ip, providerID := newSpinTestController(ctx, now, &calls) + i.assignableNodes.Add(providerID, true) + + i.ipToStatus[ip] = &ipStatus{ + state: flipopv1alpha1.IPStateError, + retry: retry{retrySchedule: provider.RetryFast, nextRetry: now.Add(time.Minute)}, + } + + i.reconcileAssignment(ctx) + + require.Zero(t, calls, "a deadline in the future must defer the assignment") + require.Equal(t, now.Add(time.Minute), i.nextRetry, "should wake at the pending deadline") + require.Equal(t, 1, i.assignableIPs.Len(), "deferred IP must stay queued") + require.Equal(t, 1, i.assignableNodes.Len(), "deferred node must stay queued") +} + +// TestIPControllerHealthyIPIsAssignable pins the behaviour that a plain After(now) check +// would break: reconcileIPStatus() sets status.nextRetry to now+5m on every healthy IP +// immediately before reconcileAssignment() runs, so the gate must also require the error +// state or no IP is ever assigned. +func TestIPControllerHealthyIPIsAssignable(t *testing.T) { + ctx := context.Background() + var calls int + now := time.Now() + i, ip, providerID := newSpinTestController(ctx, now, &calls) + i.assignableNodes.Add(providerID, true) + + i.ipToStatus[ip] = &ipStatus{ + state: flipopv1alpha1.IPStateUnassigned, + retry: retry{retrySchedule: healthyRetrySchedule, nextRetry: now.Add(5 * time.Minute)}, + } + + i.reconcileAssignment(ctx) + + require.Equal(t, 1, calls, + "the healthy status-refresh schedule must not be mistaken for an error backoff") } func TestIPControllerDisableNodes(t *testing.T) { diff --git a/pkg/provider/digitalocean_422_test.go b/pkg/provider/digitalocean_422_test.go index c60e243..ae02ce1 100644 --- a/pkg/provider/digitalocean_422_test.go +++ b/pkg/provider/digitalocean_422_test.go @@ -70,3 +70,45 @@ func TestDigitalOceanAssignIP422UnownedIsFastRetryable(t *testing.T) { require.Equal(t, RetryFast, ErrorToRetrySchedule(err), "a 422 for an IP owned by nobody must be fast-retryable") } + +// TestDigitalOceanAssignIP422ProbeFailureIsSlowRetryable is the reason the fast-retry +// branch is guarded on iErr == nil. A failed ownership probe also yields an empty +// curProvider, which is indistinguishable from "owned by nobody" on the value alone. We +// have learned nothing about why the 422 was returned, so it must keep the conservative +// RetrySlow classification rather than be optimistically retried every second. +func TestDigitalOceanAssignIP422ProbeFailureIsSlowRetryable(t *testing.T) { + ctx := context.Background() + ctrl := gomock.NewController(t) + defer ctrl.Finish() + + ipActionsService := mock_godo.NewMockFloatingIPActionsService(ctrl) + ipsService := mock_godo.NewMockFloatingIPsService(ctrl) + + ip := "192.168.1.1" + providerID := "digitalocean://123456789" + + ipActionsService.EXPECT().Assign(gomock.Any(), ip, 123456789).Return( + nil, + &godo.Response{Response: &http.Response{StatusCode: http.StatusUnprocessableEntity}}, + errors.New("422 Droplet already has a pending event"), + ) + + // The ownership probe itself fails, so curProvider is "" for a reason unrelated to + // ownership. + ipsService.EXPECT().Get(gomock.Any(), ip).Return( + nil, + &godo.Response{Response: &http.Response{StatusCode: http.StatusInternalServerError}}, + errors.New("500 internal server error"), + ) + + do := &digitalOcean{ + ipActionsService: ipActionsService, + ipsService: ipsService, + log: log.NewTestLogger(t), + } + + err := do.AssignIP(ctx, ip, providerID) + require.Error(t, err) + require.Equal(t, RetrySlow, ErrorToRetrySchedule(err), + "a 422 whose ownership probe failed must not be treated as fast-retryable") +}