CronJobs sometimes do not discard outdated jobs

[bartebor]

Is this a BUG REPORT or FEATURE REQUEST?:

Uncomment only one, leave it on its own line:

/kind bug

What happened:
I have a simple cron job scheduled for every minute with successfulJobHistoryLimit and failedJobHistoryLimit set to 1. A job sleeps 10s and succesfully exits. After some time I see jobs which should be already deleted, but they are not and hang forever. Some jobs are deleted, others do not. Each remaining job has its deletionTimestamp set and "orphan" finalizer present.

NAME                   DESIRED   SUCCESSFUL   AGE
hq-cron-1-1528363800   1         1            1h
hq-cron-1-1528363920   1         1            1h
hq-cron-1-1528369440   1         1            42s

Logs show that controller tries to delete a job every 10s but apiserver silently ignores this because deletionTimestamp is set.

What you expected to happen:
I expect to see only one successful job left as specified via successfulJobHistoryLimit.

How to reproduce it (as minimally and precisely as possible):
Create a simple cron job (schedule for every minute; sleep 10s) and wait. Unfortunately it seems to be environment dependent, so you may or may not see this behaviour.

Anything else we need to know?:
I have some findings which could be useful:

• Restarting kube-controller-manager removes all outdated jobs.
• Removing "orphan" finalizer via kubectl edit deletes job.
• As far as I see in my environment this behaviour appears only when there are more than one apiserver behind a load balancer. If I stop all except one there are no dangling jobs.
• In busy clusters this problem is much less frequent. In my testing environment it happens quite often.
• I sniffed HTTP traffic from kube-controller-manager to the apiserver and found that there is some race condition between job DELETE sent from kube-controller-manager and job GET issued by its garbage collector. If GET happens after DELETE finished, everything works ok, and GET response contains object with deletionTimestamp set and "orphan" finalizer present. If DELETE stalls for some reason (maybe because of more than one apiserver in cluster) and GET finishes earlier it gets object with no deletionTimestamp and no finalizers present, what makes garbage collector abandon its work (there is a "the orphan finalizer is already removed from object" message in kube-controller-manager's log):

kube-controller-manager[30277]: I0607 11:31:25.700191   30277 cronjob_controller.go:194] Removing job hq-cron-1-1528363800 from borek/hq-cron-1
kube-controller-manager[30277]: I0607 11:31:25.726685   30277 job_controller.go:428] Finished syncing job "borek/hq-cron-1-1528363800" (21.529µs)
kube-controller-manager[30277]: I0607 11:31:25.726812   30277 graph_builder.go:587] GraphBuilder process object: batch/v1/Job, namespace borek, name hq-cron-1-1528363800, uid 5c2aba25-6a35-11e8-939b-52540022c84b, event type update
kube-controller-manager[30277]: I0607 11:31:25.733459   30277 cronjob_controller.go:386] CronJob controller is deleting Pod borek/hq-cron-1-1528363800-k4bzx
kube-controller-manager[30277]: I0607 11:31:25.808925   30277 graph_builder.go:587] GraphBuilder process object: v1/Pod, namespace borek, name hq-cron-1-1528363800-k4bzx, uid 5c32f9c2-6a35-11e8-939b-52540022c84b, event type update
kube-controller-manager[30277]: I0607 11:31:25.809075   30277 disruption.go:340] updatePod called on pod "hq-cron-1-1528363800-k4bzx"
kube-controller-manager[30277]: I0607 11:31:25.809182   30277 disruption.go:403] No PodDisruptionBudgets found for pod hq-cron-1-1528363800-k4bzx, PodDisruptionBudget controller will avoid syncing.
kube-controller-manager[30277]: I0607 11:31:25.809199   30277 disruption.go:343] No matching pdb for pod "hq-cron-1-1528363800-k4bzx"
kube-controller-manager[30277]: I0607 11:31:25.809356   30277 controller_utils.go:229] Lowered expectations &controller.ControlleeExpectations{add:0, del:-1, key:"borek/hq-cron-1-1528363800", timestamp:time.Time{sec:63663960628, nsec:200810427, loc:(*time.Location)(0x9e7f3a0)}}
kube-controller-manager[30277]: I0607 11:31:25.809417   30277 job_controller.go:428] Finished syncing job "borek/hq-cron-1-1528363800" (6.339µs)
kube-controller-manager[30277]: I0607 11:31:25.824442   30277 deployment_controller.go:355] Pod hq-cron-1-1528363800-k4bzx deleted.
kube-controller-manager[30277]: I0607 11:31:25.824523   30277 graph_builder.go:587] GraphBuilder process object: v1/Pod, namespace borek, name hq-cron-1-1528363800-k4bzx, uid 5c32f9c2-6a35-11e8-939b-52540022c84b, event type delete
kube-controller-manager[30277]: I0607 11:31:25.824577   30277 disruption.go:369] deletePod called on pod "hq-cron-1-1528363800-k4bzx"
kube-controller-manager[30277]: I0607 11:31:25.824621   30277 disruption.go:403] No PodDisruptionBudgets found for pod hq-cron-1-1528363800-k4bzx, PodDisruptionBudget controller will avoid syncing.
kube-controller-manager[30277]: I0607 11:31:25.824633   30277 disruption.go:372] No matching pdb for pod "hq-cron-1-1528363800-k4bzx"
kube-controller-manager[30277]: I0607 11:31:25.824688   30277 taint_controller.go:339] Noticed pod deletion: types.NamespacedName{Namespace:"borek", Name:"hq-cron-1-1528363800-k4bzx"}
kube-controller-manager[30277]: I0607 11:31:25.824741   30277 controller_utils.go:229] Lowered expectations &controller.ControlleeExpectations{add:0, del:-2, key:"borek/hq-cron-1-1528363800", timestamp:time.Time{sec:63663960628, nsec:200810427, loc:(*time.Location)(0x9e7f3a0)}}
kube-controller-manager[30277]: I0607 11:31:25.824782   30277 job_controller.go:428] Finished syncing job "borek/hq-cron-1-1528363800" (4.451µs)
kube-controller-manager[30277]: I0607 11:31:25.839052   30277 job_controller.go:428] Finished syncing job "borek/hq-cron-1-1528363800" (4.647µs)
kube-controller-manager[30277]: I0607 11:31:25.839132   30277 graph_builder.go:587] GraphBuilder process object: batch/v1/Job, namespace borek, name hq-cron-1-1528363800, uid 5c2aba25-6a35-11e8-939b-52540022c84b, event type update
kube-controller-manager[30277]: I0607 11:31:25.839184   30277 graph_builder.go:549] add [batch/v1/Job, namespace: borek, name: hq-cron-1-1528363800, uid: 5c2aba25-6a35-11e8-939b-52540022c84b] to the attemptToOrphan
kube-controller-manager[30277]: I0607 11:31:25.839236   30277 garbagecollector.go:533] successfully updated all dependents of owner [batch/v1/Job, namespace: borek, name: hq-cron-1-1528363800, uid: 5c2aba25-6a35-11e8-939b-52540022c84b]
kube-controller-manager[30277]: I0607 11:31:25.843562   30277 operations.go:131] the orphan finalizer is already removed from object [batch/v1/Job, namespace: borek, name: hq-cron-1-1528363800, uid: 5c2aba25-6a35-11e8-939b-52540022c84b]
kube-controller-manager[30277]: I0607 11:31:25.855986   30277 event.go:218] Event(v1.ObjectReference{Kind:"CronJob", Namespace:"borek", Name:"hq-cron-1", UID:"a52a7b37-67f1-11e8-8662-525400c64239", APIVersion:"batch", ResourceVersion:"16801040", FieldPath:""}): type: 'Normal' reason: 'SuccessfulDelete' Deleted job hq-cron-1-1528363800

