ReplicaSetController can miss handling the deletion of a ReplicaSet

[zegl]

Is this a BUG REPORT or FEATURE REQUEST?:
/kind bug

What happened:

@ncdc's description hoisted from #69376 (comment):

I was about to file this. I spent yesterday triaging it and have determined the root cause. The issue is that the ReplicaSetController can "miss" handling the deletion of a ReplicaSet if things happen quickly enough. Here's the flow:

1. Client creates rs
2. ReplicaSetController sees new rs, starts working on creating pods
3. Client deletes rs
4. ReplicaSetController's rsInformer see the rs deletion and calls rsc.enqueueReplicaSet, which adds the namespace/name of the rs to the work queue
5. Client recreates rs with the exact same name as before
6. ReplicaSetController's rsInformer see the rs addition and calls rsc.enqueueReplicaSet, which adds the namespace/name of the rs to the work queue (again)
7. ReplicaSetController's sync handler processes the entry from the queue
8. Because the rs was recreated with the same name, when syncReplicaSet calls rsLister to get the rs, it's there (it's the 2nd one)

This is a timing issue. The ReplicaSetController doesn't check the rs's UID, and if the order of operations is "just right", the controller's sync handler won't "see" the deletion, so it never calls rsc.expectations.DeleteExpectations(key) to reflect that the rs was deleted.

/sig apps

Original description follows:

In #69344 I had to re-run the integration test 4 times to get it to work.

Log outputs:

• attempt 1
• attempt 2
• attempt 3
• attempt 4 (successful)

[neolit123]

/kind flake
/sig testing

[neolit123]

/remove-kind failing-test

[ncdc]

I was about to file this. I spent yesterday triaging it and have determined the root cause. The issue is that the ReplicaSetController can "miss" handling the deletion of a ReplicaSet if things happen quickly enough. Here's the flow:

1. Client creates rs
2. ReplicaSetController sees new rs, starts working on creating pods
3. Client deletes rs
4. ReplicaSetController's rsInformer see the rs deletion and calls rsc.enqueueReplicaSet, which adds the namespace/name of the rs to the work queue
5. Client recreates rs with the exact same name as before
6. ReplicaSetController's rsInformer see the rs addition and calls rsc.enqueueReplicaSet, which adds the namespace/name of the rs to the work queue (again)
7. ReplicaSetController's sync handler processes the entry from the queue
8. Because the rs was recreated with the same name, when syncReplicaSet calls rsLister to get the rs, it's there (it's the 2nd one)

This is a timing issue. The ReplicaSetController doesn't check the rs's UID, and if the order of operations is "just right", the controller's sync handler won't "see" the deletion, so it never calls rsc.expectations.DeleteExpectations(key) to reflect that the rs was deleted.

/sig apps

[ncdc]

For a bit more clarity:

When the rs informer sees a new rs, it calls

kubernetes/pkg/controller/replicaset/replica_set.go

Line 142 in 7bc48ba

AddFunc: rsc.enqueueReplicaSet,

When the rs informer sees a deleted rs, it calls

kubernetes/pkg/controller/replicaset/replica_set.go

Line 147 in 7bc48ba

DeleteFunc: rsc.enqueueReplicaSet,

The net effect is

kubernetes/pkg/controller/replicaset/replica_set.go

Line 417 in 7bc48ba

rsc.queue.Add(key)

Once a key ($namespace/$name) is in the queue, syncReplicaSet pops it off and then does

kubernetes/pkg/controller/replicaset/replica_set.go

Lines 582 to 587 in 7bc48ba

	rs, err := rsc.rsLister.ReplicaSets(namespace).Get(name)
	if errors.IsNotFound(err) {
	glog.V(4).Infof("%v %v has been deleted", rsc.Kind, key)
	rsc.expectations.DeleteExpectations(key)
	return nil
	}

The problem here is that there's not necessarily a guarantee that the order of operations is always like this:

1. AddFunc -> enqueueReplicaSet -> pop -> rsLister.Get() -> normal processing
2. DeleteFunc -> enqueueReplicaSet -> pop -> rsLister.Get() -> not found -> delete expectations
3. AddFunc -> enqueueReplicaSet -> pop -> rsLister.Get() -> normal processing

When the test fails, this is what happens:

1. AddFunc -> enqueueReplicaSet -> pop -> rsLister.Get() -> normal processing
2. DeleteFunc -> enqueueReplicaSet (note the change here - no pop!)
3. AddFunc -> enqueueReplicaSet -> pop -> rsLister.Get() -> normal processing

I confirmed this by adding some additional print statements to AddFunc and DeleteFunc. The DeleteFunc is always called at the "right" time. But sometimes syncReplicaSet isn't scheduled fast enough, so the new rs is already visible by the time syncReplicaSet is executed.

[spiffxp]

/milestone v1.13
FYI @jberkus

Yeah this is definitely becoming more of a problem, the daily failure rate for pull-integration-test is over 50%

It shows up on triage, but I can't point to when it started become more flaky: https://storage.googleapis.com/k8s-gubernator/triage/index.html?pr=1&job=integration

[spiffxp]

/priority critical-urgent

[ncdc]

@kubernetes/sig-apps-bugs do you think the controller should change to differentiate between two replicasets with the same name but different UIDs?

[mattfarina]

cc @caesarxuchao @lavalamp @enisoc @kow3ns

[mortent]

The flaky test is actually testing kubectl, so an option is to split this into two issues. We can fix the test to avoid this problem, which would fix the flakiness for people working on other things. And then separately come up with a fix for the issue in replicaset.

I created a PR that updates the test to avoid creating replicasets with the same name: #69739

[lavalamp]

The replica set controller needs a fix. Thanks for the clear description, @ncdc.

/assign @kow3ns

[lavalamp]

Alternatively, perhaps we could fix this by adding UID to the key used in the delta fifo?

[spiffxp]

https://storage.googleapis.com/k8s-gubernator/triage/index.html?pr=1&job=integration#3e7dba9374ac0dbc9c11 @kow3ns so flakes are definitely down now that we're working around this (thanks @mortent!), but do we have an issue for the "proper" fix @lavalamp proposed?

[kow3ns]

/assign janetkuo

[kow3ns]

We should get a fix in for the next release

[AishSundar]

As per @kow3ns comment, moving this to 1.14

/milestone v1.14

[nikopen]

(tracking update - in progress #72927)

[nikopen]

This is an important bug but the fix in #72927 still needs work @runyontr

Shifting milestones
/milestone v1.15

@kow3ns @spiffxp

[timmycarr]

Hi! We are starting the code freeze for 1.15 tomorrow EOD. Just checking in to see if this issue still planned for the 1.15 cycle?

[lavalamp]

I think #72927 is pretty close, I left a few comments.

[soggiest]

/milestone v1.16

[Pothulapati]

Hello! I'm part of the bug triage team for the 1.16 release cycle and considering this issue is tagged for 1.16, but not updated for a long time, I'd like to check its status. The code freeze is starting on August 29th (about 1.5 weeks from now), which means that there should be a PR ready (and merged) until then.

Do we still target this issue to be fixed for 1.16? If not please re-tag the issue to the planned milestone.

[xmudrii]

@lavalamp @liggitt @janetkuo This issue and the relevant PR are open for a long time now. Should we move this to the next milestone or should we remove this from the milestone entirely?

[liggitt]

A change this low-level needs more soak time. Moving to 1.17

/milestone v1.17

[tnozicka]

I think fixing the handlers and handling expectations in them will fix this issue #82572

/assign

[josiahbjorgaard]

Bug triage for 1.17 here. This issue has been open for a significant amount of time and since it is tagged for milestone 1.17, we want to let you know that the 1.17 code freeze is coming in less than one month on Nov. 14th. Will this issue be resolved before then?

[tnozicka]

I hope it will, PR #82572 is there, just a matter of getting a review/tag.