Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1759122

Summary: Upgrading a managed cluster from 4.1.18 to 4.2.0-rc.1 results in CCO CA cert issues
Product: OpenShift Container Platform Reporter: Scott Dodson <sdodson>
Component: Cloud Credential OperatorAssignee: Joel Diaz <jdiaz>
Status: CLOSED ERRATA QA Contact: sheng.lao <shlao>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 4.2.0CC: jdiaz, lseelye, nmalik, olnester, sdodson, shlao, wking, xtian
Target Milestone: ---   
Target Release: 4.2.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1758666 Environment:
Last Closed: 2019-10-16 06:41:54 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1758666    
Bug Blocks:    

Description Scott Dodson 2019-10-07 12:56:36 UTC 
+++ This bug was initially created as a clone of Bug #1758666 +++

Description of problem:

I upgraded a managed 4.1.18 cluster to 4.2.0-rc.1 today and ran into an issue with the cloud-credential-operator as part of the upgrade.

I noticed CVO reporting the cluster upgrade wasn't progressing due to an issue in this operator. Upon inspection, I noticed log messages in the opeator:

time="2019-10-04T15:54:25Z" level=error msg="error getting user: {\n\n}" actuator=aws cr=openshift-cloud-credential-operator/openshift-ingress error="RequestError: send request failed\ncaused by: Post https://iam.amazonaws.com/: x509: certificate signed by unknown authority"

Further in the log messages were notices that 2 of 5 credential requests are failing to sync:

Status:
  Conditions:
    Last Transition Time:  2019-10-04T15:03:51Z
    Message:               2 of 5 credentials requests are failing to sync.
    Reason:                CredentialsFailing
    Status:                True
    Type:                  Degraded
    Last Transition Time:  2019-10-04T15:03:51Z
    Message:               3 of 5 credentials requests provisioned, 2 reporting errors.
    Reason:                Reconciling
    Status:                True
    Type:                  Progressing
    
I thought there might be some issue that had the operator "wedged" somehow, and so I deleted the operator's pod so it would be rescheduled. From here after, 5 of 5 credential requests are failing to sync.


Version-Release number of selected component (if applicable):

4.2.0-rc.1

How reproducible:

I haven't tried to reproduce this yet.


Steps to Reproduce:
1. Install 4.1.18 cluster
2. Force upgrade to 4.2.0-rc.1

Actual results:


Expected results:

The operator shouldn't have this issue.


Additional info:

The cco-trusted-ca ConfigMap has no data associated with it, which lead Devan to suggest this commit might be worth looking at as a possibile contributing cause https://github.com/openshift/cloud-credential-operator/commit/3c1f60d80ebf00168b88e5ccceb3b7b996ca78cc. 

As some speculation, Is it possible that there is a race condition in the upgrade process whereby the contents of this configmap are being cleared from under the operator during the upgrade/reconciliation process?

--- Additional comment from W. Trevor King on 2019-10-04 15:45:41 EDT ---

Marking as a 4.2.0 blocker until we have a clearer picture.

--- Additional comment from W. Trevor King on 2019-10-04 17:55:39 EDT ---

There are some cred changes from 4.1.18->4.2.0-rc.1:

$ oc adm release extract --to 4.1.18 quay.io/openshift-release-dev/ocp-release:4.1.18
Extracted release payload from digest sha256:420633acf3fc7572372fe2df758152f6ab1f53a21c79a6c4b741fa0394c7df3a created at 2019-09-24T13:46:14Z
$ oc adm release extract --to 4.2.0-rc.1 quay.io/openshift-release-dev/ocp-release:4.2.0-rc.1
Extracted release payload from digest sha256:0a1dcbc81869f790fdd26d481706ee5d18ff4f5a13a833460d56fa0c396dc153 created at 2019-10-04T11:42:24Z
$ diff -ru 4.1.18 4.2.0-rc.1 | grep '^diff' | grep cred
diff -ru 4.1.18/0000_30_machine-api-operator_00_credentials-request.yaml 4.2.0-rc.1/0000_30_machine-api-operator_00_credentials-request.yaml
diff -ru 4.1.18/0000_50_cloud-credential-operator_01_deployment.yaml 4.2.0-rc.1/0000_50_cloud-credential-operator_01_deployment.yaml
diff -ru 4.1.18/0000_50_cloud-credential-operator_10_cluster-operator.yaml 4.2.0-rc.1/0000_50_cloud-credential-operator_10_cluster-operator.yaml
diff -ru 4.1.18/0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml 4.2.0-rc.1/0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml
diff -ru 4.1.18/0000_50_cluster-ingress-operator_00-ingress-credentials-request.yaml 4.2.0-rc.1/0000_50_cluster-ingress-operator_00-ingress-credentials-request.yaml
$ diff -u 4.1.18/0000_30_machine-api-operator_00_credentials-request.yaml 4.2.0-rc.1/0000_30_machine-api-operator_00_credentials-request.yaml
--- 4.1.18/0000_30_machine-api-operator_00_credentials-request.yaml    2019-09-20 18:27:27.000000000 -0700
+++ 4.2.0-rc.1/0000_30_machine-api-operator_00_credentials-request.yaml    2019-10-03 14:29:27.000000000 -0700
@@ -3,7 +3,7 @@
 metadata:
   labels:
     controller-tools.k8s.io: "1.0"
-  name: openshift-machine-api
+  name: openshift-machine-api-aws
...
$ diff -u 4.1.18/0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml 4.2.0-rc.1/0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml
--- 4.1.18/0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml    2019-09-20 18:54:20.000000000 -0700
+++ 4.2.0-rc.1/0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml    2019-10-03 14:35:01.000000000 -0700
@@ -19,6 +19,8 @@
       - s3:DeleteBucket
       - s3:PutBucketTagging
       - s3:GetBucketTagging
+      - s3:PutBucketPublicAccessBlock
+      - s3:GetBucketPublicAccessBlock
       - s3:PutEncryptionConfiguration
       - s3:GetEncryptionConfiguration
       - s3:PutLifecycleConfiguration

1. Upgrade kicks off.
2. Cluster-version operator pushes out new, 4.2 0000_30_machine-api-operator_00_credentials-request.yaml.  4.1 cred operator gets to work filling it (and hopefully reaping the cred from the previous name).
3. Cluster-version operator pushes out new, 4.2 0000_50_cloud-credential-operator_01_deployment.yaml.  4.2 cred operator comes up and gets worried about the missing trust bundle (which will be set up by the 4.2 net operator towards the end of the upgrade.
4. Cluster-version operator pushes out new, 4.2 0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml.  4.2 cred operator tries to work on it, but still no trust bundle.
5. Cred operator gets really mad and sets Degraded.
6. Degraded cred operator blocks 0000_50_cloud-credential-operator_10_cluster-operator.yaml.  Deployment hangs.

We don't see this in CI (yet) [1,2], possibly because the window between 0000_50_cloud-credential-operator_01_deployment.yaml and 0000_50_cluster-image-registry-operator_01-registry-credentials-request.yaml is short enough that the 4.2 cred operator levels and gets us past the ClusterOperator block most of the time before going degraded.  As long as the cluster-version operator can walk the rest of that upgrade cycle without getting stuck on something else, it would get the new net operator up, and the net operator would populate the trust bundle, and away we go.  But when we lose the race we're stuck.

This should not be a problem within 4.2, because we'll already have a trust bundle for the new cred operator to use.

The fix is having the cred operator fall back to internal creds to get over the 4.1->4.2 upgrade where a new cred operator might not have them available.  4.3 cred operators will not need the internal fallback because they'll be able to rely on the 4.2+ net operator providing the bundle.

[1]: https://ci-search-ci-search-next.svc.ci.openshift.org/chart?name=upgrade&search=clusteroperator/cloud-credential%20changed%20Degraded%20to%20True:.*
[2]: https://openshift-release.svc.ci.openshift.org/releasestream/4-stable/release/4.2.0-rc.1#upgrades-from

--- Additional comment from W. Trevor King on 2019-10-04 18:18:33 EDT ---

Trying to back up the above^ with must-gather logs, here's the CVO with a few comments stuffed in by me:

$ grep -A1 'ClusterVersionOperator\|cloud-credential\|Summarizing .* errors\|Running sync.*in state' namespaces/openshift-cluster-version/pods/cluster-version-operator-79d896cb77-n7bt4/cluster-version-operator/cluster-version-operator/logs/current.log | grep -v 'Throttling request took\|^--' | less
2019-10-04T14:56:54.634912631Z I1004 14:56:54.634633       1 start.go:19] ClusterVersionOperator v4.2.0-201910031548-dirty
2019-10-04T14:56:54.635366635Z I1004 14:56:54.635335       1 merged_client_builder.go:122] Using in-cluster configuration
2019-10-04T14:56:54.908502387Z I1004 14:56:54.908480       1 cvo.go:251] Starting ClusterVersionOperator with minimum reconcile period 2m52.525702462s
2019-10-04T14:56:54.908525052Z I1004 14:56:54.908498       1 reflector.go:131] Starting reflector *v1.Proxy (3m19.747206386s) from github.com/openshift/client-go/config/informers/externalversions/factory.go:101
2019-10-04T14:56:55.009337771Z I1004 14:56:55.009302       1 sync_worker.go:453] Running sync registry.svc.ci.openshift.org/ocp/release:4.2.0-rc.1 (force=true) on generation 5 in state Updating at attempt 0
2019-10-04T14:56:55.009490027Z I1004 14:56:55.009438       1 sync_worker.go:459] Loading payload
2019-10-04T15:00:16.081877642Z I1004 15:00:16.081857       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:00:16.084103873Z I1004 15:00:16.084056       1 sync_worker.go:592] Done syncing for namespace "openshift-apiserver-operator" (102 of 432)
2019-10-04T15:00:16.104131142Z I1004 15:00:16.101215       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:00:16.104131142Z I1004 15:00:16.101243       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:00:16.129464068Z I1004 15:00:16.129425       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:00:16.129544237Z I1004 15:00:16.129529       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:00:16.143914436Z I1004 15:00:16.143875       1 sync_worker.go:592] Done syncing for customresourcedefinition "openshiftapiservers.operator.openshift.io" (103 of 432)
2019-10-04T15:00:16.174041498Z I1004 15:00:16.173714       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:00:16.174164374Z I1004 15:00:16.174144       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:00:16.181647058Z I1004 15:00:16.181621       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:00:16.18170055Z I1004 15:00:16.181687       1 sync_worker.go:579] Running sync for namespace "openshift-machine-api" (80 of 432)
2019-10-04T15:02:40.061056677Z I1004 15:02:40.061050       1 sync_worker.go:741] Summarizing 1 errors
2019-10-04T15:02:40.061067543Z I1004 15:02:40.061056       1 sync_worker.go:745] Update error 100 of 432: ClusterOperatorNotAvailable Cluster operator machine-api is still updating (*errors.errorString: cluster operator machine-api is still updating)

^ machine-API taking a bit to level.  Not a big deal, but it kicks us into a new round while the 4.1 crd operator works on those new requests.  Back to the grep output:

2019-10-04T15:03:03.649357879Z I1004 15:03:03.649311       1 sync_worker.go:453] Running sync registry.svc.ci.openshift.org/ocp/release:4.2.0-rc.1 (force=true) on generation 5 in state Updating at attempt 1
2019-10-04T15:03:03.650489817Z I1004 15:03:03.650465       1 task_graph.go:601] Waiting for workers to complete
2019-10-04T15:03:06.152998869Z I1004 15:03:06.152978       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:03:06.202725308Z I1004 15:03:06.202690       1 sync_worker.go:592] Done syncing for namespace "openshift-apiserver-operator" (102 of 432)
2019-10-04T15:03:06.354855637Z I1004 15:03:06.354806       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:03:06.354855637Z I1004 15:03:06.354840       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:03:06.553825906Z I1004 15:03:06.553783       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:03:06.553825906Z I1004 15:03:06.553809       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:03:06.754259328Z I1004 15:03:06.754209       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:03:06.754259328Z I1004 15:03:06.754242       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:03:06.954045582Z I1004 15:03:06.954005       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:03:06.954045582Z I1004 15:03:06.954034       1 sync_worker.go:579] Running sync for namespace "openshift-machine-api" (80 of 432)
2019-10-04T15:03:08.353624208Z I1004 15:03:08.353612       1 sync_worker.go:579] Running sync for clusterrole "system:openshift:cloud-credential-operator:cluster-reader" (112 of 432)
2019-10-04T15:03:08.353800288Z I1004 15:03:08.353786       1 task_graph.go:590] Running 17 on 8
2019-10-04T15:03:08.403000771Z I1004 15:03:08.402951       1 sync_worker.go:592] Done syncing for clusterrole "system:openshift:cloud-credential-operator:cluster-reader" (112 of 432)
2019-10-04T15:03:08.403000771Z I1004 15:03:08.402990       1 sync_worker.go:579] Running sync for customresourcedefinition "credentialsrequests.cloudcredential.openshift.io" (113 of 432)
2019-10-04T15:03:09.203719171Z I1004 15:03:09.203701       1 sync_worker.go:579] Running sync for namespace "openshift-cloud-credential-operator" (114 of 432)
2019-10-04T15:03:10.015368835Z I1004 15:03:10.015326       1 sync_worker.go:592] Done syncing for namespace "openshift-cloud-credential-operator" (114 of 432)
2019-10-04T15:03:10.015452808Z I1004 15:03:10.015437       1 sync_worker.go:579] Running sync for clusterrole "cloud-credential-operator-role" (115 of 432)
2019-10-04T15:03:11.559531605Z I1004 15:03:11.559514       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-azure" (158 of 432)
2019-10-04T15:03:11.604289335Z I1004 15:03:11.604251       1 sync_worker.go:592] Done syncing for clusterrole "cloud-credential-operator-role" (115 of 432)
2019-10-04T15:03:11.604362023Z I1004 15:03:11.604344       1 sync_worker.go:579] Running sync for clusterrolebinding "cloud-credential-operator-rolebinding" (116 of 432)
2019-10-04T15:03:12.417886587Z I1004 15:03:12.417821       1 sync_worker.go:592] Done syncing for clusterrolebinding "cloud-credential-operator-rolebinding" (116 of 432)
2019-10-04T15:03:12.417886587Z I1004 15:03:12.417872       1 sync_worker.go:579] Running sync for configmap "openshift-cloud-credential-operator/cco-trusted-ca" (117 of 432)
2019-10-04T15:03:13.164626378Z I1004 15:03:13.164577       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-azure" (158 of 432)
2019-10-04T15:03:13.164626378Z I1004 15:03:13.164614       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-gcs" (159 of 432)
2019-10-04T15:03:14.025897897Z I1004 15:03:14.025851       1 sync_worker.go:592] Done syncing for configmap "openshift-cloud-credential-operator/cco-trusted-ca" (117 of 432)
2019-10-04T15:03:14.025978052Z I1004 15:03:14.025962       1 sync_worker.go:579] Running sync for service "openshift-cloud-credential-operator/controller-manager-service" (118 of 432)
2019-10-04T15:03:14.455243187Z I1004 15:03:14.455222       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress" (174 of 432)
2019-10-04T15:03:14.755838976Z I1004 15:03:14.755798       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-gcs" (159 of 432)
2019-10-04T15:03:14.755954274Z I1004 15:03:14.755909       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-openstack" (160 of 432)
2019-10-04T15:03:15.555825647Z I1004 15:03:15.555787       1 sync_worker.go:592] Done syncing for service "openshift-cloud-credential-operator/controller-manager-service" (118 of 432)
2019-10-04T15:03:15.555891508Z I1004 15:03:15.555878       1 sync_worker.go:579] Running sync for deployment "openshift-cloud-credential-operator/cloud-credential-operator" (119 of 432)

^ asking nicely for the 4.2 cred operator.  Back to grep:

2019-10-04T15:03:15.905984145Z I1004 15:03:15.905923       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress" (174 of 432)
2019-10-04T15:03:15.905984145Z I1004 15:03:15.905957       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-azure" (175 of 432)
2019-10-04T15:03:16.205116626Z I1004 15:03:16.205079       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-openstack" (160 of 432)
2019-10-04T15:03:16.205225646Z I1004 15:03:16.205206       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry" (161 of 432)
2019-10-04T15:03:17.305703228Z I1004 15:03:17.305656       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-azure" (175 of 432)
2019-10-04T15:03:17.305703228Z I1004 15:03:17.305686       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-gcp" (176 of 432)
2019-10-04T15:03:17.605523349Z I1004 15:03:17.605477       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry" (161 of 432)
2019-10-04T15:03:17.605523349Z I1004 15:03:17.605504       1 sync_worker.go:579] Running sync for clusterrole "cluster-image-registry-operator" (162 of 432)
2019-10-04T15:03:18.352918237Z I1004 15:03:18.352873       1 apps.go:115] Deployment cloud-credential-operator is not ready. status: (replicas: 2, updated: 1, ready: 1, unavailable: 1)

^ three seconds later, the 4.2 cred operator is halfway up.  Back to grep:

2019-10-04T15:03:18.754439796Z I1004 15:03:18.754391       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-gcp" (176 of 432)
2019-10-04T15:03:18.754439796Z I1004 15:03:18.754425       1 sync_worker.go:579] Running sync for namespace "openshift-ingress-operator" (177 of 432)
2019-10-04T15:03:21.853276042Z I1004 15:03:21.853245       1 apps.go:115] Deployment cloud-credential-operator is not ready. status: (replicas: 2, updated: 1, ready: 1, unavailable: 1)
2019-10-04T15:03:24.557421724Z I1004 15:03:24.556721       1 apps.go:115] Deployment cloud-credential-operator is not ready. status: (replicas: 2, updated: 1, ready: 1, unavailable: 1)
2019-10-04T15:03:27.355424004Z I1004 15:03:27.355383       1 apps.go:115] Deployment cloud-credential-operator is not ready. status: (replicas: 2, updated: 1, ready: 1, unavailable: 1)
2019-10-04T15:03:27.589846672Z I1004 15:03:27.589806       1 apps.go:115] Deployment openshift-service-catalog-controller-manager-operator is not ready. status: (replicas: 2, updated: 1, ready: 1, unavailable: 1)
2019-10-04T15:03:30.355443258Z I1004 15:03:30.355394       1 sync_worker.go:592] Done syncing for deployment "openshift-cloud-credential-operator/cloud-credential-operator" (119 of 432)

^ 4.2 cred operator up.  Back to grep:

2019-10-04T15:03:30.355443258Z I1004 15:03:30.355428       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/cloud-credential-operator-iam-ro" (120 of 432)
2019-10-04T15:03:30.360685385Z I1004 15:03:30.360653       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/cloud-credential-operator-iam-ro" (120 of 432)
2019-10-04T15:03:30.360724872Z I1004 15:03:30.360678       1 sync_worker.go:579] Running sync for clusteroperator "cloud-credential" (121 of 432)
2019-10-04T15:03:30.563945368Z I1004 15:03:30.563541       1 apps.go:115] Deployment openshift-service-catalog-controller-manager-operator is not ready. status: (replicas: 2, updated: 1, ready: 1, unavailable: 1)
2019-10-04T15:08:48.701038175Z E1004 15:08:48.700884       1 task.go:77] error running apply for clusteroperator "cloud-credential" (121 of 432): Cluster operator cloud-credential is reporting a failure: 2 of 5 credentials requests are failing to sync.

