Bug 2033745

Summary: Cluster-version operator makes upstream update service / Cincinnati requests more frequently than intended
Product: OpenShift Container Platform Reporter: W. Trevor King <wking>
Component: Cluster Version OperatorAssignee: W. Trevor King <wking>
Status: CLOSED ERRATA QA Contact: Evgeni Vakhonin <evakhoni>
Severity: low Docs Contact:
Priority: medium    
Version: 4.7CC: aos-bugs, evakhoni, jiajliu
Target Milestone: ---   
Target Release: 4.10.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
If this bug requires documentation, please select an appropriate Doc Type value.
 Story Points: ---
Clone Of: Environment:
Last Closed: 2022-03-10 16:34:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description W. Trevor King 2021-12-17 18:20:53 UTC 
Since [1], clusters born in 4.7 or later default to not having an explicit spec.upstream, so they rely on the CVO's internal default. However, in that case, u.Upstream will be an empty string, while by this point in syncAvailableUpdates, upstream will have been set to the default value. We should adopt behavior like:

a. If we have no cached data, we need to pull a graph.
b. If it's been over minimumUpdateCheckInterval since our last check, we need to pull a graph. Even if nothing has changed on our side, our data is sufficiently stale to need a refresh.
c. If the channel has changed, we have different interests, and we need to pull a graph to hear what the upstream recommends for this new set of interests.
d. If the upstream hasn't changed, because:
  i. The current upstream (explicitly or by default) matches the old explicit upstream, or
  ii. The current upstream (explicitly or by default) matches the default, and the old upstream was unset.
then everything's the same on our side, and our cached graph is recent, so we don't need to do anything.
e. Otherwise, the upstream has changed, and we need to pull a graph to see what our new guide has to suggest.

Cases for upstream:

* A -> A: Handled by d.i.
* A -> B: Handled by e.
* A -> unset (defaulted) or default: Handled by e.
* Unset or default -> A: Handled by e.
* Default -> default: Handled in d.i.
* Default -> unset (defaulted): Handled in d.i.
* Unset -> default: Handled by d.ii, new in this commit, previously resulted in an excessive pull.
* Unset -> unset (defaulted): Handled by d.ii, new in this commit, previously resulted in an excessive pull.

The bug is that since 4.7's [1] made the unset-upstream situation more common, we're hitting that final "unset -> unset (defaulted)" case for most clusters.  And at the moment, the CVO says:

> This current unset (defaulted) upstream string differs from the past unset upstream, must be an upstream change, and I should pull again without waiting out the cool-down.

While we want it to use d.ii and say:

> The current unset (defaulted) upstream string is functionally a match for the previous unset upstream, so I'm waiting out the cool-down.

[1]: https://github.com/openshift/installer/pull/4112
Comment 3 Evgeni Vakhonin 2021-12-22 13:23:54 UTC 
Reproduced:

1) install an older build and observe cvo log
oc version
Client Version: 4.10.0-0.nightly-2021-12-14-083101
Server Version: 4.10.0-0.nightly-2021-12-14-083101
Kubernetes Version: v1.22.1+6859754

oc get pod -n openshift-cluster-version
oc logs -f cluster-version-operator-66d65b874c-v9nqx -n openshift-cluster-version | \
  tee -a cvo-log.txt | \
  grep -ie "available updates" -ie "to request updates from" &

2) check first occurrence of "syncing available updates" - first pull is expected, additional pulls are excessive
grep -ie "available updates" -ie "to request updates from" cvo-log.txt |head|sed 's/Finished.*/& \n/'

I1222 10:07:15.138758       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 10:07:15.138755825 +0000 UTC m=+397.864376442)
I1222 10:07:15.149607       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 10:07:15.260867       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "stable-4.10" channel
I1222 10:07:15.260913       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (122.154267ms)

I1222 10:07:15.260925       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 10:07:15.260923417 +0000 UTC m=+397.986544036)
I1222 10:07:15.265566       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 10:07:15.345504       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "stable-4.10" channel
I1222 10:07:15.345541       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (84.615577ms)

I1222 10:07:15.619631       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 10:07:15.619629334 +0000 UTC m=+398.345249952)
I1222 10:07:15.624080       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
....

result - reproduced: as we can see, cvo keeps pulling regardless of minimumUpdateCheckInterval

