Hide Forgot
Description of problem: Cloud controller manager operator can't get leader lease when upgrading from 4.8 up to 4.9 oc adm upgrade: An upgrade is in progress. Working towards 4.9.0-0.okd-2021-11-28-035710: 142 of 744 done (19% complete), waiting on cloud-controller-manager Version-Release number of selected component (if applicable): How reproducible: Start upgrading from version 4.8 up to 4.9 Link to must-gather archive: https://drive.google.com/file/d/1JIqzEIKhDkY97eHzolzfez27ylyWnATP/view?usp=sharing
Joel Speed and I had a debugging session together on this issue. This is what we found out by looking into the must-gather: At first we looked at the logs of the cloud-controller-manager and we observed it was failing to acquire the lease. This lead us to look at its Deployment to verify the lease options for it. Here we noticed there wasn't any option set for leader election (lease locking). We also found out that the version on the Deployment was still on 4.8.0-0.okd-2021-11-14-052418 rather than being on the newer 4.9.0-0.okd-2021-11-28-035710. We then checked the CVO logs to understand better what was happening to the Deployment during the upgrade, we noticed that the version being applied for cloud-controller-manager was still 4.8.0-0.okd-2021-11-14-052418 even after CVO reported that it had applied the correct upgraded Deployment version. We checked the payload for 4.9.0-0.okd-2021-11-28-035710 (registry.ci.openshift.org/origin/release@sha256:7d8356245fc3a75fe11d1832ce9fef17f3dd0f2ea6f38271319c95918416b9d9) and it's carrying the right cloud-controller-manager version (4.9.0) as expected. We are not sure what's happening with the CVO and thus we would like to hear the opinion of the CVO team. Thanks.
Based on Damiano's comment above, as far as we can tell the CVO has not applied the deployment correctly as we can see the older deployment present. Could the CVO team please take a look and see if there is anything suspicious that might hint at why the deployment was not applied correctly.
I think this is the issue but not sure of the cause: 2021-11-29T19:00:55.483985662Z E1129 19:00:55.483928 1 task.go:112] error running apply for clusteroperator "cloud-controller-manager" (143 of 744): Cluster operator cloud-controller-manager is updating versions Here's a suspicious log that came before: 2021-11-29T19:00:32.071114112Z W1129 19:00:32.071049 1 apps.go:136] deployment openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator is not setting any expected conditions, and is therefore in an unknown state And I wonder about these. Did the prior version not have these resources or was something amiss on the cluster before the upgrade? 2021-11-29T19:00:30.003051400Z I1129 19:00:30.003018 1 sync_worker.go:753] Running sync for role "openshift-config/cluster-cloud-controller-manager" (125 of 744) 2021-11-29T19:00:30.042210678Z I1129 19:00:30.042030 1 rbac.go:107] Role openshift-config/cluster-cloud-controller-manager not found, creating 2021-11-29T19:00:30.124886381Z I1129 19:00:30.124790 1 sync_worker.go:765] Done syncing for role "openshift-config/cluster-cloud-controller-manager" (125 of 744) 2021-11-29T19:00:30.124886381Z I1129 19:00:30.124860 1 sync_worker.go:753] Running sync for rolebinding "openshift-config/cluster-cloud-controller-manager" (126 of 744) 2021-11-29T19:00:30.140980767Z I1129 19:00:30.140905 1 rbac.go:78] RoleBinding openshift-config/cluster-cloud-controller-manager not found, creating 2021-11-29T19:00:30.226483944Z I1129 19:00:30.226388 1 sync_worker.go:765] Done syncing for rolebinding "openshift-config/cluster-cloud-controller-manager" (126 of 744) 2021-11-29T19:00:30.226483944Z I1129 19:00:30.226441 1 sync_worker.go:753] Running sync for role "openshift-config-managed/cluster-cloud-controller-manager" (127 of 744) 2021-11-29T19:00:30.243570660Z I1129 19:00:30.243130 1 rbac.go:107] Role openshift-config-managed/cluster-cloud-controller-manager not found, creating 2021-11-29T19:00:30.341797658Z I1129 19:00:30.341731 1 sync_worker.go:765] Done syncing for role "openshift-config-managed/cluster-cloud-controller-manager" (127 of 744) 2021-11-29T19:00:30.341797658Z I1129 19:00:30.341784 1 sync_worker.go:753] Running sync for rolebinding "openshift-config-managed/cluster-cloud-controller-manager" (128 of 744) 2021-11-29T19:00:30.346762331Z I1129 19:00:30.346720 1 rbac.go:78] RoleBinding openshift-config-managed/cluster-cloud-controller-manager not found, creating 2021-11-29T19:00:30.424789309Z I1129 19:00:30.424721 1 sync_worker.go:765] Done syncing for rolebinding "openshift-config-managed/cluster-cloud-controller-manager" (128 of 744) ... 2021-11-29T19:00:31.309464223Z I1129 19:00:31.309453 1 sync_worker.go:753] Running sync for serviceaccount "openshift-cloud-controller-manager/cloud-node-manager" (138 of 744) 2021-11-29T19:00:31.451222341Z I1129 19:00:31.451157 1 core.go:89] ServiceAccount openshift-cloud-controller-manager/cloud-node-manager not found, creating 2021-11-29T19:00:31.490959962Z I1129 19:00:31.490891 1 sync_worker.go:765] Done syncing for serviceaccount "openshift-cloud-controller-manager/cloud-node-manager" (138 of 744) 20
Poking at the comment 0 gather: $ tar xz --strip-components 2 <gather.tar.gz By gather-time: $ yaml2json <namespaces/openshift-cloud-controller-manager-operator/apps/deployments.yaml | jq '.items[] | {generation: .metadata.generation, env: [.spec.template.spec.containers[] | (.env // [])[]], status}' { "generation": 1, "env": [ { "name": "RELEASE_VERSION", "value": "4.9.0-0.okd-2021-11-28-035710" } ], "status": { "availableReplicas": 1, "conditions": [ { "lastTransitionTime": "2021-11-29T19:00:44Z", "lastUpdateTime": "2021-11-29T19:00:44Z", "message": "Deployment has minimum availability.", "reason": "MinimumReplicasAvailable", "status": "True", "type": "Available" }, { "lastTransitionTime": "2021-11-29T19:00:32Z", "lastUpdateTime": "2021-11-29T19:00:44Z", "message": "ReplicaSet \"cluster-cloud-controller-manager-operator-65fc66598\" has successfully progressed.", "reason": "NewReplicaSetAvailable", "status": "True", "type": "Progressing" } ], "observedGeneration": 1, "readyReplicas": 1, "replicas": 1, "updatedReplicas": 1 } } So the deployment controller is caught up (observedGeneration == generation), the deployment is happy (.status.conditions), and the release version is 4.9. As you point out, it's failing to get the leader lease: $ tail -n1 namespaces/openshift-cloud-controller-manager-operator/pods/cluster-cloud-controller-manager-operator-65fc66598-dlttr/cluster-cloud-controller-manager/cluster-cloud-controller-manager/logs/current.log 2021-11-29T19:00:45.465242225Z I1129 19:00:45.465100 1 leaderelection.go:248] attempting to acquire leader lease openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-leader... Checking the lease: $ yaml2json <namespaces/openshift-cloud-controller-manager-operator/core/configmaps.yaml | jq '.items[] | select(.metadata.name == "cluster-cloud-controller-manager-leader").metadata.annotations["control-plane.alpha.kubernetes.io/leader"] | fromjson' { "holderIdentity": "cluster-cloud-controller-manager-fd8df4bbb-2c8qh_0932a044-1def-404e-9db0-b7b3d22be98d", "leaseDurationSeconds": 120, "acquireTime": "2021-11-29T16:20:09Z", "renewTime": "2021-11-30T16:27:03Z", "leaderTransitions": 14 } Ah. $ yaml2json <namespaces/openshift-cloud-controller-manager-operator/core/pods.yaml | jq -r '.items[].metadata.name' cluster-cloud-controller-manager-fd8df4bbb-2c8qh cluster-cloud-controller-manager-operator-65fc66598-dlttr I'm not clear on the expected semantics for those, but you seem to have both going in parallel and competing for the same lease.
Thanks both for your input on this. As Trevor pointed out there are two components going in parallel and competing for the same lease: cluster-cloud-controller-manager-fd8df4bbb-2c8qh cluster-cloud-controller-manager-operator-65fc66598-dlttr An important thing to note here, which can give us some context is that in OCP 4.9 the `cluster-cloud-controller-manager` Deployment has been renamed to `cluster-cloud-controller-manager-operator` and the former has been tombstoned in favour of the latter here: https://github.com/openshift/cluster-cloud-controller-manager-operator/pull/87 This should mean that the `cluster-cloud-controller-manager` Deployment should be deleted by the CVO and ``cluster-cloud-controller-manager-operator` with its ReplicaSet and Pod should take its place. Although at gather time we can see that there are still an old and a new Pod Ready belonging to the tombstoned and to the new Deployment accordingly. This can be seen by looking at the pods running in the `openshift-cloud-controller-manager-operator`: [namespaces/openshift-cloud-controller-manager-operator] $ tree . ├── pods │ ├── cluster-cloud-controller-manager-fd8df4bbb-2c8qh │ │ ├── cluster-cloud-controller-manager │ │ │ └── cluster-cloud-controller-manager │ │ │ └── logs │ │ │ ├── current.log <---------------------------- see #### 1 │ │ │ ├── previous.insecure.log │ │ │ └── previous.log │ │ └── cluster-cloud-controller-manager-fd8df4bbb-2c8qh.yaml │ │ │ │ │ └── cluster-cloud-controller-manager-operator-65fc66598-dlttr │ ├── cloud-config-sync-controller │ │ └── cloud-config-sync-controller │ │ └── logs │ │ ├── current.log │ │ ├── previous.insecure.log │ │ └── previous.log │ ├── cluster-cloud-controller-manager │ │ └── cluster-cloud-controller-manager │ │ └── logs │ │ ├── current.log <---------------------------- see #### 2 │ │ ├── previous.insecure.log │ │ └── previous.log │ └── cluster-cloud-controller-manager-operator-65fc66598-dlttr.yaml #### 1 [namespaces/openshift-cloud-controller-manager-operator] $ tail -f pods/cluster-cloud-controller-manager-fd8df4bbb-2c8qh/cluster-cloud-controller-manager/cluster-cloud-controller-manager/logs/current.log 2021-11-30T15:56:37.264242172Z I1130 15:56:37.264157 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:03:01.768943173Z I1130 16:03:01.768545 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:05:34.901658128Z I1130 16:05:34.901523 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:06:29.790813584Z I1130 16:06:29.790724 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:12:52.725530168Z I1130 16:12:52.725350 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:15:54.649188999Z I1130 16:15:54.649116 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:16:22.317529401Z I1130 16:16:22.317412 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:22:43.682771538Z I1130 16:22:43.682676 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:26:14.397560066Z I1130 16:26:14.397475 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... 2021-11-30T16:26:14.843193443Z I1130 16:26:14.843129 1 clusteroperator_controller.go:127] FeatureGate cluster is not specifying external cloud provider requirement. Skipping... ^C #### 2 [namespaces/openshift-cloud-controller-manager-operator] $ tail -f pods/cluster-cloud-controller-manager-operator-65fc66598-dlttr/cluster-cloud-controller-manager/cluster-cloud-controller-manager/logs/current.log 2021-11-29T19:00:43.900827246Z I1129 19:00:43.900582 1 request.go:665] Waited for 1.032320368s due to client-side throttling, not priority and fairness, request: GET:https://api-int.dev.god.de:6443/apis/autoscaling.openshift.io/v1?timeout=32s 2021-11-29T19:00:45.464022114Z I1129 19:00:45.463959 1 deleg.go:130] CCMOperator/controller-runtime/metrics "msg"="metrics server is starting to listen" "addr"=":8080" 2021-11-29T19:00:45.464725363Z I1129 19:00:45.464690 1 deleg.go:130] CCMOperator/setup "msg"="starting manager" 2021-11-29T19:00:45.465144530Z I1129 19:00:45.465081 1 internal.go:383] CCMOperator/controller-runtime/manager "msg"="starting metrics server" "path"="/metrics" 2021-11-29T19:00:45.465242225Z I1129 19:00:45.465100 1 leaderelection.go:248] attempting to acquire leader lease openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-leader... ^C So this would explain why there are two processes from two completely different Deployments competing for the same lease. But why is there still a Pod belonging to the tombstoned (`cluster-cloud-controller-manager`) Deployment? Has the Deployment been deleted? Yes, there is only the new one! [namespaces/openshift-cloud-controller-manager-operator/apps] $ yaml2json deployments.yaml | jq '.items[] | .metadata.name,.status' "cluster-cloud-controller-manager-operator" { "availableReplicas": 1, "conditions": [ { "lastTransitionTime": "2021-11-29T19:00:44Z", "lastUpdateTime": "2021-11-29T19:00:44Z", "message": "Deployment has minimum availability.", "reason": "MinimumReplicasAvailable", "status": "True", "type": "Available" }, { "lastTransitionTime": "2021-11-29T19:00:32Z", "lastUpdateTime": "2021-11-29T19:00:44Z", "message": "ReplicaSet \"cluster-cloud-controller-manager-operator-65fc66598\" has successfully progressed.", "reason": "NewReplicaSetAvailable", "status": "True", "type": "Progressing" } ], "observedGeneration": 1, "readyReplicas": 1, "replicas": 1, "updatedReplicas": 1 } What about their ReplicaSets? No, they are both still there. [namespaces/openshift-cloud-controller-manager-operator/apps] $ yaml2json replicasets.yaml | jq '.items[] | .metadata.name,.status,.metadata.ownerReferences' "cluster-cloud-controller-manager-66bbd89dcb" { "observedGeneration": 2, "replicas": 0 } [ { "apiVersion": "apps/v1", "blockOwnerDeletion": true, "controller": true, "kind": "Deployment", "name": "cluster-cloud-controller-manager", "uid": "49fa8259-f438-4148-b2af-9a7c56a5a033" } ] "cluster-cloud-controller-manager-74cd748f5" { "observedGeneration": 2, "replicas": 0 } [ { "apiVersion": "apps/v1", "blockOwnerDeletion": true, "controller": true, "kind": "Deployment", "name": "cluster-cloud-controller-manager", "uid": "49fa8259-f438-4148-b2af-9a7c56a5a033" } ] "cluster-cloud-controller-manager-74d459f9f6" { "observedGeneration": 2, "replicas": 0 } [ { "apiVersion": "apps/v1", "blockOwnerDeletion": true, "controller": true, "kind": "Deployment", "name": "cluster-cloud-controller-manager", "uid": "49fa8259-f438-4148-b2af-9a7c56a5a033" } ] "cluster-cloud-controller-manager-fd8df4bbb" { "availableReplicas": 1, "fullyLabeledReplicas": 1, "observedGeneration": 1, "readyReplicas": 1, "replicas": 1 } [ { "apiVersion": "apps/v1", "blockOwnerDeletion": true, "controller": true, "kind": "Deployment", "name": "cluster-cloud-controller-manager", "uid": "49fa8259-f438-4148-b2af-9a7c56a5a033" } ] "cluster-cloud-controller-manager-operator-65fc66598" { "availableReplicas": 1, "fullyLabeledReplicas": 1, "observedGeneration": 1, "readyReplicas": 1, "replicas": 1 } [ { "apiVersion": "apps/v1", "blockOwnerDeletion": true, "controller": true, "kind": "Deployment", "name": "cluster-cloud-controller-manager-operator", "uid": "5ee4862f-84f5-4842-9964-fcf1b34e8847" } ] Why isn't the ReplicaSet being Garbage Collected? We can find a clue in the `kube-controller-manager`: [namespaces/openshift-kube-controller-manager/pods] $ cat kube-controller-manager-okd4-master-01/kube-controller-manager/kube-controller-manager/logs/current.log ... 2021-11-29T19:00:32.122399034Z I1129 19:00:32.122296 1 deployment_controller.go:583] "Deployment has been deleted" deployment="openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager" 2021-11-29T19:00:32.150231936Z I1129 19:00:32.149963 1 replica_set.go:563] "Too few replicas" replicaSet="openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator-65fc66598" need=1 creating=1 2021-11-29T19:00:32.150329866Z I1129 19:00:32.150276 1 event.go:291] "Event occurred" object="openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator" kind="Deployment" apiVersion="apps/v1" type="Normal" reason="ScalingReplicaSet" message="Scaled up replica set cluster-cloud-controller-manager-operator-65fc66598 to 1" 2021-11-29T19:00:32.218331594Z I1129 19:00:32.218241 1 deployment_controller.go:490] "Error syncing deployment" deployment="openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator" err="Operation cannot be fulfilled on deployments.apps \"cluster-cloud-controller-manager-operator\": the object has been modified; please apply your changes to the latest version and try again" 2021-11-29T19:00:32.355719392Z I1129 19:00:32.355613 1 event.go:291] "Event occurred" object="openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator-65fc66598" kind="ReplicaSet" apiVersion="apps/v1" type="Normal" reason="SuccessfulCreate" message="Created pod: cluster-cloud-controller-manager-operator-65fc66598-dlttr" 2021-11-29T19:00:36.028156581Z I1129 19:00:36.028046 1 shared_informer.go:266] stop requested 2021-11-29T19:00:36.028156581Z E1129 19:00:36.028124 1 shared_informer.go:243] unable to sync caches for resource quota 2021-11-29T19:00:36.028241842Z E1129 19:00:36.028149 1 resource_quota_controller.go:452] timed out waiting for quota monitor sync 2021-11-29T19:00:36.952001965Z I1129 19:00:36.951869 1 shared_informer.go:266] stop requested 2021-11-29T19:00:36.952001965Z E1129 19:00:36.951925 1 shared_informer.go:243] unable to sync caches for garbage collector 2021-11-29T19:00:36.952001965Z E1129 19:00:36.951947 1 garbagecollector.go:242] timed out waiting for dependency graph builder sync during GC sync (attempt 9) ...
I think the GC would work in the other direction - if the ReplicaSet is deleted the pods it controls may be deleted. However it would probably be best to explicitly delete all using the delete manifest in explicit order you control and can test out. See the enhancement [1] for more details. [1] https://github.com/openshift/enhancements/blob/master/enhancements/update/object-removal-manifest-annotation.md
I don't think we can specify a manifest to delete a replicaset. The Deployment we create has the annotation and was deleted. In turn, the K8s GC should remove any child objects of this Deployment (owner reference points to a UUID of an object, if that object no longer exists, GC should remove the OR, if last OR, object is deleted IIRC). We need to work out what prevented the GC from removing the replicaset and in turn the pods owned by the replicaset
(In reply to Joel Speed from comment #7) > I don't think we can specify a manifest to delete a replicaset. The > Deployment we create has the annotation and was deleted. In turn, the K8s GC > should remove any child objects of this Deployment (owner reference points > to a UUID of an object, if that object no longer exists, GC should remove > the OR, if last OR, object is deleted IIRC). > > We need to work out what prevented the GC from removing the replicaset and > in turn the pods owned by the replicaset That's true, you're deleting the Deployment. I'm confusing with piece-parts that don't exist as manifests.
[1] seems a bit racy, with the deletion manifest landing after the new Deployment's entry. If the new deployment blocks on the lease, and the CVO blocks on the new deployment, it may never get around to requesting the old deployment's deletion. Back to comment 0's must-gather: $ grep 'deployment.*cluster-cloud-controller-manager' namespaces/openshift-cluster-version/pods/cluster-version-operator-576d994c74-7sjqz/cluster-version-operator/cluster-version-operator/logs/current.log | head -n5 2021-11-29T19:00:31.616313241Z I1129 19:00:31.616295 1 sync_worker.go:753] Running sync for deployment "openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator" (141 of 744) 2021-11-29T19:00:32.071114112Z W1129 19:00:32.071049 1 apps.go:136] deployment openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator is not setting any expected conditions, and is therefore in an unknown state 2021-11-29T19:00:32.071114112Z I1129 19:00:32.071079 1 sync_worker.go:765] Done syncing for deployment "openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-operator" (141 of 744) 2021-11-29T19:00:32.071166297Z I1129 19:00:32.071109 1 sync_worker.go:753] Running sync for deployment "openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager" (142 of 744) 2021-11-29T19:00:32.119322801Z I1129 19:00:32.119175 1 helper.go:65] Delete requested for deployment "openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager". That's the "unknown state" loophole Jack pointed out in comment 3, where the CVO says "I dunno, Deployment controller doesn't have an option, I guess that's ok :shrug:?" and moves on to the next manifest. Although in this case your new deployment seems to be Available=True with Progressing=True and NewReplicaSetAvailable, so I guess you aren't requiring a successful leader acquisition before you declare yourself ready. As long as the CVO retains the "unknown state" loophole or the operator retains the "I'm ready even if I don't have the lease" loophole, we don't have to worry about the delete manifest coming second. But I don't see any reason to have the delete manifest second either. The CVO won't wait for deletion to finalize at manifest-reconciliation time (although it will not declare the update as a whole complete until the deleted manifest is finalized), so you'd get basically the same behavior if you put the delete first, and then you wouldn't have to rely on assumptions about CVO and incoming-operator behavior. And in the sad case where the deletion goes through but for some reason the new deployment doesn't come up (or does but sticks before the pod goes ready), the Deployment controller will be Available=False and/or ProgressDeadlineExceeded, and the CVO will alert on and complain about. Back to the stuck ReplicaSet/Pod, no action on the pod around 19:00 on the 29th: $ grep -hr cluster-cloud-controller-manager-fd8df4bbb host_service_logs/masters | sort | tail -n2 Nov 29 16:17:26.331855 okd4-master-01 hyperkube[1542]: I1129 16:17:26.330210 1542 kubelet.go:1982] "SyncLoop (PLEG): event for pod" pod="openshift-cloud-controller-manager-operator/cluster-cloud-controller-manager-fd8df4bbb-2c8qh" event=&{ID:be61bb6f-febe-45d0-a16d-82c130697a6a Type:ContainerStarted Data:acfc6928bba1f78351ed17184b97419870163819774aac1b74c2ba14b5f3d8bf} Nov 30 16:27:43.342180 okd4-master-01 hyperkube[1542]: I1130 16:27:43.342104 1542 logs.go:319] "Finished parsing log file" path="/var/log/pods/openshift-cloud-controller-manager-operator_cluster-cloud-controller-manager-fd8df4bbb-2c8qh_be61bb6f-febe-45d0-a16d-82c130697a6a/cluster-cloud-controller-manager/0.log" Looking for the garbage collector: $ grep -lr garbagecollector namespaces/openshift-kube-controller-manager/pods/kube-controller-manager-okd4-master-01/kube-controller-manager/kube-controller-manager/logs/current.log Looks like maybe it hung trying to build its cache? $ grep garbagecollector namespaces/openshift-kube-controller-manager/pods/kube-controller-manager-okd4-master-01/kube-controller-manager/kube-controller-manager/logs/current.log 2021-11-29T18:56:05.462870970Z I1129 18:56:05.462776 1 controllermanager.go:616] Starting "garbagecollector" 2021-11-29T18:56:05.490707132Z I1129 18:56:05.490582 1 garbagecollector.go:142] Starting garbage collector controller ... 2021-11-30T16:30:58.230770272Z E1130 16:30:58.230686 1 garbagecollector.go:242] timed out waiting for dependency graph builder sync during GC sync (attempt 2581) 2021-11-30T16:30:58.344267189Z I1130 16:30:58.344182 1 garbagecollector.go:213] syncing garbage collector with updated resources from discovery (attempt 2582): added: [/v1, Resource=configmap... Possibly because of some issue with whatever v1.PartialObjectMetadata is: $ grep -o 'Failed to watch.*' namespaces/openshift-kube-controller-manager/pods/kube-controller-manager-okd4-master-01/kube-controller-manager/kube-controller-manager/logs/current.log | sort | uniq -c 1732 Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: Internal error occurred: error resolving resource I dunno what that's about; no other hits in the must-gather: $ grep -ri PartialObjectMetadata | grep -v kube-controller-manager/logs/current.log ...no hits... [1]: https://github.com/openshift/cluster-cloud-controller-manager-operator/pull/87
Thanks for the analysis and suggestion Trevor, I've raised a PR to switch the ordering of the manifests and would appreciate your review as a CVO expert on that PR.
Setting blocker- on this BZ as this bug won't affect 4.9 to 4.10 upgrades (the rename causing this issue was introduced in 4.9 so will affect only 4.8 to 4.9 upgrades)
#157 looked good to me. But with that attached here, should we create a new bug for whatever the garbage-collector issue was (possibly something to do with PartialObjectMetadata?)? Or are we going to write that off as a strange artifact of whatever test cluster this must-gather came from?
> Or are we going to write that off as a strange artifact of whatever test cluster this must-gather came from? It does seem like a random occurrence, which has only been reported once so far (and via an OKD cluster). I'm happy to clone this, but I don't know to whom I'd send the cloned bug to get the correct eyes on it, any ideas?
Garbage collector is in the openshift-kube-controller-manager namespace, and PartialObjectMetadata is an upstream Kube resource type, so... hrm, no component listed in [1]? Seems like it should be the kube-controller-manager component, regardless of the lack of a 'component' declaration in OWNERS. [1]: https://github.com/openshift/kubernetes-kube-controller-manager/blob/309eb2cada807e5d5c8f471f652ad6ede462caff/OWNERS
With respect to comment 13, I have the same problem on another OKD cluster, trying to upgrade from 4.8.0-0.okd-2021-10-24-061736 to 4.9.0-0.okd-2021-12-12-025847 on vSphere UPI, upgrade hangs at: error running apply for clusteroperator "cloud-controller-manager" (143 of 744): Cluster operator cloud-controller-manager is updating versions Same symptoms as original poster, both cluster-cloud-controller-manager and cluster-cloud-controller-manager-operator pods are present.
Move to verified as this won't affect 4.9 to 4.10 upgrades. Checked QE upgrade CI results, no upgrade hangs at cloud-controller-manager.
We just did an upgrade of an OKD cluster from 4.8-2021-10-24 to 4.9-2022-01-14 and saw the same problem. According to https://github.com/openshift/okd/issues/996 this should have been solved in this OKD 4.9 release. Yet the problem still occured for us. OKD team advised to report this here. If a must-gather from this cluster is needed: https://domino.ars.de/file/must-gather.local.3738823612859762202.tar.gz
@kai-uwe.rommel I've just looked into the must-gather that you've attached and can't see anything wrong there. The cloud controller manager operator pod is working as expected and has acquired the lease, the upgrade has also gone smoothly. Did you apply a workaround to resolve the issue before posting the must gather?
Yes, we applied the workaround mentioned in https://github.com/openshift/okd/issues/996 by bdlink on Dec 21st. We saw other problems after the upgrade but these were unrelated. After I reported there that we also saw this problem with the CCM, Vadim Rutkowsky responded that the OKD 4.9 version we used should already have a fix. Since we still saw the problem despite 4.9 should have the fix he asked me to report it here as well.
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