Repository: kubernetes/kubernetes (language: go)

Issue:
kube-controller-manager re-allocating already used PodCIDR (v1.31)
### What happened?

Since upgrading to Kubernetes v1.31 we have occasional observed that `kube-controller-manager` allocates a PodCIDR for a new node which is already allocated for an existing node in the cluster. We have about 200 clusters with a combined number of ca. 6k-10k nodes (autoscaling). It has happened about 10 times since upgrading a week ago, so it's rather rare but breaks the networking between the affected nodes when it happens.

We use flannel as overlay network and it uses the podCIDR assigned by `kube-controller-manager`. When a new node gets an existing podCIDR assigned, then the new node doesn't get ready and it gets terminated after 10 min. We check that the node is routable by all other nodes before we mark the node ready. This never happens because the podCIDR already points to another node in the cluster. When the new node is deleted it has the very unfortunate side effect that all flannels detect the node is deleted and they delete the routes for the podCIDR, problem is just that most nodes will have routes for the other node with the same podCIDR and this then stops working.

Terminating the affected node is the best way to resolve the issue but obviously not sustainable.

### What did you expect to happen?

`kube-controller-manager` should _never_ allocate the same podCIDR to multiple nodes at the same time.

### How can we reproduce it (as minimally and precisely as possible)?

We haven't found a predictable way to reproduce it.

We run with the pod CIDR range: `10.2.0.0/15`.

### Anything else we need to know?

This is how we configure `kube-controller-manager`: https://github.com/zalando-incubator/kubernetes-on-aws/blob/dev/cluster/node-pools/master-default/userdata.yaml#L581-L648 (the image is vanilla Kubernetes built from source and hosted in a private registry)

Here is an example from one cluster with logs:

*Node 1 (original)*:
name: `ip-172-31-14-210.eu-central-1.compute.internal`
podCIDR: `10.2.4.0/24`

*Node 2 (new)*:
name: `ip-172-31-15-241.eu-central-1.compute.internal`
podCIDR: `10.2.4.0/24`

`kube-controller-manager`  logs filtered for the node `ip-172-31-14-210.eu-central-1.compute.internal`:

```
I1001 16:54:22.944453       1 actual_state_of_world.go:540] "Failed to update statusUpdateNeeded field in actual state of world" logger="persistentvolume-attach-detach-controller" err="Failed to set statusUpdateNeeded to needed true, because nodeName=\"ip-172-31-14-210.eu-central-1.compute.internal\" does not exist"
I1001 16:54:23.001587       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 16:54:23.054817       1 node_lifecycle_controller.go:884] "Missing timestamp for Node. Assuming now as a timestamp" logger="node-lifecycle-controller" node="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 16:56:52.839072       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:01:57.639919       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:03:00.584960       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:03:19.873337       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:08:26.273278       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:13:32.137435       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:18:37.436066       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:20:50.207426       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:22:06.023052       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:22:06.058496       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:22:11.270715       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:22:11.376488       1 reconciler.go:275] "attacherDetacher.DetachVolume started" logger="persistentvolume-attach-detach-controller" node="ip-172-31-14-210.eu-central-1.compute.internal" volumeName="kubernetes.io/csi/ebs.csi.aws.com^vol-01a06d931a5cbc177"
I1001 17:22:11.386310       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:22:11.392521       1 operation_generator.go:1539] Verified volume is safe to detach for volume "pvc-0ecc2568-e98d-430d-aa57-d545f7cb8c85" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-01a06d931a5cbc177") on node "ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:22:18.918976       1 operation_generator.go:437] DetachVolume.Detach succeeded for volume "pvc-0ecc2568-e98d-430d-aa57-d545f7cb8c85" (UniqueName: "kubernetes.io/csi/ebs.csi.aws.com^vol-01a06d931a5cbc177") on node "ip-172-31-14-210.eu-central-1.compute.internal"
I1001 17:23:15.637313       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
```

`kube-controller-manager` logs filtered for the node: `ip-172-31-15-241.eu-central-1.compute.internal`:

```
I1001 17:22:45.543797       1 actual_state_of_world.go:540] "Failed to update statusUpdateNeeded field in actual state of world" logger="persistentvolume-attach-detach-controller" err="Failed to set statusUpdateNeeded to needed true, because nodeName=\"ip-172-31-15-241.eu-central-1.compute.internal\" does not exist"
I1001 17:22:45.647668       1 range_allocator.go:422] "Set node PodCIDR" logger="node-ipam-controller" node="ip-172-31-15-241.eu-central-1.compute.internal" podCIDRs=["10.2.4.0/24"]
I1001 17:22:45.648019       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:45.648088       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:45.695174       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:45.702231       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:45.724468       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:45.752257       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:45.820108       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:45.846131       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:22:48.640513       1 node_lifecycle_controller.go:884] "Missing timestamp for Node. Assuming now as a timestamp" logger="node-lifecycle-controller" node="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:23:02.216555       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:23:02.273556       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:23:16.215529       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:23:21.763576       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:23:46.683733       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:25:05.756696       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
I1001 17:25:05.786234       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-15-241.eu-central-1.compute.internal"
```

The interesting lines are:

```
I1001 16:54:23.001587       1 range_allocator.go:241] "Successfully synced" logger="node-ipam-controller" key="ip-172-31-14-210.eu-central-1.compute.internal"
...
I1001 17:22:45.647668       1 range_allocator.go:422] "Set node PodCIDR" logger="node-ipam-controller" node="ip-172-31-15-241.eu-central-1.compute.internal" podCIDRs=["10.2.4.0/24"]
```

At `16:54` the original node is `Successfully synced` by the `node-ipam-controller` and at `17:22`, much later, does the new node get the same podCIDR allocated as what is already allocated to the original node.

We can also see this from the flannel logs on the new node:

```
 time="2024-10-01T17:22:58Z" level=info msg="Added new node ip-172-31-14-210.eu-central-1.compute.internal with PodCIDR 10.2.4.0/24, address 10.2.4.0"
```

### Kubernetes version

<details>

```console
$ kubectl version
Client Version: v1.31.0
Kustomize Version: v5.4.2
Server Version: v1.31.0
```

</details>


### Cloud provider

<details>
AWS running a custom Kubernetes setup on EC2
</details>


### OS version

<details>

```console
# On Linux:
$ cat /etc/os-release
# paste output here
$ uname -a
# paste output here

# On Windows:
C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture
# paste output here
```

</details>


### Install tools


<details>

</details>


### Container runtime (CRI) and version (if applicable)

<details>

</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>

</details>



Discussion / hints:
/sig network api-machinery

/assign @aojea

Hi Antonio. Can you have a look at this? Thanks
@mikkeloscar can you grep for `Set node PodCIDR` on the kube-controller-manager logs? when `10.2.4.0/24` gets allocated twice? it has to be show on the logs
It turns out that the example I shared is likely a false positive where the old node was being terminated and the new node was getting/taking over that podCIDR. It's a bit hard to tell if there was a short overlap or not, I don't have the node objects at the time so not sure about each their state. The condition was only present for a single check interval (we check for the condition once every minute).

This means that we didn't see this issue since last weekend, where the overlap was for 10 min. but I don't have the logs of kube-controller-manager from that case so hard to give more context.

Based on this I will close this issue for now and only get back and re-open if we see it again and have more logs to better show the situation.
This is a common problem with spot vms, please validate that flannel check the deletiontimestamp of the object on an Update event and not the Delete event, 
Hey I'm back!

I believe I finally understand what is happening.

