Suspected timing issue around temporary cache and garbage collection of resources

[shawkins]

Bug Report

Keycloak tests in the same class run in the same namespace and typically just reuse the same parent cr name. The cleanup between tests ensures that the dependent statefulset is gone, but doesn't check for other dependents such as secrets or services.

In a rare case (1% of runs?) there is a timing issue happening where the state of the temporary cache is out of sync with the informer cache in such a way that does not resolve on its own. In particular the temporary cache will show a resource as existing, while the informer cache / server has it as non-existent.

What did you do?

It's difficult to reproduce, turning up logging made it even less likely to occur - with either fabric8 informer or operator sdk debug logging turned on for the reflector / informer it failed to reproduce.

Instead I resorted to some logic that checked the state of getSecondarResource vs a listing of what was in cache when were'nt fully ready after the main resolving method. That confirmed there was a temporary cache entry, but nothing in the informer cache nor on the server.

What did you expect to see?

The temporary cache state in sync.

What did you see instead? Under which circumstances?

In an extremely rare case, and seemingly related to the garbage collection of resource with the same name, the state was out-of-sync.

Somehow the temporary cache is referencing the garbage collected entry - or one that it thought it created shortly after garbage collection, but that the api server mistakenly deletes.

A possible explanation: a create of the resource seems successful so a resource is being returned for that operation. The client then receives an added and delete event in rapid succession - prior to the operator setting the state of the temporary cache. Then once it sets the temporary cache, it is no longer valid nor will there be an event that causes it to correct.

Environment

v4.8.0, Minikube v1.32.0, Kubernetes v1.27.10

Possible Solution

I'm not sure yet. I'd like to capture the full sequence of events to better understand. It could possibly invole tombstoning the temporary cache so that it won't set an entry if it's "too soon" after a delete event.

Additional context

[shawkins]

Ok, I think the full sequence goes something like this:

• Test run finishes and deletes the parent keycloak, but doesn't wait for the delete event nor all of the dependents to be deleted.
• The next run of the test will start off by using the keycloak that has been marked for deletion as the operator hasn't received that event yet, even though the next test has created a new version of the keycloak resource.
• A reconciliation of the old keycloak happens at a point in time such that the old secret does not exist, so a new one is created but its owner reference is still set to the one to be deleted.
• Then prior to the operator setting the temporary cache state, it receives the add and delete events for that secret.

If this is correct the operator should be able to see that the owner reference is wrong on the secret in temporary cache - I'll add some logging about that to confirm this is the case.

@csviri The secrets in question are using ResourceDiscriminators for their lookup, so that may also be an issue - should that be checking for the owner reference as well, and not just the name? - correction, only one of the affected secrets uses a ResourceDiscriminator, so that's of limited help to check the owner references there.

It seems like this could be considered a general issue as well, since any appropriately timed delete, not just one due to garbage collection, could cause this.

[csviri]

just to clarify:

The next run of the test will start off by using the keycloak that has been marked for deletion as the operator hasn't received that event yet, even though the next test has created a new version of the keycloak resource.

The KeyCloak controller does not seem to be working with finalizers, by "marked for deletion" you, mean it is actually deleted? or there is a finalizer from another controller?

A reconciliation of the old keycloak happens at a point in time such that the old secret does not exist, so a new one is created but its owner reference is still set to the one to be deleted.

So we start a reconciliation for the old keycloak, it will create a secret and put it into the cache with an owner ref to the old (non existing keycloak).

What does not adds up to me (what can happen I guess but very unlikely) is how is that during the reconciliation the Keycloak resource is in the cache but Secret is not. That means that somebody deleted the Keycloak, and the GC deleted the Secret - what can be quite a big time delay, but we did not receive the event from Keycloak but received the Secret (from GC delete)?

Then prior to the operator setting the temporary cache state, it receives the add and delete events for that secret.