^ we were waiting for the cred operator to level, and now it's 5m later and the cred operator is Degraded.

2019-10-04T15:08:48.701038175Z I1004 15:08:48.701022       1 task_graph.go:583] Canceled worker 1
2019-10-04T15:08:48.701058188Z I1004 15:08:48.701051       1 task_graph.go:611] Result of work: [Cluster operator cloud-credential is reporting a failure: 2 of 5 credentials requests are failing to sync.]
2019-10-04T15:08:48.70106805Z I1004 15:08:48.701062       1 sync_worker.go:741] Summarizing 1 errors
2019-10-04T15:08:48.701076618Z I1004 15:08:48.701067       1 sync_worker.go:745] Update error 121 of 432: ClusterOperatorDegraded Cluster operator cloud-credential is reporting a failure: 2 of 5 credentials requests are failing to sync. (*errors.errorString: cluster operator cloud-credential is reporting a failure: 2 of 5 credentials requests are failing to sync.)

^ failing the second round on the cred Degraded.  Future rounds keep hitting this same thing.  I dunno what entry rolls out the trust bundle, but I suspect that never happens.

--- Additional comment from W. Trevor King on 2019-10-04 18:38:40 EDT ---

And here's a happy 4.1.18->4.2.0-rc.1 run out of CI:

$ curl -s https://storage.googleapis.com/origin-ci-test/logs/release-openshift-origin-installer-e2e-aws-upgrade-4.1/513/artifacts/e2e-aws-upgrade/must-gather/quay-io-openshift-release-dev-ocp-v4-0-art-dev-sha256-b12acbea934c36134fa16e35b98843ba437a90b697322dabcc9397e9d9eef778/namespaces/openshift-cluster-version/pods/cluster-version-operator-795687b64c-tr7jk/cluster-version-operator/cluster-version-operator/logs/current.log | grep 'ClusterVersionOperator\|cloud-credential\|Result of work\|Running sync.*in state' | grep -v 'Throttling request took'
2019-10-04T15:23:05.354622331Z I1004 15:23:05.354379       1 start.go:19] ClusterVersionOperator v4.2.0-201910031548-dirty
2019-10-04T15:23:05.855399656Z I1004 15:23:05.855368       1 cvo.go:251] Starting ClusterVersionOperator with minimum reconcile period 2m52.525702462s
2019-10-04T15:23:05.956114966Z I1004 15:23:05.956066       1 sync_worker.go:453] Running sync registry.svc.ci.openshift.org/ocp/release@sha256:0a1dcbc81869f790fdd26d481706ee5d18ff4f5a13a833460d56fa0c396dc153 (force=true) on generation 2 in state Updating at attempt 0
2019-10-04T15:23:49.938126394Z I1004 15:23:49.938094       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:23:49.966886555Z I1004 15:23:49.966845       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:23:49.966886555Z I1004 15:23:49.966877       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:23:49.976155733Z I1004 15:23:49.976111       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:23:49.976195467Z I1004 15:23:49.976145       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:23:49.983912846Z I1004 15:23:49.983867       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:23:49.983912846Z I1004 15:23:49.983898       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:23:49.992377006Z I1004 15:23:49.992333       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:23:53.178533481Z I1004 15:23:53.178507       1 sync_worker.go:579] Running sync for clusterrole "system:openshift:cloud-credential-operator:cluster-reader" (112 of 432)
2019-10-04T15:23:53.188682416Z I1004 15:23:53.188632       1 sync_worker.go:592] Done syncing for clusterrole "system:openshift:cloud-credential-operator:cluster-reader" (112 of 432)
2019-10-04T15:23:53.231982116Z I1004 15:23:53.231939       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-azure" (158 of 432)
2019-10-04T15:23:53.241541374Z I1004 15:23:53.238927       1 sync_worker.go:579] Running sync for namespace "openshift-cloud-credential-operator" (114 of 432)
2019-10-04T15:23:53.246705033Z I1004 15:23:53.246634       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress" (174 of 432)
2019-10-04T15:23:53.774297917Z I1004 15:23:53.774255       1 sync_worker.go:592] Done syncing for namespace "openshift-cloud-credential-operator" (114 of 432)
2019-10-04T15:23:53.774297917Z I1004 15:23:53.774284       1 sync_worker.go:579] Running sync for clusterrole "cloud-credential-operator-role" (115 of 432)
2019-10-04T15:23:54.226631408Z I1004 15:23:54.226588       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-azure" (158 of 432)
2019-10-04T15:23:54.226631408Z I1004 15:23:54.226622       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-gcs" (159 of 432)
2019-10-04T15:23:54.574803409Z I1004 15:23:54.574757       1 sync_worker.go:592] Done syncing for clusterrole "cloud-credential-operator-role" (115 of 432)
2019-10-04T15:23:54.574843727Z I1004 15:23:54.574801       1 sync_worker.go:579] Running sync for clusterrolebinding "cloud-credential-operator-rolebinding" (116 of 432)
2019-10-04T15:23:54.681198819Z I1004 15:23:54.681157       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress" (174 of 432)
2019-10-04T15:23:54.681250378Z I1004 15:23:54.681197       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-azure" (175 of 432)
2019-10-04T15:23:55.374519336Z I1004 15:23:55.374477       1 sync_worker.go:592] Done syncing for clusterrolebinding "cloud-credential-operator-rolebinding" (116 of 432)
2019-10-04T15:23:55.37455913Z I1004 15:23:55.374515       1 sync_worker.go:579] Running sync for configmap "openshift-cloud-credential-operator/cco-trusted-ca" (117 of 432)
2019-10-04T15:23:55.826311489Z I1004 15:23:55.826266       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-gcs" (159 of 432)
2019-10-04T15:23:55.826311489Z I1004 15:23:55.826296       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-openstack" (160 of 432)
2019-10-04T15:23:56.180121575Z I1004 15:23:56.180081       1 sync_worker.go:592] Done syncing for configmap "openshift-cloud-credential-operator/cco-trusted-ca" (117 of 432)
2019-10-04T15:23:56.18016116Z I1004 15:23:56.180115       1 sync_worker.go:579] Running sync for service "openshift-cloud-credential-operator/controller-manager-service" (118 of 432)
2019-10-04T15:23:56.278819954Z I1004 15:23:56.278777       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-azure" (175 of 432)
2019-10-04T15:23:56.278857821Z I1004 15:23:56.278816       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-gcp" (176 of 432)
2019-10-04T15:23:57.426530261Z I1004 15:23:57.426496       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-openstack" (160 of 432)
2019-10-04T15:23:57.42661334Z I1004 15:23:57.426577       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry" (161 of 432)
2019-10-04T15:23:57.729359151Z I1004 15:23:57.729302       1 sync_worker.go:592] Done syncing for service "openshift-cloud-credential-operator/controller-manager-service" (118 of 432)
2019-10-04T15:23:57.729359151Z I1004 15:23:57.729338       1 sync_worker.go:579] Running sync for deployment "openshift-cloud-credential-operator/cloud-credential-operator" (119 of 432)
2019-10-04T15:23:57.82717221Z I1004 15:23:57.827108       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-gcp" (176 of 432)
2019-10-04T15:23:58.876579613Z I1004 15:23:58.876528       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry" (161 of 432)
2019-10-04T15:24:00.475128021Z I1004 15:24:00.475084       1 sync_worker.go:592] Done syncing for deployment "openshift-cloud-credential-operator/cloud-credential-operator" (119 of 432)