3) patch upstream (unset to default) - should not pull
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://api.openshift.com/api/upgrades_info/v1/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:28:10.399175       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:28:10.399172076 +0000 UTC m=+5253.124793106)
I1222 11:28:10.402758       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:28:10.481521       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "stable-4.10" channel
I1222 11:28:10.481557       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (82.381632ms)

cvo pulled...

also, to be consistent with the validation test, I performed all other steps on this build too

-clear upstream (default to unset) - should not pull
oc patch clusterversion/version --patch '{"spec":{"upstream":""}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:28:58.125400       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:28:58.125398194 +0000 UTC m=+5300.851018797)
I1222 11:28:58.125420       1 availableupdates.go:44] Available updates were recently retrieved, will try later.
I1222 11:28:58.125424       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (24µs)

-set upstream (unset to A) - should pull
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://amd64.ocp.releases.ci.openshift.org/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:33:14.620361       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:33:14.620358936 +0000 UTC m=+5557.345979539)
I1222 11:33:14.624573       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://amd64.ocp.releases.ci.openshift.org/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:33:14.765671       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (145.302885ms)

I1222 11:33:14.774240       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:33:14.774236498 +0000 UTC m=+5557.499857213)
I1222 11:33:14.774274       1 availableupdates.go:44] Available updates were recently retrieved, will try later.
I1222 11:33:14.774277       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (39.369µs)


-change to same (A to A) - should not pull
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://amd64.ocp.releases.ci.openshift.org/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched (no change)

-change upstream (A to B) - should pull
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:34:02.057321       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:34:02.05728177 +0000 UTC m=+5604.782902476)
I1222 11:34:02.060678       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:34:02.187806       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (130.514544ms)

I1222 11:34:23.126874       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:34:23.126872311 +0000 UTC m=+5625.852492933)
I1222 11:34:23.126947       1 availableupdates.go:44] Available updates were recently retrieved, will try later.
I1222 11:34:23.126958       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (83.792µs)


-clear upstream (A to unset) - should pull, but not excessively 
oc patch clusterversion/version --patch '{"spec":{"upstream":""}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:35:53.846159       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:35:53.846156039 +0000 UTC m=+5716.571776732)
I1222 11:35:53.852254       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:35:53.979569       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "stable-4.10" channel
I1222 11:35:53.979601       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (133.442778ms)

I1222 11:35:53.979614       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:35:53.979612124 +0000 UTC m=+5716.705232745)
I1222 11:35:53.985257       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:35:54.053552       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "stable-4.10" channel
I1222 11:35:54.053595       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (73.979722ms)

I1222 11:35:54.053607       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:35:54.053605061 +0000 UTC m=+5716.779225673)
I1222 11:35:54.056230       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:35:54.204517       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "stable-4.10" channel
I1222 11:35:54.204546       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (150.937936ms)

note: pulled 3 times in a row for single change

-change channel - should pull
oc patch clusterversion/version --patch '{"spec":{"channel":"nightly-4.10"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:36:21.499960       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:36:21.49995785 +0000 UTC m=+5744.225578454)
I1222 11:36:21.503257       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=nightly-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:36:21.619161       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "nightly-4.10" channel
I1222 11:36:21.619196       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (119.235124ms)

I1222 11:36:21.627584       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:36:21.62758019 +0000 UTC m=+5744.353200908)
I1222 11:36:21.630529       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=nightly-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:36:21.699883       1 availableupdates.go:228] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-14-083101 not found in the "nightly-4.10" channel
I1222 11:36:21.699916       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (72.332887ms)


-change upstream and channel together - should pull
oc patch clusterversion version --type json -p '[{"op": "add", "path": "/spec/channel", "value": "stable-4.10"}, {"op": "add", "path": "/spec/upstream", "value": "https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph"}]'

clusterversion.config.openshift.io/version patched
I1222 11:37:33.179555       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:37:33.179553167 +0000 UTC m=+5815.905173866)
I1222 11:37:33.182598       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph?arch=amd64&channel=stable-4.10&id=c3c110bb-e9ee-4648-aa0f-0855f90f2d1b&version=4.10.0-0.nightly-2021-12-14-083101
I1222 11:37:33.274649       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (95.08956ms)

I1222 11:37:33.290443       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:37:33.290440577 +0000 UTC m=+5816.016061271)
I1222 11:37:33.290452       1 availableupdates.go:44] Available updates were recently retrieved, will try later.
I1222 11:37:33.290455       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (13.359µs)


-clear channel and upstream at once
oc patch clusterversion version --type json -p '[{"op": "add", "path": "/spec/channel", "value": ""}, {"op": "add", "path": "/spec/upstream", "value": ""}]'

clusterversion.config.openshift.io/version patched
I1222 11:37:51.680322       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:37:51.680315478 +0000 UTC m=+5834.405936186)
I1222 11:37:51.683492       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (3.169442ms)
I1222 11:37:51.696485       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:37:51.696482544 +0000 UTC m=+5834.422103237)
I1222 11:37:51.701192       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (4.696001ms)

-- total pulls after a while
echo - "ran $(grep -c "Started syncing available updates" cvo-log.txt) times \
 pulled $(grep -c "to request updates from" cvo-log.txt) times \
 skipped $(grep -c "Available updates were recently retrieved" cvo-log.txt) times "
ran 191 times    pulled 181 times    skipped 8 times
Comment 4 Evgeni Vakhonin 2021-12-22 17:59:15 UTC 
Verifying:

1) install newer build and observe cvo log
oc version
Client Version: 4.10.0-0.nightly-2021-12-18-034942
Server Version: 4.10.0-0.nightly-2021-12-18-034942
Kubernetes Version: v1.22.1+6859754

oc get pod -n openshift-cluster-version
oc logs -f cluster-version-operator-664f686dc-mt5dp -n openshift-cluster-version | \
  tee -a cvo-log.txt | \
  grep -ie "available updates" -ie "to request updates from" &

2) check first occurrence of "syncing available updates" - first pull is expected, then it should wait for minimumUpdateCheckInterval
grep -ie "available updates" -ie "to request updates from" cvo-log.txt |head|sed 's/Finished.*/& \n/'


I1222 10:11:48.145526       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 10:11:48.145524389 +0000 UTC m=+704.045419892)
I1222 10:11:48.145557       1 availableupdates.go:44] First attempt to retrieve available updates
I1222 10:11:48.149960       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 10:11:48.275739       1 availableupdates.go:236] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-18-034942 not found in the "stable-4.10" channel
I1222 10:11:48.275758       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (130.232388ms)

I1222 10:11:48.275768       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 10:11:48.275766359 +0000 UTC m=+704.175661860)
I1222 10:11:48.275778       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 10:11:48.27575227 +0000 UTC m=+704.175647773, will try later.
I1222 10:11:48.275784       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (16.344µs)
...................................
...................................
I1222 10:15:18.742622       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 10:15:18.74261995 +0000 UTC m=+914.642515492)
I1222 10:15:18.742799       1 availableupdates.go:46] Retrieving available updates again, because more than 3m4.223665607s has elapsed since 2021-12-22 10:11:48.27575227 +0000 UTC m=+704.175647773
I1222 10:15:18.745707       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 10:15:18.873524       1 availableupdates.go:236] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-18-034942 not found in the "stable-4.10" channel
I1222 10:15:18.873555       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (130.932044ms)


3) patch upstream (unset to default) - should not pull
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://api.openshift.com/api/upgrades_info/v1/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:47:24.819827       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:47:24.819825312 +0000 UTC m=+6440.719720804)
I1222 11:47:24.819855       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:44:58.907096607 +0000 UTC m=+6294.806992090, will try later.
I1222 11:47:24.819859       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (33.436µs)


as we can see, there is no excessive pulling! :)



-clear upstream (default to unset) - should not pull unless minimumUpdateCheckInterval
oc patch clusterversion/version --patch '{"spec":{"upstream":""}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:48:05.764379       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:48:05.764376321 +0000 UTC m=+6481.664271816)
I1222 11:48:05.764390       1 availableupdates.go:46] Retrieving available updates again, because more than 3m4.223665607s has elapsed since 2021-12-22 11:44:58.907096607 +0000 UTC m=+6294.806992090
I1222 11:48:05.767400       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 11:48:05.862130       1 availableupdates.go:236] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-18-034942 not found in the "stable-4.10" channel
I1222 11:48:05.862160       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (97.780955ms)

