Repository: kubernetes/kubernetes (language: go)

Issue:
kube-proxy: initialization check race leads to stale UDP conntrack
### What happened?

AKS had a customer report repeated issues in their clusters where:
1. kube-proxy would redeploy (e.g. due to AKS deploying a new kube-proxy image with CVE fixes)
2. Envoy c-ares DNS client would send repeated DNS queries to the kube-dns service VIP from the same src IP address, creating a UDP conntrack entry to the svc VIP and keeping it alive. For example, with kube-dns svc VIP 192.168.0.10, conntrack showed:
```
# conntrack -L | grep 192.168.0.10 | grep UNREPLIED
udp      17 29 src=10.120.1.150 dst=192.168.0.10 sport=49660 dport=53 [UNREPLIED] src=192.168.0.10 dst=10.120.1.150 sport=53 dport=49660 mark=0 use=1
conntrack v1.4.5 (conntrack-tools): 2273 flow entries have been shown
```

3. DNS queries to the svc VIP were blackholed until the customer manually ran a command like: `conntrack -D -p udp --src 10.120.1.150 --sport 49660`

Issue occurred only in clusters with many services and endpoints (~10k services and ~6k endpoints). However, the customer has seen this issue repeatedly for months, about 1-5 times per week across their clusters.

### What did you expect to happen?

kube-proxy code to delete stale UDP conntrack entries should have deleted the conntrack entry to kube-dns svc VIP automatically in the first sync after service and endpointslice cache is initialized.

### How can we reproduce it (as minimally and precisely as possible)?

Unfortunately, the customer said they were unable to reproduce this issue in other environments outside of their production clusters. AKS engineers were also unable to repro this issue.

**Update (2024-08-03)**: I'm now able to reproduce the issue using a DNS client that reuses the same src IP / port and clears DNAT conntrack entries between queries, in a k8s 1.29.7 cluster with 2,000 services. The bug is triggered reliably in this setup with `kubectl rollout restart -n kube-system ds/kube-proxy` The test client code, scripts, and steps to reproduce are in this repository: https://github.com/wedaly/dns-blackhole-tester

### Anything else we need to know?


The customer shared kube-proxy logs (at verbosity "3") from when the issue occurred. Unfortunately, I don't have permission to share the full logs publicly, but I think what I'm seeing in the logs gives a clue about what's happening.

1. By 05:00:02.477433 nodes, endpointslices, and services all synced:
```
I0723 05:00:02.000779       1 config.go:322] "Calling handler.OnNodeSynced()"
I0723 05:00:02.177877       1 config.go:104] "Calling handler.OnEndpointSlicesSynced()"
I0723 05:00:02.477433       1 config.go:195] "Calling handler.OnServiceSynced()"
```

2. kube-dns endpointslices processed after `OnEndpointSlicesSynced()`, but before iptables sync:
```
I0723 05:00:02.760960       1 endpointslicecache.go:358] "Setting endpoints for service port name" portName="kube-system/kube-dns:dns
```

3. First iptables sync at 05:00:02.81104 shows **4658** services, which is much less than the number of services in the cluster. (We can't see if kube-dns is one of these services, since kube-proxy at `-v=3` doesn't log which services were processed.)
```
I0723 05:00:02.811044       1 proxier.go:790] "Syncing iptables rules"
I0723 05:00:04.611400       1 proxier.go:1497] "Reloading service iptables data" numServices=4658 numEndpoints=3188 numFilterChains=6 numFilterRules=2919 numNATChains=9867 numNATRules=18214
I0723 05:00:05.721503       1 proxier.go:784] "SyncProxyRules complete" elapsed="3.244002731s"
```

4. Between `OnServiceSynced()` at 05:00:02.47743 and the next sync at 05:00:05.799348, we see thousands of lines that look like services and endpointslices updates:
```
I0723 05:00:02.492956       1 endpointslicecache.go:358] "Setting endpoints for service port name"
...
I0723 05:00:02.810688       1 utils.go:133] "Skipping service due to cluster IP"
```

5. Second sync at 05:00:05.799348 shows **9605** services:
```
I0723 05:00:05.799348       1 proxier.go:1497] "Reloading service iptables data" numServices=9605 numEndpoints=6244 numFilterChains=6 numFilterRules=5978 numNATChains=4978 numNATRules=14818
```

