Repository: kubernetes/kubernetes (language: go)

Issue:
[Flaking Test] ci-kubernetes-unit (Unexpected event resourceVersion 2 less than or equal to bookmark 2)
### Which jobs are flaking?

sig-release-master-blocking
- ci-kubernetes-unit

### Which tests are flaking?

`k8s.io/apiserver/pkg/storage/cacher.cacher`

### Since when has it been flaking?

05/30/2024 19:25 IST
Prow Logs: https://prow.k8s.io/view/gs/kubernetes-jenkins/logs/ci-kubernetes-unit/1796177771727163392
Triage: https://storage.googleapis.com/k8s-triage/index.html?test=k8s.io%2Fapiserver%2Fpkg%2Fstorage%2Fcacher.cacher

### Testgrid link

https://testgrid.k8s.io/sig-release-master-blocking#ci-kubernetes-unit

### Reason for failure (if possible)

```
{Failed;  === RUN   TestWatchBookmarksWithCorrectResourceVersion
W0530 14:27:24.502997   70007 logging.go:59] [core] [Channel #387 SubChannel #390] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:38087", ServerName: "localhost:38087", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:38087: connect: connection refused"
W0530 14:27:24.503472   70007 logging.go:59] [core] [Channel #435 SubChannel #438] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:37907", ServerName: "localhost:37907", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:37907: connect: connection refused"
W0530 14:27:24.817666   70007 logging.go:59] [core] [Channel #460 SubChannel #462] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:32897", ServerName: "localhost:32897", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:32897: connect: connection refused"
W0530 14:27:25.178669   70007 reflector.go:556] storage/cacher.go:/pods: failed to list *example.Pod: injected error
E0530 14:27:25.178720   70007 cacher.go:476] cacher (pods): unexpected ListAndWatch error: failed to list *example.Pod: injected error; reinitializing...
W0530 14:27:25.368480   70007 logging.go:59] [core] [Channel #472 SubChannel #473] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:41447", ServerName: "localhost:41447", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:41447: connect: connection refused"
W0530 14:27:25.885017   70007 logging.go:59] [core] [Channel #292 SubChannel #293] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:43397", ServerName: "localhost:43397", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:43397: connect: connection refused"
W0530 14:27:25.940337   70007 logging.go:59] [core] [Channel #400 SubChannel #402] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:32947", ServerName: "localhost:32947", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:32947: connect: connection refused"
    watcher_tests.go:1205: Unexpected event resourceVersion 2 less than or equal to bookmark 2)
W0530 14:27:26.194730   70007 logging.go:59] [core] [Channel #483 SubChannel #485] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:34213", ServerName: "localhost:34213", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:34213: connect: connection refused"
--- FAIL: TestWatchBookmarksWithCorrectResourceVersion (1.83s)
;}
```

### Anything else we need to know?

_No response_

### Relevant SIG(s)

/sig


Discussion / hints:
This issue is currently awaiting triage.

If a SIG or subproject determines this is a relevant issue, they will accept it by applying the `triage/accepted` label and provide further guidance.

The `triage/accepted` label can be added by org members by writing `/triage accepted` in a comment.


<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes-sigs/prow](https://github.com/kubernetes-sigs/prow/issues/new?title=Prow%20issue:) repository.
</details>
/sig storage
@kubernetes/release-team-release-signal 
/sig api-machinery
/cc @serathius @p0lyn0mial 

This started last week, but it seems to be fairly rare, so might be a consequence of something a bit earlier.

The value of "2" suggests that it's happening on the first event, and my brain goes towards: https://github.com/kubernetes/kubernetes/pull/124754/files

@p0lyn0mial - will you be able to take a look at it?

> @p0lyn0mial - will you be able to take a look at it?

sure, I will have a look.

/assign @p0lyn0mial 
We chatted with @p0lyn0mial about that offline and it seems like a real correctness issue.

Regression indeed introduced by https://github.com/kubernetes/kubernetes/pull/124754/files

We have a race with setting RV in watchcache and incoming events.

The current explanation is:
1. watchcache initializeds with RV=N
2. an event comes with RV=N+1 [but wasn't yet dispatched]
3. the polling introduced in that PR catches RV=N+1
4. only then the event (with RV=N+1) is received
@wojtek-t @p0lyn0mial So it is a release blocker, then? (Upcoming alpha 1 release cut scheduled for tomorrow)

Fix patch:
diff --git a/staging/src/k8s.io/apiserver/pkg/storage/cacher/cacher.go b/staging/src/k8s.io/apiserver/pkg/storage/cacher/cacher.go
index bbb510fcb7397..2922f4804ee27 100644
--- a/staging/src/k8s.io/apiserver/pkg/storage/cacher/cacher.go
+++ b/staging/src/k8s.io/apiserver/pkg/storage/cacher/cacher.go
@@ -912,10 +912,10 @@ func (c *Cacher) dispatchEvents() {
 	// The first successful sync with the underlying store.
 	// The cache must wait until this first sync is completed to be deemed ready.
 	// Since we cannot send a bookmark when the lastProcessedResourceVersion is 0,
-	// we poll aggressively for the first RV before entering the dispatch loop.
+	// we poll aggressively for the first list RV before entering the dispatch loop.
 	lastProcessedResourceVersion := uint64(0)
 	if err := wait.PollUntilContextCancel(wait.ContextForChannel(c.stopCh), 10*time.Millisecond, true, func(_ context.Context) (bool, error) {
-		if rv := c.watchCache.getResourceVersion(); rv != 0 {
+		if rv := c.watchCache.getListResourceVersion(); rv != 0 {
 			lastProcessedResourceVersion = rv
 			return true, nil
 		}
diff --git a/staging/src/k8s.io/apiserver/pkg/storage/cacher/watch_cache.go b/staging/src/k8s.io/apiserver/pkg/storage/cacher/watch_cache.go
index 1f65be9705ef8..642619ff20218 100644
--- a/staging/src/k8s.io/apiserver/pkg/storage/cacher/watch_cache.go
+++ b/staging/src/k8s.io/apiserver/pkg/storage/cacher/watch_cache.go
@@ -644,10 +644,10 @@ func (w *watchCache) Resync() error {
 	return nil
 }
 
-func (w *watchCache) getResourceVersion() uint64 {
+func (w *watchCache) getListResourceVersion() uint64 {
 	w.RLock()
 	defer w.RUnlock()
-	return w.resourceVersion
+	return w.listResourceVersion
 }
 
 func (w *watchCache) currentCapacity() int {


Test patch: