+++ This bug was initially created as a clone of Bug #1843526 +++ +++ This bug was initially created as a clone of Bug #1838497 +++ --- Additional comment from W. Trevor King on 2020-05-28 08:39:16 UTC --- Ok, we have a better lead on this issue after looking at some local reproducers and then taking a closer look at the CVO logs attached in comment 6. From the attached unsuccessful_oc_logs_cluster_version_operator.log: I0524 16:02:50.774740 1 start.go:19] ClusterVersionOperator v4.3.19-202005041055-dirty ... I0524 16:02:51.342076 1 cvo.go:332] Starting ClusterVersionOperator with minimum reconcile period 2m52.525702462s ... I0524 16:02:51.444381 1 sync_worker.go:471] Running sync quay.io/openshift-release-dev/ocp-release@sha256:039a4ef7c128a049ccf916a1d68ce93e8f5494b44d5a75df60c85e9e7191dacc (force=true) on generation 2 in state Updating at attempt 0 ... I0524 16:08:36.950963 1 sync_worker.go:539] Payload loaded from quay.io/openshift-release-dev/ocp-release@sha256:039a4ef7c128a049ccf916a1d68ce93e8f5494b44d5a75df60c85e9e7191dacc with hash h110xMINmng= ... I0524 16:08:36.953283 1 task_graph.go:611] Result of work: [update was cancelled at 0 of 573] ... I0524 16:11:29.479262 1 sync_worker.go:471] Running sync quay.io/openshift-release-dev/ocp-release@sha256:039a4ef7c128a049ccf916a1d68ce93e8f5494b44d5a75df60c85e9e7191dacc (force=true) on generation 2 in state Reconciling at attempt 0 ... So the 4.3.19 CVO loads the 4.4.3 (in that case) manifests, begins updating to them, immediately hits a cancel/timeout [1], and then decides (mistakenly) that it successfully completed the update and start Reconciling. We're still not clear on exactly what the mistake is. In the meantime, reconciliation's shuffled, flattened manifest graph can do bad things like updating the kubelets before updating the Kubernetes API server. Raising to urgent while we work on bottoming this out. [1]: https://github.com/openshift/cluster-version-operator/pull/372 to improve the logging here, but the 5m45s duration between 2:51 and 8:36 roughly matches 2 * 2m52s [2]. [2]: https://github.com/openshift/cluster-version-operator/blob/86b9bdba55a85e2e071603916db4c43b481e7588/pkg/cvo/sync_worker.go#L296 --- Additional comment from W. Trevor King on 2020-05-28 12:46:48 UTC --- PR submitted. We should backport through 4.2, when we started supporting restricted-network flows, because the timing out signature retrievals plus forced updates common there are what makes tripping this race more likely. Here's a full impact statement, now that we understand the issue: Who is impacted? If we have to block upgrade edges based on this issue, which edges would need blocking? All customers upgrading out of a CVO that does not contain the patch are potentially affected, but the chance of tripping the race is very small except for restricted-network users who are forcing updates. The impact when the race trips is also small for patch-level bumps, so the main concern is restricted-network users who are performing minor bumps like 4.2->4.3. What is the impact? Is it serious enough to warrant blocking edges? The CVO enters reconciliation mode on the target version, attempting to apply a flat, shuffled manifest graph. All kinds of terrible things could happen like the machine-config trying to roll out the newer machine-os-content and its 4.4 hyperkube binary before rolling out prerequisites like the 4.4 kube-apiserver operator. That one will make manifest application sticky, but it would not surprise me if you could find some terrible ordering that might brick a cluster. How involved is remediation (even moderately serious impacts might be acceptable if they are easy to mitigate)? Admin must update to a CVO that is not vulnerable to the race. Using an unforced update (e.g. by copying in a signature ConfigMap [1] for 4.3.12+ or 4.4.0+) would help reduce the likelihood of tripping the race. Using a patch-level update would reduce the impact if the race trips anyway. [1]: https://github.com/openshift/openshift-docs/pull/21993 --- Additional comment from Brenton Leanhardt on 2020-05-28 12:51:30 UTC --- Are clusters that hit this bug permanently wedged or is there a chance a subsequent attempt avoids the race? --- Additional comment from W. Trevor King on 2020-05-28 13:11:06 UTC --- > Are clusters that hit this bug permanently wedged or is there a chance a subsequent attempt avoids the race? Once you trip the race and move from UpdatingPayload to ReconcilingPayload, that CVO will not go back to updating. You can re-target your update with 'oc adm upgrade ...' and that will get you back into UpdatingPayload mode. But while the CVO was running between the trace trip and your update, it could have been doing all sorts of things as it tried to push out the flattened, shuffled manifest graph. Recovering a cluster that has hit this bug is going to be hard, and will probably involve a case-by-case review of its current state to try to determine a next-hop update target that is as close as possible to what the cluster is currently running. And also accounts for which directions and orders operators can transition in. Worst case short of a bricked cluster would be having to turn the CVO off entirely, and push manifests one at a time on its behalf to slowly unwind any components that had been too tangled up.
*** Bug 1843987 has been marked as a duplicate of this bug. ***
Re-test this bug with 4.4.0-0.nightly-2020-06-07-075345, still reproduced. 1. set up a full-disconnected cluster with 4.3.19 2. trigger upgrade towards 4.4.0-0.nightly-2020-06-07-075345 with --force option [root@preserve-jialiu-ansible ~]# oc get clusterversion NAME VERSION AVAILABLE PROGRESSING SINCE STATUS version 4.3.19 True True 2m40s Working towards registry.svc.ci.openshift.org/ocp/release@sha256:7bfabfd2569bf719033f7c08c8040535627e07d36c5ecb78db9e7857ea325a4c: downloading update [root@preserve-jialiu-ansible ~]# oc get node NAME STATUS ROLES AGE VERSION ip-10-0-50-99.us-east-2.compute.internal NotReady,SchedulingDisabled master 135m v1.16.2 ip-10-0-54-103.us-east-2.compute.internal Ready worker 126m v1.16.2 ip-10-0-55-33.us-east-2.compute.internal Ready master 135m v1.16.2 ip-10-0-63-79.us-east-2.compute.internal NotReady,SchedulingDisabled worker 126m v1.16.2 ip-10-0-66-133.us-east-2.compute.internal Ready master 135m v1.16.2 ip-10-0-77-46.us-east-2.compute.internal Ready [root@preserve-jialiu-ansible ~]# oc get clusterversion NAME VERSION AVAILABLE PROGRESSING SINCE STATUS version 4.3.19 True True 39m Unable to apply 4.4.0-0.nightly-2020-06-07-075345: the cluster operator etcd is degraded [root@preserve-jialiu-ansible ~]# oc get co NAME VERSION AVAILABLE PROGRESSING DEGRADED SINCE authentication 4.4.0-0.nightly-2020-06-07-075345 True False False 132m cloud-credential 4.3.19 True False False 132m cluster-autoscaler 4.4.0-0.nightly-2020-06-07-075345 True False False 163m console 4.3.19 True False False 40m dns 4.4.0-0.nightly-2020-06-07-075345 True False False 168m etcd 4.4.0-0.nightly-2020-06-07-075345 True False True 25m image-registry 4.4.0-0.nightly-2020-06-07-075345 True False False 85m ingress 4.3.19 True False False 40m insights 4.3.19 True False False 164m kube-apiserver 4.3.19 True False True 166m kube-controller-manager 4.3.19 True False True 166m kube-scheduler 4.3.19 True False True 166m machine-api 4.4.0-0.nightly-2020-06-07-075345 True False False 168m machine-config 4.3.19 False True True 29m marketplace 4.4.0-0.nightly-2020-06-07-075345 True False False 50m monitoring 4.4.0-0.nightly-2020-06-07-075345 True False False 81m network 4.3.19 True False False 168m node-tuning 4.4.0-0.nightly-2020-06-07-075345 True False False 47m openshift-apiserver 4.4.0-0.nightly-2020-06-07-075345 True False True 42m openshift-controller-manager 4.4.0-0.nightly-2020-06-07-075345 True False False 168m openshift-samples 4.3.19 True False False 154m operator-lifecycle-manager 4.3.19 True False False 164m operator-lifecycle-manager-catalog 4.3.19 True False False 164m operator-lifecycle-manager-packageserver 4.3.19 True False False 39m service-ca 4.4.0-0.nightly-2020-06-07-075345 True False False 168m service-catalog-apiserver 4.4.0-0.nightly-2020-06-07-075345 True False False 164m service-catalog-controller-manager 4.4.0-0.nightly-2020-06-07-075345 True False False 164m storage 4.4.0-0.nightly-2020-06-07-075345 True False False 53m [root@ip-10-0-50-99 ~]# journalctl -f -u kubelet <--snip--> Jun 08 05:00:59 ip-10-0-50-99 hyperkube[48332]: I0608 05:00:59.983939 48332 kubelet_node_status.go:70] Attempting to register node ip-10-0-50-99.us-east-2.compute.internal Jun 08 05:00:59 ip-10-0-50-99 hyperkube[48332]: I0608 05:00:59.984028 48332 event.go:281] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"ip-10-0-50-99.us-east-2.compute.internal", UID:"ip-10-0-50-99.us-east-2.compute.internal", APIVersion:"", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'NodeHasSufficientMemory' Node ip-10-0-50-99.us-east-2.compute.internal status is now: NodeHasSufficientMemory Jun 08 05:00:59 ip-10-0-50-99 hyperkube[48332]: I0608 05:00:59.984072 48332 event.go:281] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"ip-10-0-50-99.us-east-2.compute.internal", UID:"ip-10-0-50-99.us-east-2.compute.internal", APIVersion:"", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'NodeHasNoDiskPressure' Node ip-10-0-50-99.us-east-2.compute.internal status is now: NodeHasNoDiskPressure Jun 08 05:00:59 ip-10-0-50-99 hyperkube[48332]: I0608 05:00:59.984265 48332 event.go:281] Event(v1.ObjectReference{Kind:"Node", Namespace:"", Name:"ip-10-0-50-99.us-east-2.compute.internal", UID:"ip-10-0-50-99.us-east-2.compute.internal", APIVersion:"", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'NodeHasSufficientPID' Node ip-10-0-50-99.us-east-2.compute.internal status is now: NodeHasSufficientPID Jun 08 05:00:59 ip-10-0-50-99 hyperkube[48332]: I0608 05:00:59.998603 48332 kubelet_node_status.go:112] Node ip-10-0-50-99.us-east-2.compute.internal was previously registered Jun 08 05:01:00 ip-10-0-50-99 hyperkube[48332]: E0608 05:01:00.005588 48332 kubelet_node_status.go:122] Unable to reconcile node "ip-10-0-50-99.us-east-2.compute.internal" with API server: error updating node: failed to patch status "{\"metadata\":{\"labels\":{\"node.kubernetes.io/instance-type\":\"m4.xlarge\",\"topology.kubernetes.io/region\":\"us-east-2\",\"topology.kubernetes.io/zone\":\"us-east-2a\"}}}" for node "ip-10-0-50-99.us-east-2.compute.internal": nodes "ip-10-0-50-99.us-east-2.compute.internal" is forbidden: is not allowed to modify labels: topology.kubernetes.io/region, topology.kubernetes.io/zone Jun 08 05:01:00 ip-10-0-50-99 hyperkube[48332]: I0608 05:01:00.083904 48332 prober.go:129] Liveness probe for "openshift-kube-scheduler-ip-10-0-50-99.us-east-2.compute.internal_openshift-kube-scheduler(9afa2b85dd4b8d7bf23e023894147856):scheduler" succeeded Jun 08 05:01:00 ip-10-0-50-99 hyperkube[48332]: I0608 05:01:00.173944 48332 nodeinfomanager.go:402] Failed to publish CSINode: the server could not find the requested resource Jun 08 05:01:00 ip-10-0-50-99 hyperkube[48332]: E0608 05:01:00.174004 48332 csi_plugin.go:273] Failed to initialize CSINode: error updating CSINode annotation: timed out waiting for the condition; caused by: the server could not find the requested resource Jun 08 05:01:00 ip-10-0-50-99 hyperkube[48332]: F0608 05:01:00.174014 48332 csi_plugin.go:287] Failed to initialize CSINode after retrying: timed out waiting for the condition Jun 08 05:01:00 ip-10-0-50-99 systemd[1]: kubelet.service: Main process exited, code=exited, status=255/n/a Jun 08 05:01:00 ip-10-0-50-99 systemd[1]: kubelet.service: Failed with result 'exit-code'. Jun 08 05:01:00 ip-10-0-50-99 systemd[1]: kubelet.service: Consumed 2.790s CPU tim
Created attachment 1695988 [details] qe cvo log
(In reply to Johnny Liu from comment #4) > Re-test this bug with 4.4.0-0.nightly-2020-06-07-075345, still reproduced. > > 1. set up a full-disconnected cluster with 4.3.19 > 2. trigger upgrade towards 4.4.0-0.nightly-2020-06-07-075345 with --force > option The bug should be fixed when the patches land in the source release; the target release is irrelevant. This bug targets 4.4.z, so you should be verifying with a recent-4.4-nightly -> whatever update. Could be recent-4.4-nightly -> other-4.4.z. Could be recent-4.4-nightly -> 4.5.0-rc.1. But 4.3.z -> 4.4 is going to continue to fail until this 4.4.z bug gets VERIFIED, which will unblock the bug 1844117 4.3.z backport. Once bug 1844117 gets fixed, then 4.3.z -> 4.4 should be safe.
Per my test experience, I can not reproduce this issue from 4.4 to 4.5, only reproduced from 4.3 to 4.4. Here I trigger an upgrade against a fully disconnected cluster from 4.4.0-0.nightly-2020-06-07-075345 to 4.5.0-0.nightly-2020-06-04-001344. SUCCESS. I will trigger one more round of testing from latest-4.3-nightly to 4.4.0-0.nightly-2020-06-07-075345 to confirm the original issue is really fixed. Move this bug to verified to unblock 4.3.z backport.
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, 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/RHBA-2020:2445