^ all the way through to the cred operator deployment in the first round.  And we're levelling 2.7s after requesting the bump at 23:57.729359151Z!

2019-10-04T15:24:00.4751792Z I1004 15:24:00.475129       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/cloud-credential-operator-iam-ro" (120 of 432)
2019-10-04T15:24:01.576911039Z I1004 15:24:01.576860       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/cloud-credential-operator-iam-ro" (120 of 432)
2019-10-04T15:24:01.576946929Z I1004 15:24:01.576903       1 sync_worker.go:579] Running sync for clusteroperator "cloud-credential" (121 of 432)
2019-10-04T15:24:01.576982029Z I1004 15:24:01.576957       1 sync_worker.go:592] Done syncing for clusteroperator "cloud-credential" (121 of 432)
2019-10-04T15:28:51.00787889Z I1004 15:28:51.007851       1 task_graph.go:611] Result of work: [Cluster operator machine-config is still updating]

^ before we die on the machine-config.

2019-10-04T15:29:15.50346586Z I1004 15:29:15.503385       1 sync_worker.go:453] Running sync registry.svc.ci.openshift.org/ocp/release@sha256:0a1dcbc81869f790fdd26d481706ee5d18ff4f5a13a833460d56fa0c396dc153 (force=true) on generation 2 in state Updating at attempt 1
2019-10-04T15:29:18.009578499Z I1004 15:29:18.009565       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:29:18.211201312Z I1004 15:29:18.211162       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-aws" (76 of 432)
2019-10-04T15:29:18.211238984Z I1004 15:29:18.211193       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:29:18.411091358Z I1004 15:29:18.411049       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-azure" (77 of 432)
2019-10-04T15:29:18.411122724Z I1004 15:29:18.411087       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:29:18.611925376Z I1004 15:29:18.611887       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-openstack" (78 of 432)
2019-10-04T15:29:18.612018466Z I1004 15:29:18.611991       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:29:18.811906509Z I1004 15:29:18.811862       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-machine-api-gcp" (79 of 432)
2019-10-04T15:29:20.111785867Z I1004 15:29:20.111571       1 sync_worker.go:579] Running sync for clusterrole "system:openshift:cloud-credential-operator:cluster-reader" (112 of 432)
2019-10-04T15:29:20.309153144Z I1004 15:29:20.309112       1 sync_worker.go:592] Done syncing for clusterrole "system:openshift:cloud-credential-operator:cluster-reader" (112 of 432)
2019-10-04T15:29:21.111253368Z I1004 15:29:21.111168       1 sync_worker.go:579] Running sync for namespace "openshift-cloud-credential-operator" (114 of 432)
2019-10-04T15:29:21.408907558Z I1004 15:29:21.408898       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-azure" (158 of 432)
2019-10-04T15:29:21.909933017Z I1004 15:29:21.909890       1 sync_worker.go:592] Done syncing for namespace "openshift-cloud-credential-operator" (114 of 432)
2019-10-04T15:29:21.909972048Z I1004 15:29:21.909926       1 sync_worker.go:579] Running sync for clusterrole "cloud-credential-operator-role" (115 of 432)
2019-10-04T15:29:22.015232723Z I1004 15:29:22.015190       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress" (174 of 432)
2019-10-04T15:29:22.715635897Z I1004 15:29:22.715583       1 sync_worker.go:592] Done syncing for clusterrole "cloud-credential-operator-role" (115 of 432)
2019-10-04T15:29:22.715678285Z I1004 15:29:22.715626       1 sync_worker.go:579] Running sync for clusterrolebinding "cloud-credential-operator-rolebinding" (116 of 432)
2019-10-04T15:29:23.012253599Z I1004 15:29:23.012213       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-azure" (158 of 432)
2019-10-04T15:29:23.012284848Z I1004 15:29:23.012248       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-gcs" (159 of 432)
2019-10-04T15:29:23.508659846Z I1004 15:29:23.508617       1 sync_worker.go:592] Done syncing for clusterrolebinding "cloud-credential-operator-rolebinding" (116 of 432)
2019-10-04T15:29:23.508698835Z I1004 15:29:23.508649       1 sync_worker.go:579] Running sync for configmap "openshift-cloud-credential-operator/cco-trusted-ca" (117 of 432)
2019-10-04T15:29:23.610920771Z I1004 15:29:23.610879       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress" (174 of 432)
2019-10-04T15:29:23.61096187Z I1004 15:29:23.610914       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-azure" (175 of 432)
2019-10-04T15:29:24.319788441Z I1004 15:29:24.318682       1 sync_worker.go:592] Done syncing for configmap "openshift-cloud-credential-operator/cco-trusted-ca" (117 of 432)
2019-10-04T15:29:24.319788441Z I1004 15:29:24.318755       1 sync_worker.go:579] Running sync for service "openshift-cloud-credential-operator/controller-manager-service" (118 of 432)
2019-10-04T15:29:24.614663169Z I1004 15:29:24.614619       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-gcs" (159 of 432)
2019-10-04T15:29:24.614704547Z I1004 15:29:24.614655       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-openstack" (160 of 432)
2019-10-04T15:29:25.211135248Z I1004 15:29:25.211095       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-azure" (175 of 432)
2019-10-04T15:29:25.211189739Z I1004 15:29:25.211130       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-gcp" (176 of 432)
2019-10-04T15:29:25.913362412Z I1004 15:29:25.913321       1 sync_worker.go:592] Done syncing for service "openshift-cloud-credential-operator/controller-manager-service" (118 of 432)
2019-10-04T15:29:25.913394483Z I1004 15:29:25.913358       1 sync_worker.go:579] Running sync for deployment "openshift-cloud-credential-operator/cloud-credential-operator" (119 of 432)
2019-10-04T15:29:26.210716916Z I1004 15:29:26.210657       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry-openstack" (160 of 432)
2019-10-04T15:29:26.210716916Z I1004 15:29:26.210690       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry" (161 of 432)
2019-10-04T15:29:26.763131386Z I1004 15:29:26.763085       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-ingress-gcp" (176 of 432)
2019-10-04T15:29:27.711435051Z I1004 15:29:27.711399       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/openshift-image-registry" (161 of 432)
2019-10-04T15:29:28.809218888Z I1004 15:29:28.809178       1 sync_worker.go:592] Done syncing for deployment "openshift-cloud-credential-operator/cloud-credential-operator" (119 of 432)
2019-10-04T15:29:28.809218888Z I1004 15:29:28.809205       1 sync_worker.go:579] Running sync for credentialsrequest "openshift-cloud-credential-operator/cloud-credential-operator-iam-ro" (120 of 432)
2019-10-04T15:29:30.061693539Z I1004 15:29:30.061652       1 sync_worker.go:592] Done syncing for credentialsrequest "openshift-cloud-credential-operator/cloud-credential-operator-iam-ro" (120 of 432)
2019-10-04T15:29:30.061746843Z I1004 15:29:30.061687       1 sync_worker.go:579] Running sync for clusteroperator "cloud-credential" (121 of 432)
2019-10-04T15:29:30.061823086Z I1004 15:29:30.061794       1 sync_worker.go:592] Done syncing for clusteroperator "cloud-credential" (121 of 432)
2019-10-04T15:31:24.657818709Z I1004 15:31:24.657787       1 task_graph.go:611] Result of work: []
2019-10-04T15:34:17.183836883Z I1004 15:34:17.183759       1 sync_worker.go:453] Running sync registry.svc.ci.openshift.org/ocp/release@sha256:0a1dcbc81869f790fdd26d481706ee5d18ff4f5a13a833460d56fa0c396dc153 (force=true) on generation 2 in state Reconciling at attempt 0

^ successfully through the whole thing in the second round.  Cred ClusterOperator checked out at 15:29:30, 5.5m after the cred operator deployment was bumped to 4.2 at 15:23:57 and that deployment leveled at 15:24:00.

2.7 seconds is a really fast deployment level.  I wonder if these logs are from a new CVO pod that was rescheduled.  Something like:

1. Bump the CVO pod, new 4.2 pod scheduled on node A.
2. Upgrade mostly completes.
3. Node A gets cycled late in the upgrade, CVO rescheduled to node B.
4. Must-gather gets logs from the node-B pod

Checking:

$ curl -s https://storage.googleapis.com/origin-ci-test/logs/release-openshift-origin-installer-e2e-aws-upgrade-4.1/513/artifacts/e2e-aws-upgrade/must-gather/quay-io-openshift-release-dev-ocp-v4-0-art-dev-sha256-b12acbea934c36134fa16e35b98843ba437a90b697322dabcc9397e9d9eef778/namespaces/openshift-cluster-version/pods/cluster-version-operator-795687b64c-tr7jk/cluster-version-operator-795687b64c-tr7jk.yaml | grep nodeName:
  nodeName: ip-10-0-141-224.ec2.internal
$ curl -s https://storage.googleapis.com/origin-ci-test/logs/release-openshift-origin-installer-e2e-aws-upgrade-4.1/513/artifacts/e2e-aws-upgrade/nodes.json | jq -r '.items[] | .conditions = ([.status.conditions[] | {key: .type, value: .}] | from_entries) | .conditions.Ready.lastTransitionTime + " " + .metadata.name + " " + .metadata.annotations["machine.openshift.io/machine"]' | sort
2019-10-04T15:08:04Z ip-10-0-159-151.ec2.internal openshift-machine-api/ci-op-wb4nr65l-281c8-f4hpp-worker-us-east-1b-dslpq
2019-10-04T15:08:31Z ip-10-0-141-224.ec2.internal openshift-machine-api/ci-op-wb4nr65l-281c8-f4hpp-master-0
2019-10-04T15:21:15Z ip-10-0-139-183.ec2.internal openshift-machine-api/ci-op-wb4nr65l-281c8-f4hpp-worker-us-east-1a-tslpq
2019-10-04T15:25:46Z ip-10-0-131-234.ec2.internal openshift-machine-api/ci-op-wb4nr65l-281c8-f4hpp-master-2
2019-10-04T15:29:33Z ip-10-0-153-34.ec2.internal openshift-machine-api/ci-op-wb4nr65l-281c8-f4hpp-master-1
2019-10-04T15:38:23Z ip-10-0-142-88.ec2.internal openshift-machine-api/ci-op-wb4nr65l-281c8-f4hpp-worker-us-east-1a-rl89g

So yeah, the CVO pod we have started at 15:23:05, and we missed the bulk of the upgrade which has been running since at least 15:08.  Getting an exact start time:

$ curl -s https://storage.googleapis.com/origin-ci-test/logs/release-openshift-origin-installer-e2e-aws-upgrade-4.1/513/artifacts/e2e-aws-upgrade/must-gather/quay-io-openshift-release-dev-ocp-v4-0-art-dev-sha256-b12acbea934c36134fa16e35b98843ba437a90b697322dabcc9397e9d9eef778/cluster-scoped-resources/config.openshift.io/clusterversions/version.yaml | yaml2json | jq -r '.status.history[0].startedTime'
2019-10-04T14:32:48Z

So without a way to peer back deeper into the CVO logs, these late-upgrade pod logs are probably not all that useful.
Comment 3 sheng.lao 2019-10-11 10:02:13 UTC 
I updated it from 4.1.18 to 4.2.0-rc.5

# oc get clusterversion
NAME      VERSION      AVAILABLE   PROGRESSING   SINCE   STATUS
version   4.2.0-rc.5   True        False         57m     Cluster version is 4.2.0-rc.5

# oc get pod  -n openshift-cluster-version 
NAME                                        READY   STATUS    RESTARTS   AGE
cluster-version-operator-76fd5d88d9-lq2xp   1/1     Running   0          60m

monitor log without errors
# oc logs -f cluster-version-operator-76fd5d88d9-lq2xp  -n openshift-cluster-version |grep 'ClusterVersionOperator\|cloud-credential\|Result of work\|Running sync.*in state' | grep -v 'Throttling request took'
Comment 4 errata-xmlrpc 2019-10-16 06:41: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, 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-2019:2922