Bug 1917537: Fix time comparison in CSV reconcile loop #1974

hasbro17 · 2021-01-26T20:01:39Z

Description of the change:
Fix the comparison check for csv.status.LastUpdateTime in the CSV reconcile from == to Time.Equal().

Motivation for the change:
See the following bug for background on the reconcile hotloop: https://bugzilla.redhat.com/show_bug.cgi?id=1917537

After installing an operator on an openshift 4.6.z cluster (e.g 4.6.13) the OLM operator can get into a loop where the CSV object is being continuously being reconciled and updated roughly every second.

time="2021-01-26T19:55:44Z" level=info msg="checking ocs-operator.v4.6.1"
2021-01-26T19:55:44.512Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "operator", "request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:44.513Z	DEBUG	controllers.operator	reconciling operator	{"request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:44.513Z	DEBUG	controllers.operator	Operator is already up-to-date	{"request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:44.513Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "operator", "request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:44.514Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "clusterserviceversion", "request": "openshift-storage/ocs-operator.v4.6.1"}
2021-01-26T19:55:45.634Z	DEBUG	controllers.operator	reconciling operator	{"request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:45.635Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "subscription", "request": "openshift-storage/ocs-operator"}
time="2021-01-26T19:55:45Z" level=info msg="csv in operatorgroup" csv=ocs-operator.v4.6.1 id=zuP7V namespace=openshift-storage opgroup=openshift-storage-dvlsm phase=Succeeded
time="2021-01-26T19:55:45Z" level=info msg="checking ocs-operator.v4.6.1"
2021-01-26T19:55:45.666Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "clusterserviceversion", "request": "openshift-storage/ocs-operator.v4.6.1"}
2021-01-26T19:55:45.678Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "operator", "request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:45.680Z	DEBUG	controllers.operator	reconciling operator	{"request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:45.680Z	DEBUG	controllers.operator	Operator is already up-to-date	{"request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:45.680Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "operator", "request": "/ocs-operator.openshift-storage"}
2021-01-26T19:55:46.848Z	DEBUG	controller-runtime.controller	Successfully Reconciled	{"controller": "subscription", "request": "openshift-storage/ocs-operator"}
2021-01-26T19:55:46.848Z	DEBUG	controllers.operator	reconciling operator	{"request": "/ocs-operator.openshift-storage"}
time="2021-01-26T19:55:46Z" level=info msg="csv in operatorgroup" csv=ocs-operator.v4.6.1 id=zykOJ namespace=openshift-storage opgroup=openshift-storage-dvlsm phase=Succeeded
time="2021-01-26T19:55:46Z" level=info msg="checking ocs-operator.v4.6.1"
...

This results in increased CPU usage and requests to the APIserver.

While it's unclear how the operator gets into this reconcile hotloop when installing certain operators (OCS, ACM) and not others (etcd, cert-manager), the comparison check outCSV.Status.LastUpdateTime == clusterServiceVersion.Status.LastUpdateTime is incorrect as it always results false since the values being compared are *metav1.Time pointer addresses.

This results in the OLM operator always updating the CSV object with no real status change and triggering another reconcile event.

With the proposed fix the reconcile hotloop does go away since the CSV is no longer being updated when there are no status changes.

TODO:

Unknown how OLM gets into the reconcile loop or why it doesn't occur on a 4.7.z cluster
Figure out a unit or e2e test to cover this case

Reviewer Checklist

Implementation matches the proposed design, or proposal is updated to match implementation
Sufficient unit test coverage
Sufficient end-to-end test coverage
Docs updated or added to /docs
Commit messages sensible and descriptive

openshift-ci-robot · 2021-01-26T20:01:43Z

@hasbro17: This pull request references Bugzilla bug 1917537, which is invalid:

expected the bug to target the "4.7.0" release, but it targets "---" instead

Comment /bugzilla refresh to re-evaluate validity if changes to the Bugzilla bug are made, or edit the title of this pull request to link to a different bug.

In response to this:

WIP: Bug 1917537: Fix time comparison in CSV reconcile loop

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.

pkg/controller/operators/olm/operator.go

hasbro17 · 2021-01-27T20:46:04Z

/bugzilla refresh

openshift-ci-robot · 2021-01-27T20:46:17Z

@hasbro17: This pull request references Bugzilla bug 1917537, which is valid. The bug has been moved to the POST state. The bug has been updated to refer to the pull request using the external bug tracker.

3 validation(s) were run on this bug

bug is open, matching expected state (open)
bug target release (4.7.0) matches configured target release for branch (4.7.0)
bug is in the state ASSIGNED, which is one of the valid states (NEW, ASSIGNED, ON_DEV, POST, POST)

In response to this:

/bugzilla refresh

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.

hasbro17 · 2021-01-27T20:46:52Z

/retest

hasbro17 · 2021-01-27T21:21:05Z

pkg/controller/operators/olm/operator.go

@@ -1097,7 +1097,7 @@ func (a *Operator) syncClusterServiceVersion(obj interface{}) (syncError error)
 	}

 	// status changed, update CSV