well just reached the interval, trying again...
(doing from unset -> default and again -> unset)
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://api.openshift.com/api/upgrades_info/v1/graph"}}' --type=merge
oc patch clusterversion/version --patch '{"spec":{"upstream":""}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:49:43.660619       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:49:43.660610402 +0000 UTC m=+6579.560505948)
I1222 11:49:43.660663       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:48:05.862147093 +0000 UTC m=+6481.762042576, will try later.
I1222 11:49:43.660669       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (57.414µs)

-set upstream (unset to A) - should pull
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://amd64.ocp.releases.ci.openshift.org/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:51:45.772946       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:51:45.772944008 +0000 UTC m=+6701.672839494)
I1222 11:51:45.773292       1 availableupdates.go:46] Retrieving available updates again, because more than 3m4.223665607s has elapsed since 2021-12-22 11:48:05.862147093 +0000 UTC m=+6481.762042576
I1222 11:51:45.776487       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://amd64.ocp.releases.ci.openshift.org/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 11:51:45.918846       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (145.896844ms)
I1222 11:51:45.926368       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:51:45.926364888 +0000 UTC m=+6701.826260389)
I1222 11:51:45.926475       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:51:45.918829335 +0000 UTC m=+6701.818724818, will try later.
I1222 11:51:45.926480       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (114.574µs)

caught interval again... retrying..
oc patch clusterversion/version --patch '{"spec":{"upstream":""}}' --type=merge
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://amd64.ocp.releases.ci.openshift.org/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:53:24.008768       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:53:24.008757708 +0000 UTC m=+6799.908653221)
I1222 11:53:24.008796       1 availableupdates.go:53] Retrieving available updates again, because the upstream has changed from "" to "https://amd64.ocp.releases.ci.openshift.org/graph"
I1222 11:53:24.018819       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://amd64.ocp.releases.ci.openshift.org/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 11:53:24.161362       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (152.598559ms)
I1222 11:53:24.168570       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:53:24.168567304 +0000 UTC m=+6800.068462796)
I1222 11:53:24.168739       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:53:24.161344494 +0000 UTC m=+6800.061239980, will try later.
I1222 11:53:24.168764       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (194.972µs)
I1222 11:53:56.828404       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:53:56.828394476 +0000 UTC m=+6832.728290060)
I1222 11:53:56.828444       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:53:24.161344494 +0000 UTC m=+6800.061239980, will try later.
I1222 11:53:56.828458       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (61.419µs)

-change to same (A to A) - should not pull
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://amd64.ocp.releases.ci.openshift.org/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched (no change)

-change upsteam (A to B) - should pull - "Retrieving available updates again, because the upstream has changed"
oc patch clusterversion/version --patch '{"spec":{"upstream":"https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:55:32.586610       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:55:32.586604169 +0000 UTC m=+6928.486499696)
I1222 11:55:32.586778       1 availableupdates.go:53] Retrieving available updates again, because the upstream has changed from "https://amd64.ocp.releases.ci.openshift.org/graph" to "https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph"
I1222 11:55:32.589660       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 11:55:32.701655       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (115.046175ms)

-clear upstream (A to unset) - should pull "Retrieving available updates again, because the upstream has changed"
-next occurance - should not pull - "Available updates were recently retrieved"
oc patch clusterversion/version --patch '{"spec":{"upstream":""}}' --type=merge


clusterversion.config.openshift.io/version patched
I1222 11:56:03.374004       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:56:03.374000124 +0000 UTC m=+6959.273895685)
I1222 11:56:03.374032       1 availableupdates.go:53] Retrieving available updates again, because the upstream has changed from "https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph" to ""
I1222 11:56:03.378109       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 11:56:03.500714       1 availableupdates.go:236] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-18-034942 not found in the "stable-4.10" channel
I1222 11:56:03.500733       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (126.73124ms)

I1222 11:56:03.500743       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:56:03.500741645 +0000 UTC m=+6959.400637144)
I1222 11:56:03.500760       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:56:03.500726993 +0000 UTC m=+6959.400622485, will try later.
I1222 11:56:03.500767       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (24.373µs)

I1222 11:56:03.508470       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:56:03.508467945 +0000 UTC m=+6959.408363508)
I1222 11:56:03.508660       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:56:03.500726993 +0000 UTC m=+6959.400622485, will try later.
I1222 11:56:03.508682       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (212.807µs)