The order is strictly delete then add if understand correctly. ? or you mean also the Delete event of the new secret that is created with a non-existing owner ?

[shawkins]

The KeyCloak controller does not seem to be working with finalizers, by "marked for deletion" you, mean it is actually deleted? or there is a finalizer from another controller?

Yes this is a simple background delete. However there is a lag (at least 30 seconds) between when the operation completes and when you can still set that uid on an owner reference - even if a simple get returns a 404 for the owner.

This demonstrates that and forces the situation to happen where we resurrect an invalid entry by adding a time delay:

@KubernetesTest
public class TestSomething {

    static KubernetesClient client;

    @BeforeAll
    public static void before() throws FileNotFoundException {
        BaseOperatorTest.createCRDs(client);
    }

    @Test
    public void testGargageCollection() {
        Keycloak defaultKc = K8sUtils.getDefaultKeycloakDeployment();

        client.secrets().inform(new ResourceEventHandler<Secret>() {

            @Override
            public void onAdd(Secret obj) {

            }

            @Override
            public void onUpdate(Secret oldObj, Secret newObj) {

            }

            @Override
            public void onDelete(Secret obj, boolean deletedFinalStateUnknown) {
                System.out.println("Deleting " + obj.getMetadata().getName() + " " + obj.getMetadata().getUid() + " " + obj.getMetadata().getResourceVersion());
            }
        });

        Keycloak keycloak = null;
        for (int i = 0; i < 100; i++) {
            try {
                keycloak = client.resource(defaultKc).create();
            } catch (KubernetesClientException e) {
                if (e.getCode() != 409) {
                    throw e;
                }
            }
            client.resource(keycloak).delete();
            final var kc = keycloak;
            Secret s = new SecretBuilder().withNewMetadata().withName("x").endMetadata().build();
            s.addOwnerReference(kc);
            try {
                var result = client.resource(s).create();
                Thread.sleep(100);
                System.out.println("Setting temporary cache to " + result.getMetadata().getName() + " " + result.getMetadata().getUid() + " " + result.getMetadata().getResourceVersion());
            } catch (Exception e) {
                System.out.println("Could not create dependent, the owner is missing");
            }
        }
    }

}

If you run something like that, or substitute any other owner / dependent, you should see logs like:

Deleting x bedbfde6-05a9-4e8c-9800-dc917ba67f4e 629598
Setting temporary cache to x bedbfde6-05a9-4e8c-9800-dc917ba67f4e 629597

Showing that we've moved backwards in resourceVersion to the now deleted entry.

More than likely there's some extreme behavior being introduced here cause these minikube instances are running in GHA with the minimum of 2 cpu and already seem a little stressed for memory.

That means that somebody deleted the Keycloak, and the GC deleted the Secret - what can be quite a big time delay, but we did not receive the event from Keycloak but received the Secret (from GC delete)?

That is correct, and sense these are independent informers that's possible - just very unlikely.

The order is strictly delete then add if understand correctly. ? or you mean also the Delete event of the new secret that is created with a non-existing owner ?

It's the latter. As long as the sequence ends with a delete, then we are in trouble. If the sequence were to end in an add/update then the current add/update opertation would compare resourceVersions.

[csviri]

Just a side note: if I understand this correctly, the main problem is that the Delete event in this case arrives before the resource from our update is put in the secondary cache; if the delete arrives after the resource is put in the cache we are ok, since temp cache is cleared, and informer cache is leading again. Note that the former event recording algorithm kinda would cope with this scenario also (without tombstones).

[shawkins]

Just a side note: if I understand this correctly, the main problem is that the Delete event in this case arrives before the resource from our update is put in the secondary cache

It can be any sequence that ends in a delete yes - in theory you could create and delete the resource several times in the span of time that it takes to set the temporary cache entry.

Note that the former event recording algorithm kinda would cope with this scenario also (without tombstones).

I've opened a pr to show what this fix would look like with pre/post calls. This makes it more similar to the previous logic.