Reconciliations stop "randomly" during busy periods

[nstuart]

I've noticed some odd behavior with some recent changes I've made to one of our custom operators, and this may be more of confirmation question than a real issue, but it's unexpected behavior to me at least.

Context; Custom Operator deployed to GKE monitoring and updating a set of Deployments, Services and Virtual Services.

What's happening is that we'll have a set of deployments being managed by our operator (monitoring a CRD as a single top level object) stop getting updated and not finishing a reconciliation loop, and then, any changes we make to the CRD Object after this starts are also ignored. There are no errors in the logs or anything saying something went wrong, and the only clue I have is one log message that is simply:

pause

that's it, no context around it, no additional metadata, just "pause". The messages does align with when our resources top getting updated, so somehow they are related. Also, it pauses one set of resources, while other managed objects are updated and reconciled just fine during this.

My working theory is that I introduced a usage of the kubernetes client to query for a list of pods related to the deployments, and this is somehow causing something to trip and hit some kind of rate limiting. I can see log messages right before "pause" all ending right before I make use of the API calls.

Is this a thing? Is there any documentation around any rate limits in the operator framework or kubernetes client? My googling hasn't turned up anything useful. I see some "pause" related code in the core operator-sdk, but can't really tell if it's related or not.

[csviri]

Hi @nstuart ,

In JOSDK there is possibility to rate limit the reconciliation, but that would not stop the reconiler in "middle", if I understand correctly that is the case. Also there is no default rate limiter, unless you did not set one it does no do any rate limiting. Note that if a reconciler pauses in the middle of reocniliation if won't be triggered again until it finished to avoid concurrent reconiliations of same resources.

My working theory is that I introduced a usage of the kubernetes client to query for a list of pods related to the deployments, and this is somehow causing something to trip and hit some kind of rate limiting. I can see log messages right before "pause" all ending right before I make use of the API calls.

I did not see any problems regarding to this, but looping in @manusa @shawkins from fabric8 client.

Just one point regarding listing pods, have you considered using informers for this purpose?

pls also let us know what verison of k8s and JOSDK you are using. Thx

[nstuart]

@csviri , thanks for the response, for version of JOSDK, I'm going through the Quarkus Operator SDK, which is using version 5.1.1 of JOSDK at the moment. I opened this here since it feels like something below quarkus, and maybe even below JOSDK is causing the issue.

And yes, it is stopping in the middle of a reconcile, which is seems even odder to me, and never resumes until I restart the operator. I did forgot to mention that I can kick the operator over and everything just start working as expected again. Wherever the last reconcile left off in not updating, it reconciles on restart and updates the items fine.

I hadn't looked into informers, but I've also just removed my interaction with the pods for now, and relying on the Deployment resources that the operator manages directly to see if that solves the problem. It's a bit tricky as I don't know the true trigger condition, so I'm kind of just waiting for some of our usual behavior to trigger reconcile events (scaling via HPAs usually), and watching for any of these pause messages.

[nstuart]

One more note, if it wasn't clear, either the pause messages it not coming from a Java Framework, or if it is, its getting spit out using System.out instead of a logger. It has none of the metadata normally attached to java style logs (logger name, mdc, formatting, etc), which we have an abundance of around these messages.

[csviri]

So in JOSDK we definetelly don't do anything like that (pause). This is eaither a quarkus thing, or something coming fom fabric8 (Vertx?); if you are sure that it is not your code. cc @xstefank @metacosm

[metacosm]

Which version of QOSDK are you using, btw?

[metacosm]

Seems like there was some work done regarding to rolling update (and pausing thereof) of deployments that occurred around the time the Fabric8 client 7.3.1 was released (which would be the release used in 5.1.1, iirc). Maybe this is somehow related?
fabric8io/kubernetes-client#6658
Maybe this would ring a bell to @manusa?

[nstuart]

@metacosm, quarkus versions;

quarkusPluginId=io.quarkus
quarkusPluginVersion=3.25.4
quarkusPlatformGroupId=io.quarkus.platform
quarkusPlatformArtifactId=quarkus-bom
quarkusPlatformVersion=3.25.4

I'm trying to reproduce with a more contained example, and of course having trouble since there are so many moving parts and I'm still guessing at root cause.

I will say, I removed the client interaction last night, and so far through some busy periods this morning I haven't seen any pauses.

For reference, here is how I was interacting the client;

// typically has 3 values, and this code would have been called during the main reconcile controller loop, as well
// as the DeploymentResource reconciliation, so "twice" per loop I guess
val deployments = context.getSecondaryResources(Deployment::class.java)
deployments.all { depl ->
            val podQuery = context.client.pods()
                .inNamespace(service.metadata.namespace)
                .withLabels(
                   labels
                )
            val runningPods =
                podQuery.resources().filter { pod -> pod.get()?.status?.phase == "Running" }.toList()
            val hasPods = runningPods.isNotEmpty()
            val hasPods = (depl.status.readyReplicas ?: 0) > 0
            //...
}

You can see why I can switch away from this, but at the same time, I don't really see anything "wrong" with the interaction either.

[shawkins]

I don't believe this message is coming from fabric8 or the operator sdk - which http client are you using?

I recall seeing something like this before, but now can't find it in any of the recent logs I've looked at.

It could help to take thread dumps around the time that this is occurring.

[metacosm]

Yeah, this somehow rings a bell but can't recall where I saw that last time