Operator-sdk: Using RequeueAfter in Reconcile requeues immediately

[cwilkers]

Bug Report

What did you do?

I tried to add a five second delay here

What did you expect to see?
I expected to see changes made my the Reconciler to persist for about five seconds before moving to the next iteration of the reconciler.

What did you see instead? Under which circumstances?
I get immediate run of the next iteration of the Reconciler method despite the delay.

Environment

• operator-sdk version:
  Side note:
  This may be a "good first issue" RFE, to ensure version works as a command like most other k8s binaries.

10:06 $ operator-sdk version
Error: unknown command "version" for "operator-sdk"
Run 'operator-sdk --help' for usage.
10:06 $ operator-sdk --version
operator-sdk version v0.5.0+git

• Kubernetes version information:
  Minikube with:

$ kubectl version
Client Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.3", GitCommit:"721bfa751924da8d1680787490c54b9179b1fed0", GitTreeState:"clean", BuildDate:"2019-02-01T20:08:12Z", GoVersion:"go1.11.5", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.3", GitCommit:"721bfa751924da8d1680787490c54b9179b1fed0", GitTreeState:"clean", BuildDate:"2019-02-01T20:00:57Z", GoVersion:"go1.11.5", Compiler:"gc", Platform:"linux/amd64"}

• Kubernetes cluster kind:

minikube in VBox

• Are you writing your operator in ansible, helm, or go?

go

Possible Solution

Additional context
The old fashioned method, inserting time.Sleep(duration) works as expected.

[hasbro17]

@cwilkers Depending on the reconcile.Result and error returned by your Reconciler the controller will decided whether or not to enqueue the key for your CR so it is processed again.
https://github.com/kubernetes-sigs/controller-runtime/blob/master/pkg/internal/controller/controller.go#L215-L229

With RequeueAfter you can control the delay with which the key is added for your CR.

However there is another eventhandler enqueuing keys for your CR to the controller's queue as well.
That is spawned from the secondary Watch for the Deployments that you have set for the controller.
https://github.com/cwilkers/useless-operator/blob/master/pkg/controller/useless/useless_controller.go#L55-L58

So when you update the Deployment in your reconcile loop that will result in the EnqueueRequestForOwner eventhandler from your secondary watch to receive an Update event for that Deployment, and that in turn adds the key for your CR to the controller's queue.

So with RequeueAfter you can't delay the keys(events) that are added to your controller's queue from other sources. (@shawn-hurley Just want to double check that I'm not wrong on this)

time.Sleep() works to delay the processing of keys the controller won't process any other keys added to queue for your CR while it is blocked processing the current key in your reconcile loop.

I'm curious about why you would want to delay your reconcile loop in this manner though.
RequeueAfter is usually meant for periodically re-triggering the reconcile loop in the case where you can't watch for resources that are related to your CR, or for introducing a delay when processing errors and to avoid going into a hot-loop.
In your case of successfully updating a secondary resource(Deployment) that your are watching your reconcile loop should be able reconcile again without any delays by fetching the latest version of that resource.

[cwilkers]

I see what you mean; I took all the requeueing out of my controller, and the secondary watch alone seems to be forcing each iteration along as soon as possible.

Since my operator is just a toy demo (thus the "useless machine" concept) I was hoping to slow it down so observers could see the steps it performs in order. In this case, I can use the sleep function to effectively slow the execution down in a serial manner.

Thanks for clarifying what was going on!