I believe this could explain why kube-proxy does not clean up the stale UDP conntrack entry:

* kube-proxy detects that the endpointslice and service caches are synced using [`endpointSliceInformer.Informer().HasSynced`](https://github.com/kubernetes/kubernetes/blob/2c184e444f7878bf1f017ed29e59c52f41bebe2e/pkg/proxy/config/config.go#L75) and [`serviceInformer.Informer().HasSynced`](https://github.com/kubernetes/kubernetes/blob/2c184e444f7878bf1f017ed29e59c52f41bebe2e/pkg/proxy/config/config.go#L166C17-L166C53) respectively.
* Comments on the [`HasSynced` method in the `SharedInformer` interface](https://github.com/kubernetes/kubernetes/blob/b5b21717cac7c02f2f754feb3e07b24a9d85a2fc/staging/src/k8s.io/client-go/tools/cache/shared_informer.go#L174-L181) say that this indicates that the informer cache is up-to-date, but warns "Note that this doesn't tell you if an individual handler is synced!! For that, please call HasSynced on the handle returned by AddEventHandler."
* This comment, along with the output of kube-proxy logs, makes me suspect that kube-proxy is initiating a sync *before* it has received and processed all the services and endpoints in the informer cache.
* If so, this could explain why the "delete conntrack" codepath is skipped.
   - kube-proxy deletes stale conntrack entries for UDP services that are updated from [0 endpoints to at least one endpoint](https://github.com/kubernetes/kubernetes/blob/b5b21717cac7c02f2f754feb3e07b24a9d85a2fc/pkg/proxy/endpointschangetracker.go#L323-L350) *and* are in [`svcPortMap`](https://github.com/kubernetes/kubernetes/blob/b5b21717cac7c02f2f754feb3e07b24a9d85a2fc/pkg/proxy/conntrack/cleanup.go#L87).
   - If in the first sync `svcPortMap` is missing kube-dns, but `DeletedUDPEndpoints` includes kube-dns, then kube-proxy would [skip deletion of the stale conntrack entry](https://github.com/kubernetes/kubernetes/blob/b5b21717cac7c02f2f754feb3e07b24a9d85a2fc/pkg/proxy/conntrack/cleanup.go#L87). Subsequent syncs would see at least one endpoint for kube-dns, so would continue to skip deletion.

If this theory is correct, then I wonder if kube-proxy could change the initialization check to ensure that all pre-sync events from the informer cache are delivered before the first iptables sync, maybe like this:

```diff
diff --git a/pkg/proxy/config/config.go b/pkg/proxy/config/config.go
index 373cd0a1c64..5097ab52715 100644
--- a/pkg/proxy/config/config.go
+++ b/pkg/proxy/config/config.go
@@ -78,11 +78,10 @@ type EndpointSliceConfig struct {
 // NewEndpointSliceConfig creates a new EndpointSliceConfig.
 func NewEndpointSliceConfig(ctx context.Context, endpointSliceInformer discoveryv1informers.EndpointSliceInformer, resyncPeriod time.Duration) *EndpointSliceConfig {
 	result := &EndpointSliceConfig{
-		listerSynced: endpointSliceInformer.Informer().HasSynced,
-		logger:       klog.FromContext(ctx),
+		logger: klog.FromContext(ctx),
 	}
 
-	_, _ = endpointSliceInformer.Informer().AddEventHandlerWithResyncPeriod(
+	handlerRegistration, _ := endpointSliceInformer.Informer().AddEventHandlerWithResyncPeriod(
 		cache.ResourceEventHandlerFuncs{
 			AddFunc:    result.handleAddEndpointSlice,
 			UpdateFunc: result.handleUpdateEndpointSlice,
@@ -91,6 +90,8 @@ func NewEndpointSliceConfig(ctx context.Context, endpointSliceInformer discovery
 		resyncPeriod,
 	)
 
+	result.listerSynced = handlerRegistration.HasSynced
+
 	return result
 }
 
@@ -171,11 +172,10 @@ type ServiceConfig struct {
 // NewServiceConfig creates a new ServiceConfig.
 func NewServiceConfig(ctx context.Context, serviceInformer v1informers.ServiceInformer, resyncPeriod time.Duration) *ServiceConfig {
 	result := &ServiceConfig{
-		listerSynced: serviceInformer.Informer().HasSynced,
-		logger:       klog.FromContext(ctx),
+		logger: klog.FromContext(ctx),
 	}
 
-	_, _ = serviceInformer.Informer().AddEventHandlerWithResyncPeriod(
+	handlerRegistration, _ := serviceInformer.Informer().AddEventHandlerWithResyncPeriod(
 		cache.ResourceEventHandlerFuncs{
 			AddFunc:    result.handleAddService,
 			UpdateFunc: result.handleUpdateService,
@@ -184,6 +184,8 @@ func NewServiceConfig(ctx context.Context, serviceInformer v1informers.ServiceIn
 		resyncPeriod,
 	)
 
+	result.listerSynced = handlerRegistration.HasSynced
+
 	return result
 }
```

**Should kube-proxy wait until all pre-sync events are *delivered* before setting `isInitialized=true`?**


### Kubernetes version

kube-proxy version is v1.28.5
```
I0723 05:00:01.875477       1 server.go:846] "Version info" version="v1.28.5"
```

Note that the kube-proxy image that AKS built for 1.28.5 includes the backported patch to fix this race condition in iptables partial sync: https://github.com/kubernetes/kubernetes/pull/122757 

### Cloud provider

Azure Kubernetes Service


### OS version

Linux (I don't have the exact version but could get it if it's relevant)

### Install tools

N/A

### Container runtime (CRI) and version (if applicable)

N/A

### Related plugins (CNI, CSI, ...) and versions (if applicable)

N/A


Discussion / hints:

Fix patch:
diff --git a/pkg/proxy/config/config.go b/pkg/proxy/config/config.go
index 373cd0a1c64b5..5097ab5271535 100644
--- a/pkg/proxy/config/config.go
+++ b/pkg/proxy/config/config.go
@@ -78,11 +78,10 @@ type EndpointSliceConfig struct {
 // NewEndpointSliceConfig creates a new EndpointSliceConfig.
 func NewEndpointSliceConfig(ctx context.Context, endpointSliceInformer discoveryv1informers.EndpointSliceInformer, resyncPeriod time.Duration) *EndpointSliceConfig {
 	result := &EndpointSliceConfig{
-		listerSynced: endpointSliceInformer.Informer().HasSynced,
-		logger:       klog.FromContext(ctx),
+		logger: klog.FromContext(ctx),
 	}
 
-	_, _ = endpointSliceInformer.Informer().AddEventHandlerWithResyncPeriod(
+	handlerRegistration, _ := endpointSliceInformer.Informer().AddEventHandlerWithResyncPeriod(
 		cache.ResourceEventHandlerFuncs{
 			AddFunc:    result.handleAddEndpointSlice,
 			UpdateFunc: result.handleUpdateEndpointSlice,
@@ -91,6 +90,8 @@ func NewEndpointSliceConfig(ctx context.Context, endpointSliceInformer discovery
 		resyncPeriod,
 	)
 
+	result.listerSynced = handlerRegistration.HasSynced
+
 	return result
 }
 
@@ -171,11 +172,10 @@ type ServiceConfig struct {
 // NewServiceConfig creates a new ServiceConfig.
 func NewServiceConfig(ctx context.Context, serviceInformer v1informers.ServiceInformer, resyncPeriod time.Duration) *ServiceConfig {
 	result := &ServiceConfig{
-		listerSynced: serviceInformer.Informer().HasSynced,
-		logger:       klog.FromContext(ctx),
+		logger: klog.FromContext(ctx),
 	}
 
-	_, _ = serviceInformer.Informer().AddEventHandlerWithResyncPeriod(
+	handlerRegistration, _ := serviceInformer.Informer().AddEventHandlerWithResyncPeriod(
 		cache.ResourceEventHandlerFuncs{
 			AddFunc:    result.handleAddService,
 			UpdateFunc: result.handleUpdateService,
@@ -184,6 +184,8 @@ func NewServiceConfig(ctx context.Context, serviceInformer v1informers.ServiceIn
 		resyncPeriod,
 	)
 
+	result.listerSynced = handlerRegistration.HasSynced
+
 	return result
 }
 


Test patch: