kubebuilder icon indicating copy to clipboard operation
kubebuilder copied to clipboard

Published 20 hours ago • verified publisher icon kubernetes-sigs

Multiple repeated log lines per cronjob reconciliation loop

Open mattwelke opened this issue 2 years ago • 3 comments
trafficstars

What broke? What's expected?

I'm following the tutorial and got to the part where you deploy the controller into the cluster (I'm using kind) and allow it to automatically create jobs on the schedule defined in the tutorial's cronjob.

I'm observing something that I don't understand right now. I'm not sure if it's the way it's supposed to work or if it's a bug, so I decided to create this bug report in order to find out.

What I expected to happen:

When I use kubectl to get the logs of the pod associated with my deployed controller, I would see one instance of the log line containing the phrase "created Job", one containing "job count", and one containing "no upcoming scheduled times, sleeping until next" for every iteration of the reconciliation loop.

I expected to see only this much logging because of the code used in the tutorial:

scheduledResult := ctrl.Result{RequeueAfter: nextRun.Sub(r.Now())} // save this so we can re-use it elsewhere
log = log.WithValues("now", r.Now(), "next run", nextRun)

if missedRun.IsZero() {
	log.V(1).Info("no upcoming scheduled times, sleeping until next")
	return scheduledResult, nil
}

It looks like we define scheduledResult, which will tell the k8s system to not perform another reconciliation until just after the next scheduled run for the job, based on the cronjob schedule defined. So, I expect this to be logged about once every thirty seconds because the schedule is */1 * * * *.

What actually happens:

When I observe the logs, I see multiple instances of the lines containing "job count" and "no upcoming scheduled times, sleeping until next", logged in rapid succession. It isn't the same number each time. In this example, I observe seven and then eight times:

$ kubectl -n kubebuilder-tutorial-system logs kubebuilder-tutorial-controller-manager-864966bcdb-xbbhv

Output:

...
2023-10-23T19:34:00Z	DEBUG	created Job for CronJob run	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "5ea1aafe-7713-423e-a1e4-a4e43dc63eaa", "now": "2023-10-23T19:34:00Z", "next run": "2023-10-23T19:35:00Z", "current run": "2023-10-23T19:34:00Z", "job": {"namespace": "default", "name": "cronjob-sample-1698089640"}}
2023-10-23T19:34:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "570b4d1e-81bc-46cd-83fa-5bca3d195a47", "active jobs": 1, "successful jobs": 30, "failed jobs": 0}
2023-10-23T19:34:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "570b4d1e-81bc-46cd-83fa-5bca3d195a47", "now": "2023-10-23T19:34:00Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:34:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "fea67c79-8929-4d67-834c-f0d04bad37ae", "active jobs": 1, "successful jobs": 30, "failed jobs": 0}
2023-10-23T19:34:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "fea67c79-8929-4d67-834c-f0d04bad37ae", "now": "2023-10-23T19:34:00Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:34:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "4453cb33-5ce3-422c-9b47-72a03d20a5ce", "active jobs": 1, "successful jobs": 30, "failed jobs": 0}
2023-10-23T19:34:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "4453cb33-5ce3-422c-9b47-72a03d20a5ce", "now": "2023-10-23T19:34:00Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:34:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "8242bec1-683a-488c-9b6e-1205c635c7ee", "active jobs": 1, "successful jobs": 30, "failed jobs": 0}
2023-10-23T19:34:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "8242bec1-683a-488c-9b6e-1205c635c7ee", "now": "2023-10-23T19:34:00Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:34:03Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "d59868a9-f3cd-46bb-9fb7-1be7b1779548", "active jobs": 1, "successful jobs": 30, "failed jobs": 0}
2023-10-23T19:34:03Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "d59868a9-f3cd-46bb-9fb7-1be7b1779548", "now": "2023-10-23T19:34:03Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:34:03Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "3e8450b5-2134-41d4-838c-738ce2eafff9", "active jobs": 1, "successful jobs": 30, "failed jobs": 0}
2023-10-23T19:34:04Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "3e8450b5-2134-41d4-838c-738ce2eafff9", "now": "2023-10-23T19:34:04Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:34:04Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "62d12677-61f7-49c8-8d2b-2dc8110a05f7", "active jobs": 0, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:34:04Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "62d12677-61f7-49c8-8d2b-2dc8110a05f7", "now": "2023-10-23T19:34:04Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:34:04Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "bf1b2aeb-6a41-4c30-b34e-ed7c17d8c795", "active jobs": 0, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:34:04Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "bf1b2aeb-6a41-4c30-b34e-ed7c17d8c795", "now": "2023-10-23T19:34:04Z", "next run": "2023-10-23T19:35:00Z"}
2023-10-23T19:35:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "4695eb60-6a4b-4f73-ab6a-4582de276b59", "active jobs": 0, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:35:00Z	DEBUG	created Job for CronJob run	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "4695eb60-6a4b-4f73-ab6a-4582de276b59", "now": "2023-10-23T19:35:00Z", "next run": "2023-10-23T19:36:00Z", "current run": "2023-10-23T19:35:00Z", "job": {"namespace": "default", "name": "cronjob-sample-1698089700"}}
2023-10-23T19:35:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "08484532-a2f6-4943-8deb-2a5d70d213cb", "active jobs": 1, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:35:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "08484532-a2f6-4943-8deb-2a5d70d213cb", "now": "2023-10-23T19:35:00Z", "next run": "2023-10-23T19:36:00Z"}
2023-10-23T19:35:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "224c5fb5-1291-4579-9e3a-5335b4cf9c18", "active jobs": 1, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:35:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "224c5fb5-1291-4579-9e3a-5335b4cf9c18", "now": "2023-10-23T19:35:00Z", "next run": "2023-10-23T19:36:00Z"}
2023-10-23T19:35:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "c9e4b960-777d-4049-a711-201a1a6ff194", "active jobs": 1, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:35:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "c9e4b960-777d-4049-a711-201a1a6ff194", "now": "2023-10-23T19:35:00Z", "next run": "2023-10-23T19:36:00Z"}
2023-10-23T19:35:00Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "f8f0ab58-3cb1-41bf-864f-2a8ddae1ae30", "active jobs": 1, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:35:00Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "f8f0ab58-3cb1-41bf-864f-2a8ddae1ae30", "now": "2023-10-23T19:35:00Z", "next run": "2023-10-23T19:36:00Z"}
2023-10-23T19:35:04Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "ffa3fa75-f928-458f-9987-2b536a2ed536", "active jobs": 1, "successful jobs": 31, "failed jobs": 0}
2023-10-23T19:35:04Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "ffa3fa75-f928-458f-9987-2b536a2ed536", "now": "2023-10-23T19:35:04Z", "next run": "2023-10-23T19:36:00Z"}
2023-10-23T19:35:04Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "48c62d2c-7fe6-4e71-87b6-6675904672d0", "active jobs": 0, "successful jobs": 32, "failed jobs": 0}
2023-10-23T19:35:04Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "48c62d2c-7fe6-4e71-87b6-6675904672d0", "now": "2023-10-23T19:35:04Z", "next run": "2023-10-23T19:36:00Z"}
2023-10-23T19:35:04Z	DEBUG	job count	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "72cc8012-361e-4cb5-bf5d-008eb5b8ecc7", "active jobs": 0, "successful jobs": 32, "failed jobs": 0}
2023-10-23T19:35:04Z	DEBUG	no upcoming scheduled times, sleeping until next	{"controller": "cronjob", "controllerGroup": "batch.tutorial.kubebuilder.io", "controllerKind": "CronJob", "CronJob": {"name":"cronjob-sample","namespace":"default"}, "namespace": "default", "name": "cronjob-sample", "reconcileID": "72cc8012-361e-4cb5-bf5d-008eb5b8ecc7", "now": "2023-10-23T19:35:04Z", "next run": "2023-10-23T19:36:00Z"}

Is this a bug or is this non-deterministic behavior by design, simply how k8s works?

Reproducing this issue

  1. Follow the tutorial up to the point where you deploy the completed custom controller and CRDs to the cluster (to the page https://kubebuilder.io/cronjob-tutorial/running).
  2. If applicable, use the workaround described in https://github.com/kubernetes-sigs/kubebuilder/issues/1501 to comment the code that enabled the webhooks, so that you can reach this point in the tutorial and observe the controller pod working without crashing even if you do not have cert-manager already installed in the cluster. If you have cert-manager already installed, you can skip this step.
  3. Observe logs of the controller pod that runs (kubebuilder-tutorial-controller-manager-<id>).

KubeBuilder (CLI) Version

3.12.0

PROJECT version

3

Plugin versions

layout:
- go.kubebuilder.io/v4

Other versions

$ go version
go version go1.21.3 linux/amd64

sigs.k8s.io/controller-runtime v0.16.0

("controller-tools" unknown, not present in any file in project)

Extra Labels

No response

mattwelke avatar Oct 23 '23 19:10 mattwelke