-	if !(outCSV.Status.LastUpdateTime == clusterServiceVersion.Status.LastUpdateTime &&
+	if !(outCSV.Status.LastUpdateTime.Equal(clusterServiceVersion.Status.LastUpdateTime) &&


Forgot that this could be a nil dereference if outCSV.Status.LastUpdateTime == nil. Going to add a check for that first.

Actually, never mind. I keep forgetting a method is orthogonal to the underlying data and LastUpdateTime.Equal() is fine even if LastUpdateTime == nil.

ecordell · 2021-02-02T16:00:02Z

/approve

openshift-ci-robot · 2021-02-02T16:00:12Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: ecordell, hasbro17

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [ecordell]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

ecordell · 2021-02-02T16:00:35Z

/cherry-pick release-4.6

openshift-cherrypick-robot · 2021-02-02T16:00:36Z

@ecordell: once the present PR merges, I will cherry-pick it on top of release-4.6 in a new PR and assign it to you.

In response to this:

/cherry-pick release-4.6

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.

kevinrizza · 2021-02-02T17:55:42Z

/lgtm

hasbro17 · 2021-02-02T19:45:19Z

/retest

openshift-bot · 2021-02-02T19:50:11Z

/retest

Please review the full test history for this PR and help us cut down flakes.

openshift-ci-robot · 2021-02-02T21:12:04Z

@hasbro17: All pull requests linked via external trackers have merged:

operator-framework/operator-lifecycle-manager#1974

Bugzilla bug 1917537 has been moved to the MODIFIED state.

In response to this:

Bug 1917537: Fix time comparison in CSV reconcile loop

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.

openshift-cherrypick-robot · 2021-02-02T21:12:13Z

@ecordell: new pull request created: #1987

In response to this:

/cherry-pick release-4.6

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.

Fix time comparison in CSV reconcile loop

8c8270a

hasbro17 requested review from ecordell, benluddy, njhale and kevinrizza January 26, 2021 20:01

openshift-ci-robot requested review from Bowenislandsong and exdx January 26, 2021 20:01

exdx reviewed Jan 26, 2021

View reviewed changes

pkg/controller/operators/olm/operator.go Show resolved Hide resolved

openshift-ci-robot added the bugzilla/valid-bug Indicates that a referenced Bugzilla bug is valid for the branch this PR is targeting. label Jan 27, 2021

openshift-ci-robot removed the bugzilla/invalid-bug Indicates that a referenced Bugzilla bug is invalid for the branch this PR is targeting. label Jan 27, 2021

hasbro17 changed the title ~~WIP: Bug 1917537: Fix time comparison in CSV reconcile loop~~ Bug 1917537: Fix time comparison in CSV reconcile loop Jan 27, 2021

openshift-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Jan 27, 2021

hasbro17 commented Jan 27, 2021

View reviewed changes

openshift-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Feb 2, 2021

openshift-ci-robot assigned kevinrizza Feb 2, 2021

openshift-ci-robot added the lgtm Indicates that a PR is ready to be merged. label Feb 2, 2021

openshift-merge-robot merged commit 0373c9b into operator-framework:master Feb 2, 2021

openshift-cherrypick-robot mentioned this pull request Feb 2, 2021

[release-4.6] Bug 1924257: Fix time comparison in CSV reconcile loop #1987

Closed

hasbro17 mentioned this pull request Feb 3, 2021

[release-4.6] Bug 1924257: Fix time comparison in CSV reconcile loop #1991

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bug 1917537: Fix time comparison in CSV reconcile loop #1974

Bug 1917537: Fix time comparison in CSV reconcile loop #1974

hasbro17 commented Jan 26, 2021

openshift-ci-robot commented Jan 26, 2021

hasbro17 commented Jan 27, 2021

openshift-ci-robot commented Jan 27, 2021

hasbro17 commented Jan 27, 2021

hasbro17 Jan 27, 2021

hasbro17 Jan 28, 2021

ecordell commented Feb 2, 2021

openshift-ci-robot commented Feb 2, 2021

ecordell commented Feb 2, 2021

openshift-cherrypick-robot commented Feb 2, 2021

kevinrizza commented Feb 2, 2021

hasbro17 commented Feb 2, 2021

openshift-bot commented Feb 2, 2021

openshift-ci-robot commented Feb 2, 2021

openshift-cherrypick-robot commented Feb 2, 2021

Bug 1917537: Fix time comparison in CSV reconcile loop #1974

Bug 1917537: Fix time comparison in CSV reconcile loop #1974

Conversation

hasbro17 commented Jan 26, 2021

openshift-ci-robot commented Jan 26, 2021

hasbro17 commented Jan 27, 2021

openshift-ci-robot commented Jan 27, 2021

hasbro17 commented Jan 27, 2021

hasbro17 Jan 27, 2021

Choose a reason for hiding this comment

hasbro17 Jan 28, 2021

Choose a reason for hiding this comment

ecordell commented Feb 2, 2021

openshift-ci-robot commented Feb 2, 2021

ecordell commented Feb 2, 2021

openshift-cherrypick-robot commented Feb 2, 2021

kevinrizza commented Feb 2, 2021

hasbro17 commented Feb 2, 2021

openshift-bot commented Feb 2, 2021

openshift-ci-robot commented Feb 2, 2021

openshift-cherrypick-robot commented Feb 2, 2021