We are managing the majority of our nodes via [karpenter](https://github.com/aws/karpenter-provider-aws) and it is setting a finalizer on nodes which leads to nodes in this state when being deleted. It can be in this state for a long time if karpenter is stuck draining a node:

```yaml
metadata
  ...
  deletionTimestamp: "2024-10-16T09:54:24Z"
  finalizers:
  - karpenter.sh/termination
```

This particular node was in deletion state for over a day because of a PDB blocking the deletion of a pod.

Looking at the nodeipam controller code it looks like it doesn't consider finalizers when releasing the podCIDR, so it's basically releasing the podCIDR of a still running node and sometimes new nodes happen to get that same podCIDR:

https://github.com/kubernetes/kubernetes/blob/948afe5ca072329a73c8e79ed5938717a5cb3d21/pkg/controller/nodeipam/ipam/range_allocator.go#L270-L274

It's a bit questionable that karpenter would mark a node for deletion when it had pods with PDBs as it can lead to other problems of a mostly empty node wasting resources, but since this condition is allowed by Kubernetes I think the nodeipam should handle finalizers correctly to not hand out the same podCIDR to multiple nodes.

This is the PR which introduced the change to nodeipam controller: https://github.com/kubernetes/kubernetes/pull/123238 this was introduced in v1.31 which explains why we didn't see this issue on v1.30. Before v1.31 the release of CIDR was _only_ done on a node delete event:

https://github.com/kubernetes/kubernetes/blob/74e84a90c725047b1328ff3d589fedb1cb7a120e/pkg/controller/nodeipam/ipam/range_allocator.go#L161-L163
> I think the nodeipam should handle finalizers correctly to node hand out the same podCIDR to multiple nodes.

yes, if the podCIDR is still in use it should not be released

/triage accepted

This seems as simple as

```diff
diff --git a/pkg/controller/nodeipam/ipam/range_allocator.go b/pkg/controller/nodeipam/ipam/range_allocator.go
index a79982a6db2..97ac56b94fd 100644
--- a/pkg/controller/nodeipam/ipam/range_allocator.go
+++ b/pkg/controller/nodeipam/ipam/range_allocator.go
@@ -270,7 +270,7 @@ func (r *rangeAllocator) syncNode(ctx context.Context, key string) error {
        // Check the DeletionTimestamp to determine if object is under deletion.
        if !node.DeletionTimestamp.IsZero() {
                logger.V(3).Info("node is being deleted", "node", key)
-               return r.ReleaseCIDR(logger, node)
+               return nil
        }
        return r.AllocateOrOccupyCIDR(ctx, node)
 }
```

@mikkeloscar do you want to contribute the fix?
The only missing thing is added an unit test to cover from regressions
(if you don't want to contribute a fix, I'll happily take it)
@adrianmoisey  you're welcome to take it!
/assign @adrianmoisey 
/kind regression

we need to backport this to 1.31
jFYI: We have been running a custom kube-controller-manager with the [patch](https://github.com/kubernetes/kubernetes/issues/127792#issuecomment-2419901538) suggested by @aojea since Friday, and did not see the issue since then.
That's amazing! I guess all I need to do is write some e2e tests

Fix patch:
diff --git a/pkg/controller/nodeipam/ipam/range_allocator.go b/pkg/controller/nodeipam/ipam/range_allocator.go
index a79982a6db2d5..036030db5160f 100644
--- a/pkg/controller/nodeipam/ipam/range_allocator.go
+++ b/pkg/controller/nodeipam/ipam/range_allocator.go
@@ -145,16 +145,22 @@ func NewCIDRRangeAllocator(ctx context.Context, client clientset.Interface, node
 		DeleteFunc: func(obj interface{}) {
 			// The informer cache no longer has the object, and since Node doesn't have a finalizer,
 			// we don't see the Update with DeletionTimestamp != 0.
-			// TODO: instead of executing the operation directly in the handler, build a small cache with key node.Name
-			// and value PodCIDRs use ReleaseCIDR on the reconcile loop so we can retry on `ReleaseCIDR` failures.
-			if err := ra.ReleaseCIDR(logger, obj.(*v1.Node)); err != nil {
-				utilruntime.HandleError(fmt.Errorf("error while processing CIDR Release: %w", err))
+			node, ok := obj.(*v1.Node)
+			if !ok {
+				tombstone, ok := obj.(cache.DeletedFinalStateUnknown)
+				if !ok {
+					utilruntime.HandleError(fmt.Errorf("unexpected object type: %v", obj))
+					return
+				}
+				node, ok = tombstone.Obj.(*v1.Node)
+				if !ok {
+					utilruntime.HandleError(fmt.Errorf("unexpected object types: %v", obj))
+					return
+				}
 			}
-			// IndexerInformer uses a delta nodeQueue, therefore for deletes we have to use this
-			// key function.
-			key, err := cache.DeletionHandlingMetaNamespaceKeyFunc(obj)
-			if err == nil {
-				ra.queue.Add(key)
+			if err := ra.ReleaseCIDR(logger, node); err != nil {
+				utilruntime.HandleError(fmt.Errorf("error while processing CIDR Release: %w", err))
+
 			}
 		},
 	})
@@ -270,7 +276,7 @@ func (r *rangeAllocator) syncNode(ctx context.Context, key string) error {
 	// Check the DeletionTimestamp to determine if object is under deletion.
 	if !node.DeletionTimestamp.IsZero() {
 		logger.V(3).Info("node is being deleted", "node", key)
-		return r.ReleaseCIDR(logger, node)
+		return nil
 	}
 	return r.AllocateOrOccupyCIDR(ctx, node)
 }


Test patch:
diff --git a/pkg/controller/nodeipam/ipam/range_allocator_test.go b/pkg/controller/nodeipam/ipam/range_allocator_test.go
index 109da26ea2c6c..bc8ebcdaf2ad3 100644
--- a/pkg/controller/nodeipam/ipam/range_allocator_test.go
+++ b/pkg/controller/nodeipam/ipam/range_allocator_test.go
@@ -841,3 +841,109 @@ func TestReleaseCIDRSuccess(t *testing.T) {
 		testFunc(tc)
 	}
 }
+func TestNodeDeletionReleaseCIDR(t *testing.T) {
+	_, clusterCIDRv4, err := netutils.ParseCIDRSloppy("10.10.0.0/16")
+	if err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+
+	_, allocatedCIDR, err := netutils.ParseCIDRSloppy("10.10.0.0/24")
+	if err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	testCases := []struct {
+		description       string
+		nodeKey           string
+		existingNodes     []*v1.Node
+		shouldReleaseCIDR bool
+	}{
+		{
+			description: "Regular node not under deletion",
+			nodeKey:     "node0",
+			existingNodes: []*v1.Node{
+				{
+					ObjectMeta: metav1.ObjectMeta{
+						Name: "node0",
+					},
+					Spec: v1.NodeSpec{
+						PodCIDR:  allocatedCIDR.String(),
+						PodCIDRs: []string{allocatedCIDR.String()}},
+				},
+			},
+			shouldReleaseCIDR: false,
+		},
+		{
+			description: "Node under deletion",
+			nodeKey:     "node0",
+			existingNodes: []*v1.Node{
+				{
+					ObjectMeta: metav1.ObjectMeta{
+						Name:              "node0",
+						DeletionTimestamp: &metav1.Time{Time: time.Now()},
+					},
+					Spec: v1.NodeSpec{
+						PodCIDR:  allocatedCIDR.String(),
+						PodCIDRs: []string{allocatedCIDR.String()}},
+				},
+			},
+			shouldReleaseCIDR: false,
+		},
+		{
+			description:       "Node deleted",
+			nodeKey:           "node0",
+			existingNodes:     []*v1.Node{},
+			shouldReleaseCIDR: true,
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.description, func(t *testing.T) {
+			allocatorParams := CIDRAllocatorParams{
+				ClusterCIDRs: []*net.IPNet{clusterCIDRv4}, ServiceCIDR: nil,
+				SecondaryServiceCIDR: nil,
+				NodeCIDRMaskSizes:    []int{24},
+			}
+
+			fakeNodeHandler := &testutil.FakeNodeHandler{
+				Existing:  tc.existingNodes,
+				Clientset: fake.NewSimpleClientset(),
+			}
+			_, tCtx := ktesting.NewTestContext(t)
+
+			fakeNodeInformer := test.FakeNodeInformer(fakeNodeHandler)
+			nodeList, err := fakeNodeHandler.List(tCtx, metav1.ListOptions{})
+			if err != nil {
+				t.Fatalf("Failed to get list of nodes %v", err)
+			}
+			allocator, err := NewCIDRRangeAllocator(tCtx, fakeNodeHandler, fakeNodeInformer, allocatorParams, nodeList)
+			if err != nil {
+				t.Fatalf("failed to create CIDRRangeAllocator: %v", err)
+			}
+			rangeAllocator, ok := allocator.(*rangeAllocator)
+			if !ok {
+				t.Fatalf("found non-default implementation of CIDRAllocator")
+			}
+			rangeAllocator.nodesSynced = test.AlwaysReady
+			rangeAllocator.recorder = testutil.NewFakeRecorder()
+
+			rangeAllocator.syncNode(tCtx, tc.nodeKey)
+
+			if len(rangeAllocator.cidrSets) != 1 {
+				t.Fatalf("Expected a single cidrSet, but got %d", len(rangeAllocator.cidrSets))
+			}
+
+			// if the allocated CIDR was released we expect the nextAllocated CIDR to be the same
+			nextCIDR, err := rangeAllocator.cidrSets[0].AllocateNext()
+			if err != nil {
+				t.Fatalf("unexpected error trying to allocate next CIDR: %v", err)
+			}
+			expectedCIDR := "10.10.1.0/24" // existing allocated is 10.0.0.0/24
+			if tc.shouldReleaseCIDR {
+				expectedCIDR = allocatedCIDR.String() // if cidr was released we expect to reuse it. ie: 10.0.0.0/24
+			}
+			if nextCIDR.String() != expectedCIDR {
+				t.Fatalf("Expected CIDR %s to be allocated next, but got: %v", expectedCIDR, nextCIDR.String())
+			}
+		})
+	}
+}