-change channel - should pull
oc patch clusterversion/version --patch '{"spec":{"channel":"nightly-4.10"}}' --type=merge

clusterversion.config.openshift.io/version patched
I1222 11:56:50.629197       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:56:50.629193529 +0000 UTC m=+7006.529089090)
I1222 11:56:50.629417       1 availableupdates.go:48] Retrieving available updates again, because the channel has changed from "stable-4.10" to "nightly-4.10"
I1222 11:56:50.633006       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=nightly-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 11:56:50.739164       1 availableupdates.go:236] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: VersionNotFound: currently reconciling cluster version 4.10.0-0.nightly-2021-12-18-034942 not found in the "nightly-4.10" channel
I1222 11:56:50.739197       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (110.001372ms)

I1222 11:56:50.747042       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:56:50.747039668 +0000 UTC m=+7006.646935169)
I1222 11:56:50.747056       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:56:50.739179999 +0000 UTC m=+7006.639075481, will try later.
I1222 11:56:50.747063       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (21.682µs)

I1222 11:56:56.163384       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:56:56.163382106 +0000 UTC m=+7012.063277590)
I1222 11:56:56.163394       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:56:50.739179999 +0000 UTC m=+7006.639075481, will try later.
I1222 11:56:56.163403       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (19.032µs)

-change upstream and channel together - should pull - "Retrieving available updates again, because the channel has changed"
oc patch clusterversion version --type json -p '[{"op": "add", "path": "/spec/channel", "value": "stable-4.10"}, {"op": "add", "path": "/spec/upstream", "value": "https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph"}]'

I1222 11:57:33.902058       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:57:33.902044679 +0000 UTC m=+7049.801940272)
I1222 11:57:33.902368       1 availableupdates.go:48] Retrieving available updates again, because the channel has changed from "nightly-4.10" to "stable-4.10"
I1222 11:57:33.905251       1 cincinnati.go:87] Using a root CA pool with 0 root CA subjects to request updates from https://openshift-release.apps.ci.l2s4.p1.openshiftapps.com/graph?arch=amd64&channel=stable-4.10&id=656a71a2-ef7a-491c-a061-ffc7184893a2&version=4.10.0-0.nightly-2021-12-18-034942
I1222 11:57:33.998762       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (96.714173ms)

I1222 11:57:34.007391       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:57:34.007352541 +0000 UTC m=+7049.907248042)
I1222 11:57:34.007555       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:57:33.998748342 +0000 UTC m=+7049.898643830, will try later.
I1222 11:57:34.007573       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (218.986µs)

-clear channel and upstream together
oc patch clusterversion version --type json -p '[{"op": "add", "path": "/spec/channel", "value": ""}, {"op": "add", "path": "/spec/upstream", "value": ""}]'

clusterversion.config.openshift.io/version patched
I1222 11:57:56.319364       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:57:56.319361794 +0000 UTC m=+7072.219257293)
I1222 11:57:56.319379       1 availableupdates.go:48] Retrieving available updates again, because the channel has changed from "stable-4.10" to ""
I1222 11:57:56.323153       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (3.787339ms)

I1222 11:57:56.334904       1 cvo.go:587] Started syncing available updates "openshift-cluster-version/version" (2021-12-22 11:57:56.334838029 +0000 UTC m=+7072.234733528)
I1222 11:57:56.334931       1 availableupdates.go:50] Available updates were recently retrieved, with less than 3m4.223665607s elapsed since 2021-12-22 11:57:56.323133794 +0000 UTC m=+7072.223029299, will try later.
I1222 11:57:56.334960       1 cvo.go:589] Finished syncing available updates "openshift-cluster-version/version" (121.003µs)

-- total pulls after a while
echo - "ran $(grep -c "Started syncing available updates" cvo-log.txt) times \
   pulled $(grep -c "to request updates from" cvo-log.txt) times \
   skipped $(grep -c "Available updates were recently retrieved" cvo-log.txt) times "

ran 75 times    pulled 25 times    skipped 44 times
Comment 8 errata-xmlrpc 2022-03-10 16:34:54 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: OpenShift Container Platform 4.10.3 security update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2022:0056