I am not sure if this is related with #56348.
This could affect not only cronjobs. We had a similar situation with replication controllers before, but we made some changes in our software to mitigate this and I am unable to verify that now.

Environment:

• Kubernetes version (use kubectl version):

Client Version: version.Info{Major:"1", Minor:"8", GitVersion:"v1.8.13", GitCommit:"290fb182489a396dce5d136451388f9b12f29c94", GitTreeState:"clean", BuildDate:"2018-05-15T18:08:47Z", GoVersion:"go1.8.3", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"8", GitVersion:"v1.8.13", GitCommit:"290fb182489a396dce5d136451388f9b12f29c94", GitTreeState:"clean", BuildDate:"2018-05-15T18:08:47Z", GoVersion:"go1.8.3", Compiler:"gc", Platform:"linux/amd64"}

[jhorwit2]

/sig apps

[mortent]

@bartebor This looks like you might be running etcd without quorum read? Before version 1.9 you have to start the api server(s) with the --etcd-quorum-read flag set to true if you are running an HA configuration. In the latest version of kubernetes using etcd v3, the default is quorum read.
If you are sure you are running with quorum read, let me know and I'll try to repro.

[bartebor]

@mortent I think this is exactly what happened. We did not have --etcd-quorum-read set and problem disappeared after upgrading to 1.9. Now we have 1.10 with etcd2 and etcd3 backends and it works flawlessly. I think we can close this, thanks!

[mortent]

/close

[k8s-ci-robot]

@mortent: you can't close an active issue unless you authored it or you are assigned to it, Can only assign issues to org members and/or repo collaborators..

In response to this:

/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[kow3ns]

/assign mortent

[k8s-ci-robot]

@kow3ns: GitHub didn't allow me to assign the following users: mortent.

Note that only kubernetes members and repo collaborators can be assigned.
For more information please see the contributor guide

In response to this:

/assign mortent

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[kow3ns]

/close