I0208 07:56:21.174003 1 cvo.go:363] Starting ClusterVersionOperator with minimum reconcile period 3m39.457405047s
3m39.457405047 is on a longer side of the domain. Could be useful.
I0208 11:10:57.056591 1 cvo.go:595] Desired version from spec is v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}
I0208 11:10:57.056643 1 sync_worker.go:811] Detected while considering cluster version generation 3: version changed (from { 4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58 false} to { registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca false})
This is the first occurrence of ci-ln-dkrq3mk so this is when oc adm upgrade --to-image <ci-ln-dkrq3mk> --allow-explicit-upgrade was run. CVO noticed the version difference and started trying to upgrade
I0208 11:10:57.056651 1 sync_worker.go:261] syncPayload: registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca (force=false)
I0208 11:10:57.056890 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RetrievePayload' Retrieving and verifying payload version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca"
I0208 11:10:57.659802 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:11:23.901112 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:11:27.658943 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:11:53.900983 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:11:57.659713 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:12:23.900416 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:12:27.659153 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:12:44.256281 1 cvo.go:658] Started syncing upgradeable "openshift-cluster-version/version"
I0208 11:12:44.256368 1 upgradeable.go:69] Upgradeability last checked 1m47.199799838s ago, will not re-check until 2023-02-08T11:12:57Z
I0208 11:12:44.256375 1 cvo.go:660] Finished syncing upgradeable "openshift-cluster-version/version" (107.239µs)
I0208 11:12:53.900463 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
Nothing of interest here.
I0208 11:12:57.057460 1 sync_worker.go:437] loadUpdatedPayload syncPayload err=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
Verification timed out after 2 minutes. Expected with the PR. Expected the cluster to stay in this state and keep retrying.
I0208 11:12:57.057488 1 status.go:170] Synchronizing status errs=field.ErrorList(nil) status=&cvo.SyncWorkerStatus{Generation:2, Failure:error(nil), Done:834, Total:834, Completed:36, Reconciling:true, Initial:false, VersionHash:"xoIORUSMPyg=", Architecture:"amd64", LastProgress:time.Date(2023, time.February, 8, 11, 9, 58, 828308336, time.Local), Actual:v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)}, Verified:false, loadPayloadStatus:cvo.LoadPayloadStatus{Step:"RetrievePayload", Message:"Retrieving payload failed version=\"\" image=\"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca\" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat", AcceptedRisks:"", Failure:(*payload.UpdateError)(0xc002c10ab0), Update:v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}, Verified:false, Local:false, LastTransitionTime:time.Time{wall:0xc0f0fece436c9453, ext:12268030905134, loc:(*time.Location)(0x2fe2900)}}, CapabilitiesStatus:cvo.CapabilityStatus{Status:v1.ClusterVersionCapabilitiesStatus{EnabledCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}, KnownCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}}, ImplicitlyEnabledCaps:[]v1.ClusterVersionCapability(nil)}}
I0208 11:12:57.057597 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Warning' reason: 'RetrievePayloadFailed' Retrieving payload failed version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
I0208 11:12:57.057562 1 status.go:90] merge into existing history completed=true desired=v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)} last=&v1.UpdateHistory{State:"Completed", StartedTime:time.Date(2023, time.February, 8, 7, 43, 58, 0, time.Local), CompletionTime:time.Date(2023, time.February, 8, 8, 43, 51, 0, time.Local), Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", Verified:false, AcceptedRisks:""}
I0208 11:12:57.066116 1 cvo.go:572] Finished syncing cluster version "openshift-cluster-version/version" (2m0.009531641s)
I0208 11:12:57.066154 1 cvo.go:570] Started syncing cluster version "openshift-cluster-version/version", spec changes, status, and payload
I0208 11:12:57.066161 1 cvo.go:581] Cluster version changed, waiting for newer event
I0208 11:12:57.066164 1 cvo.go:572] Finished syncing cluster version "openshift-cluster-version/version" (11.749µs)
I0208 11:12:57.070430 1 cvo.go:658] Started syncing upgradeable "openshift-cluster-version/version"
I0208 11:12:57.070437 1 cvo.go:570] Started syncing cluster version "openshift-cluster-version/version", spec changes, status, and payload
I0208 11:12:57.070529 1 cvo.go:595] Desired version from spec is v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}
I0208 11:12:57.070579 1 sync_worker.go:811] Detected while considering cluster version generation 3: version changed (from { 4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58 false} to { registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca false})
We immediately (why immediately?) retry.
- Check out what are the expectations for the retry.
I0208 11:12:57.070591 1 sync_worker.go:261] syncPayload: registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca (force=false)
I0208 11:12:57.070500 1 upgradeable.go:123] Cluster current version=4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest
I0208 11:12:57.070931 1 upgradeable.go:112] All upgradeability conditions are passing
I0208 11:12:57.070946 1 cvo.go:660] Finished syncing upgradeable "openshift-cluster-version/version" (516.96µs)
I0208 11:12:57.071276 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RetrievePayload' Retrieving and verifying payload version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca"
I0208 11:12:57.659179 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:13:16.019579 1 availableupdates.go:277] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: RemoteFailed: Get "https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.12&id=2e9fe08f-707f-4cf2-8e68-667e59901d66&version=4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest": dial tcp 44.209.252.60:443: connect: connection timed out
I0208 11:13:16.019614 1 cvo.go:641] Finished syncing available updates "openshift-cluster-version/version" (4m22.670666968s)
I0208 11:13:16.019626 1 cvo.go:639] Started syncing available updates "openshift-cluster-version/version"
I0208 11:13:16.019640 1 availableupdates.go:58] Available updates were recently retrieved, with less than 3m39.457405047s elapsed since 2023-02-08T11:13:16Z, will try later.
I0208 11:13:16.019646 1 cvo.go:641] Finished syncing available updates "openshift-cluster-version/version" (19.135µs)
I0208 11:13:23.900444 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:13:27.659216 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:13:38.286371 1 sync_worker.go:587] Wait finished
I0208 11:13:53.900569 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:13:57.658984 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:14:23.900995 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:14:27.659470 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:14:53.900575 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:14:57.071738 1 sync_worker.go:437] loadUpdatedPayload syncPayload err=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
2 minutes timeout on verification, same result. Expected.
I0208 11:14:57.071763 1 status.go:170] Synchronizing status errs=field.ErrorList(nil) status=&cvo.SyncWorkerStatus{Generation:2, Failure:error(nil), Done:834, Total:834, Completed:36, Reconciling:true, Initial:false, VersionHash:"xoIORUSMPyg=", Architecture:"amd64", LastProgress:time.Date(2023, time.February, 8, 11, 9, 58, 828308336, time.Local), Actual:v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)}, Verified:false, loadPayloadStatus:cvo.LoadPayloadStatus{Step:"RetrievePayload", Message:"Retrieving payload failed version=\"\" image=\"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca\" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat", AcceptedRisks:"", Failure:(*payload.UpdateError)(0xc0005d1a70), Update:v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}, Verified:false, Local:false, LastTransitionTime:time.Time{wall:0xc0f0feec44467c2d, ext:12388045185798, loc:(*time.Location)(0x2fe2900)}}, CapabilitiesStatus:cvo.CapabilityStatus{Status:v1.ClusterVersionCapabilitiesStatus{EnabledCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}, KnownCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}}, ImplicitlyEnabledCaps:[]v1.ClusterVersionCapability(nil)}}
I0208 11:14:57.071828 1 status.go:90] merge into existing history completed=true desired=v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)} last=&v1.UpdateHistory{State:"Completed", StartedTime:time.Date(2023, time.February, 8, 7, 43, 58, 0, time.Local), CompletionTime:time.Date(2023, time.February, 8, 8, 43, 51, 0, time.Local), Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", Verified:false, AcceptedRisks:""}
I0208 11:14:57.072081 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Warning' reason: 'RetrievePayloadFailed' Retrieving payload failed version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
I0208 11:14:57.072150 1 sync_worker.go:637] Previous sync status: &cvo.SyncWorkerStatus{Generation:2, Failure:error(nil), Done:834, Total:834, Completed:36, Reconciling:true, Initial:false, VersionHash:"xoIORUSMPyg=", Architecture:"amd64", LastProgress:time.Date(2023, time.February, 8, 11, 9, 58, 828308336, time.Local), Actual:v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)}, Verified:false, loadPayloadStatus:cvo.LoadPayloadStatus{Step:"RetrievePayload", Message:"Retrieving payload failed version=\"\" image=\"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca\" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat", AcceptedRisks:"", Failure:(*payload.UpdateError)(0xc0005d1a70), Update:v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}, Verified:false, Local:false, LastTransitionTime:time.Time{wall:0xc0f0feec44467c2d, ext:12388045185798, loc:(*time.Location)(0x2fe2900)}}, CapabilitiesStatus:cvo.CapabilityStatus{Status:v1.ClusterVersionCapabilitiesStatus{EnabledCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}, KnownCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}}, ImplicitlyEnabledCaps:[]v1.ClusterVersionCapability(nil)}}
Nothing interesting here.
I0208 11:14:57.072226 1 sync_worker.go:888] apply: 4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest on generation 3 in state Reconciling at attempt 0
Here we started a current payload (ci-ln-vtrvh42) reconciliation attempt.
Notably, this before the --force upgrade is issued.
- Generation 3 (whatever that means)
- State
Reconciling(I think this is correct) - Attempt 0 (not sure what this means)
Questions:
- Should it run NOW?
- Should it run with these parameters?
- Is the finish of this operation logged somehow? How?
I0208 11:14:57.074037 1 task_graph.go:477] Running 0 on worker 1
I0208 11:14:57.074057 1 task_graph.go:477] Running 2 on worker 1
I0208 11:14:57.074075 1 sync_worker.go:993] Running sync for namespace "openshift-cluster-storage-operator" (253 of 834)
I0208 11:14:57.074130 1 task_graph.go:477] Running 1 on worker 0
I0208 11:14:57.078122 1 sync_worker.go:1013] Done syncing for namespace "openshift-cluster-storage-operator" (253 of 834)
I0208 11:14:57.078149 1 task_graph.go:477] Running 3 on worker 1
I0208 11:14:57.082259 1 sync_worker.go:984] Precreated resource clusteroperator "openshift-apiserver" (449 of 834)
I0208 11:14:57.082282 1 sync_worker.go:993] Running sync for namespace "openshift-apiserver-operator" (441 of 834)
I0208 11:14:57.085110 1 sync_worker.go:984] Precreated resource clusteroperator "marketplace" (655 of 834)
I0208 11:14:57.085137 1 sync_worker.go:993] Running sync for namespace "openshift-marketplace" (645 of 834)
I0208 11:14:57.089063 1 sync_worker.go:1013] Done syncing for namespace "openshift-apiserver-operator" (441 of 834)
I0208 11:14:57.089169 1 sync_worker.go:993] Running sync for openshiftapiserver "cluster" (442 of 834)
I0208 11:14:57.089221 1 sync_worker.go:1013] Done syncing for namespace "openshift-marketplace" (645 of 834)
I0208 11:14:57.089299 1 sync_worker.go:993] Running sync for serviceaccount "openshift-marketplace/marketplace-operator" (646 of 834)
We reconcile some manifests. Why do we reconcile these manifests? We changed nothing. Maybe hotlooping.
Another sync started running here. My understanding is that the apply (log
snippet above) is not finished yet, we just run concurrently and our logs are
mixed.
I0208 11:14:57.092137 1 cvo.go:658] Started syncing upgradeable "openshift-cluster-version/version"
I0208 11:14:57.092188 1 upgradeable.go:123] Cluster current version=4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest
I0208 11:14:57.092213 1 upgradeable.go:112] All upgradeability conditions are passing
I0208 11:14:57.092227 1 cvo.go:660] Finished syncing upgradeable "openshift-cluster-version/version" (92.398µs)
I0208 11:14:57.092402 1 cvo.go:572] Finished syncing cluster version "openshift-cluster-version/version" (2m0.021965667s)
I0208 11:14:57.092417 1 cvo.go:570] Started syncing cluster version "openshift-cluster-version/version", spec changes, status, and payload
I0208 11:14:57.092429 1 cvo.go:595] Desired version from spec is v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}
I0208 11:14:57.092483 1 sync_worker.go:811] Detected while considering cluster version generation 3: version changed (from { 4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58 false} to { registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca false})
Again, immediate retry.
I0208 11:14:57.092496 1 sync_worker.go:261] syncPayload: registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca (force=false)
I0208 11:14:57.092673 1 cvo.go:639] Started syncing available updates "openshift-cluster-version/version"
I0208 11:14:57.092692 1 availableupdates.go:58] Available updates were recently retrieved, with less than 3m39.457405047s elapsed since 2023-02-08T11:13:16Z, will try later.
I0208 11:14:57.092697 1 cvo.go:641] Finished syncing available updates "openshift-cluster-version/version" (24.853µs)
I0208 11:14:57.092902 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RetrievePayload' Retrieving and verifying payload version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca"
I0208 11:14:57.093052 1 sync_worker.go:1013] Done syncing for serviceaccount "openshift-marketplace/marketplace-operator" (646 of 834)
Nothing of interest except the proof of the apply continues to run on the above line.
I0208 11:14:57.659167 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:15:23.900999 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:15:27.659372 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:15:53.901290 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:15:57.659792 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:16:23.900437 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:16:27.659050 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:16:35.164043 1 cvo.go:658] Started syncing upgradeable "openshift-cluster-version/version"
I0208 11:16:35.164088 1 cvo.go:639] Started syncing available updates "openshift-cluster-version/version"
I0208 11:16:35.164117 1 availableupdates.go:58] Available updates were recently retrieved, with less than 3m39.457405047s elapsed since 2023-02-08T11:13:16Z, will try later.
I0208 11:16:35.164125 1 upgradeable.go:69] Upgradeability last checked 1m38.071896117s ago, will not re-check until 2023-02-08T11:16:57Z
I0208 11:16:35.164127 1 cvo.go:641] Finished syncing available updates "openshift-cluster-version/version" (42.466µs)
I0208 11:16:35.164133 1 cvo.go:660] Finished syncing upgradeable "openshift-cluster-version/version" (97.941µs)
I0208 11:16:53.900928 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:16:57.093557 1 sync_worker.go:437] loadUpdatedPayload syncPayload err=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
And a 2m timeout of the immediate retry.
I0208 11:16:57.093583 1 status.go:170] Synchronizing status errs=field.ErrorList(nil) status=&cvo.SyncWorkerStatus{Generation:3, Failure:error(nil), Done:3, Total:834, Completed:0, Reconciling:true, Initial:false, VersionHash:"xoIORUSMPyg=", Architecture:"amd64", LastProgress:time.Date(1, time.January, 1, 0, 0, 0, 0, time.UTC), Actual:v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)}, Verified:false, loadPayloadStatus:cvo.LoadPayloadStatus{Step:"RetrievePayload", Message:"Retrieving payload failed version=\"\" image=\"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca\" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat", AcceptedRisks:"", Failure:(*payload.UpdateError)(0xc0004dc870), Update:v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}, Verified:false, Local:false, LastTransitionTime:time.Time{wall:0xc0f0ff0a45936c84, ext:12508067005281, loc:(*time.Location)(0x2fe2900)}}, CapabilitiesStatus:cvo.CapabilityStatus{Status:v1.ClusterVersionCapabilitiesStatus{EnabledCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}, KnownCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}}, ImplicitlyEnabledCaps:[]v1.ClusterVersionCapability(nil)}}
I0208 11:16:57.093660 1 status.go:90] merge into existing history completed=false desired=v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)} last=&v1.UpdateHistory{State:"Completed", StartedTime:time.Date(2023, time.February, 8, 7, 43, 58, 0, time.Local), CompletionTime:time.Date(2023, time.February, 8, 8, 43, 51, 0, time.Local), Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", Verified:false, AcceptedRisks:""}
I0208 11:16:57.093889 1 sync_worker.go:993] Running sync for clusterrole "marketplace-operator" (647 of 834)
The apply above continues. But why is there a 2m delay between
11:14:57.093052 Done syncing for serviceaccount "openshift-marketplace/marketplace-operator" (646 of 834)
and here?
- Check out how this behaved in the runs before here.
I0208 11:16:57.093951 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Warning' reason: 'RetrievePayloadFailed' Retrieving payload failed version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
I0208 11:16:57.093962 1 sync_worker.go:1013] Done syncing for openshiftapiserver "cluster" (442 of 834)
I0208 11:16:57.094051 1 sync_worker.go:993] Running sync for configmap "openshift-apiserver-operator/openshift-apiserver-operator-config" (443 of 834)
I0208 11:16:57.101659 1 cvo.go:572] Finished syncing cluster version "openshift-cluster-version/version" (2m0.009234375s)
I0208 11:16:57.101699 1 cvo.go:570] Started syncing cluster version "openshift-cluster-version/version", spec changes, status, and payload
I0208 11:16:57.101708 1 cvo.go:581] Cluster version changed, waiting for newer event
I0208 11:16:57.101711 1 cvo.go:572] Finished syncing cluster version "openshift-cluster-version/version" (13.377µs)
I0208 11:16:57.105242 1 cvo.go:658] Started syncing upgradeable "openshift-cluster-version/version"
I0208 11:16:57.105287 1 upgradeable.go:123] Cluster current version=4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest
I0208 11:16:57.105335 1 upgradeable.go:112] All upgradeability conditions are passing
I0208 11:16:57.105344 1 cvo.go:660] Finished syncing upgradeable "openshift-cluster-version/version" (111.68µs)
I0208 11:16:57.105361 1 cvo.go:570] Started syncing cluster version "openshift-cluster-version/version", spec changes, status, and payload
I0208 11:16:57.105390 1 cvo.go:595] Desired version from spec is v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}
I0208 11:16:57.105436 1 sync_worker.go:811] Detected while considering cluster version generation 3: version changed (from { 4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58 false} to { registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca false})
Immediate retry.
I0208 11:16:57.105504 1 sync_worker.go:261] syncPayload: registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca (force=false)
I0208 11:16:57.105942 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RetrievePayload' Retrieving and verifying payload version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca"
I0208 11:16:57.106357 1 cvo.go:639] Started syncing available updates "openshift-cluster-version/version"
I0208 11:16:57.106402 1 availableupdates.go:52] Retrieving available updates again, because more than 3m39.457405047s has elapsed since 2023-02-08T11:13:16Z
I0208 11:16:57.109993 1 sync_worker.go:1013] Done syncing for configmap "openshift-apiserver-operator/openshift-apiserver-operator-config" (443 of 834)
I0208 11:16:57.112093 1 cincinnati.go:111] 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.12&id=2e9fe08f-707f-4cf2-8e68-667e59901d66&version=4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest
I0208 11:16:57.659607 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:17:23.900926 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:17:27.659274 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:17:53.900602 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:17:57.659055 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:18:23.900949 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:18:27.659273 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:18:48.054152 1 cvo.go:658] Started syncing upgradeable "openshift-cluster-version/version"
I0208 11:18:48.055104 1 upgradeable.go:69] Upgradeability last checked 1m50.949753303s ago, will not re-check until 2023-02-08T11:18:57Z
I0208 11:18:48.055136 1 cvo.go:660] Finished syncing upgradeable "openshift-cluster-version/version" (993.099µs)
I0208 11:18:53.901050 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:18:57.105749 1 sync_worker.go:437] loadUpdatedPayload syncPayload err=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
... and a timeout after 2 minutes
I0208 11:18:57.105780 1 status.go:170] Synchronizing status errs=field.ErrorList(nil) status=&cvo.SyncWorkerStatus{Generation:3, Failure:error(nil), Done:5, Total:834, Completed:0, Reconciling:true, Initial:false, VersionHash:"xoIORUSMPyg=", Architecture:"amd64", LastProgress:time.Date(1, time.January, 1, 0, 0, 0, 0, time.UTC), Actual:v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)}, Verified:false, loadPayloadStatus:cvo.LoadPayloadStatus{Step:"RetrievePayload", Message:"Retrieving payload failed version=\"\" image=\"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca\" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat", AcceptedRisks:"", Failure:(*payload.UpdateError)(0xc00029d0e0), Update:v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:false}, Verified:false, Local:false, LastTransitionTime:time.Time{wall:0xc0f0ff28464d6ee5, ext:12628079195587, loc:(*time.Location)(0x2fe2900)}}, CapabilitiesStatus:cvo.CapabilityStatus{Status:v1.ClusterVersionCapabilitiesStatus{EnabledCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}, KnownCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}}, ImplicitlyEnabledCaps:[]v1.ClusterVersionCapability(nil)}}
I0208 11:18:57.105853 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Warning' reason: 'RetrievePayloadFailed' Retrieving payload failed version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca" failure=The update cannot be verified: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
I0208 11:18:57.105873 1 status.go:90] merge into existing history completed=false desired=v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)} last=&v1.UpdateHistory{State:"Completed", StartedTime:time.Date(2023, time.February, 8, 7, 43, 58, 0, time.Local), CompletionTime:time.Date(2023, time.February, 8, 8, 43, 51, 0, time.Local), Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", Verified:false, AcceptedRisks:""}
I0208 11:18:57.105911 1 sync_worker.go:993] Running sync for configmap "openshift-apiserver-operator/trusted-ca-bundle" (444 of 834)
Again, a suspicious 2m delay since the last Done syncing (OAO ConfigMap).
I0208 11:18:57.105957 1 cvo.go:572] Finished syncing cluster version "openshift-cluster-version/version" (2m0.000604789s)
I0208 11:18:57.105972 1 cvo.go:570] Started syncing cluster version "openshift-cluster-version/version", spec changes, status, and payload
I0208 11:18:57.105993 1 cvo.go:595] Desired version from spec is v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:true}
I0208 11:18:57.106115 1 sync_worker.go:1013] Done syncing for clusterrole "marketplace-operator" (647 of 834)
I0208 11:18:57.106371 1 sync_worker.go:811] Detected while considering cluster version generation 4: version changed (from { 4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58 false} to { registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca true})
Another immediate retry, but this time with Force: true (the oc adm upgrade --force was issued on 13:18:49 IST, 8s before here)
I0208 11:18:57.106448 1 sync_worker.go:261] syncPayload: registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca (force=true)
I0208 11:18:57.106622 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RetrievePayload' Retrieving and verifying payload version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca"
I0208 11:18:57.659670 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:19:23.900737 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:19:27.659766 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:19:53.901352 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:19:57.659019 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:20:23.900551 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:20:26.072699 1 cvo.go:658] Started syncing upgradeable "openshift-cluster-version/version"
I0208 11:20:26.072763 1 upgradeable.go:123] Cluster current version=4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest
I0208 11:20:26.072802 1 upgradeable.go:112] All upgradeability conditions are passing
I0208 11:20:26.072814 1 cvo.go:660] Finished syncing upgradeable "openshift-cluster-version/version" (121.574µs)
I0208 11:20:27.659821 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:20:53.901490 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
W0208 11:20:57.107454 1 updatepayload.go:125] Target release version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca" cannot be verified, but continuing anyway because the update was forced: unable to verify sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca against keyrings: verifier-public-key-redhat
2m until the timeout, as expected. But we proceed because now the upgrade is forced.
I0208 11:20:57.138561 1 batch.go:55] No active pods for job version--fmbrq in namespace openshift-cluster-version
I0208 11:20:57.138578 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
The version--fmbrq name looks a bit fishy, aren't we missing something in the middle?
- Check out the version
Jobname assembly
I0208 11:20:57.659238 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:21:00.142151 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:03.143114 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:06.142619 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:09.144563 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:12.143523 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:15.145706 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:18.142757 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:19.348664 1 availableupdates.go:277] Upstream server https://api.openshift.com/api/upgrades_info/v1/graph could not return available updates: RemoteFailed: Get "https://api.openshift.com/api/upgrades_info/v1/graph?arch=amd64&channel=stable-4.12&id=2e9fe08f-707f-4cf2-8e68-667e59901d66&version=4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest": dial tcp 44.209.252.60:443: connect: connection timed out
I0208 11:21:19.348702 1 cvo.go:641] Finished syncing available updates "openshift-cluster-version/version" (4m22.243342257s)
I0208 11:21:19.348715 1 cvo.go:639] Started syncing available updates "openshift-cluster-version/version"
I0208 11:21:19.348729 1 availableupdates.go:58] Available updates were recently retrieved, with less than 3m39.457405047s elapsed since 2023-02-08T11:21:19Z, will try later.
I0208 11:21:19.348733 1 cvo.go:641] Finished syncing available updates "openshift-cluster-version/version" (19.623µs)
I0208 11:21:21.145379 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:23.900635 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:21:24.142072 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:27.149475 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:27.659593 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:21:30.143032 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:33.145433 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:36.141862 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:39.143589 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:42.145608 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:45.146553 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:48.143715 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:51.143346 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:53.900899 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:21:54.143962 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:57.142523 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:21:57.659074 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:22:00.143552 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:03.141779 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:06.143916 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:09.143538 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:12.145290 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:15.145646 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:18.144013 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:21.146642 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:23.900502 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:22:24.143027 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:27.141960 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:27.659377 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:22:30.145443 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:33.145499 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:36.143227 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:39.143717 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:42.144505 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:45.148490 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:48.143575 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:51.142014 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:53.901098 1 metrics.go:505] skipping metrics for etcd ClusterOperator condition RecentBackup=Unknown (neither True nor False)
I0208 11:22:54.143083 1 batch.go:29] Job version--fmbrq in namespace openshift-cluster-version is not ready, continuing to wait.
I0208 11:22:57.107405 1 sync_worker.go:437] loadUpdatedPayload syncPayload err=Unable to download and prepare the update: timed out waiting for the condition
2 minutes of waiting while the "Job is not ready", then we timeout. Timeout is expected, but I want to see more about the wait. I would expect the job to start executing but "hang" and be aborted. "not ready" sounds like it never starts. It is probably just messaging.
- Check out how exactly do we wait for the condition
I0208 11:22:57.107438 1 status.go:170] Synchronizing status errs=field.ErrorList(nil) status=&cvo.SyncWorkerStatus{Generation:3, Failure:error(nil), Done:6, Total:834, Completed:0, Reconciling:true, Initial:false, VersionHash:"xoIORUSMPyg=", Architecture:"amd64", LastProgress:time.Date(1, time.January, 1, 0, 0, 0, 0, time.UTC), Actual:v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)}, Verified:false, loadPayloadStatus:cvo.LoadPayloadStatus{Step:"RetrievePayload", Message:"Retrieving payload failed version=\"\" image=\"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca\" failure=Unable to download and prepare the update: timed out waiting for the condition", AcceptedRisks:"", Failure:(*payload.UpdateError)(0xc0029b4bd0), Update:v1.Update{Architecture:"", Version:"", Image:"registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca", Force:true}, Verified:false, Local:false, LastTransitionTime:time.Time{wall:0xc0f0ff644666afd1, ext:12868080850600, loc:(*time.Location)(0x2fe2900)}}, CapabilitiesStatus:cvo.CapabilityStatus{Status:v1.ClusterVersionCapabilitiesStatus{EnabledCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}, KnownCapabilities:[]v1.ClusterVersionCapability{"CSISnapshot", "Console", "Insights", "Storage", "baremetal", "marketplace", "openshift-samples"}}, ImplicitlyEnabledCaps:[]v1.ClusterVersionCapability(nil)}}
I0208 11:22:57.107522 1 status.go:90] merge into existing history completed=false desired=v1.Release{Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", URL:"", Channels:[]string(nil)} last=&v1.UpdateHistory{State:"Completed", StartedTime:time.Date(2023, time.February, 8, 7, 43, 58, 0, time.Local), CompletionTime:time.Date(2023, time.February, 8, 8, 43, 51, 0, time.Local), Version:"4.13.0-0.ci.test-2023-02-08-064507-ci-ln-vtrvh42-latest", Image:"registry.build05.ci.openshift.org/ci-ln-vtrvh42/release@sha256:220b151892fc485298631a08a5b712ddffecb157402ee1f39d63d928d735bf58", Verified:false, AcceptedRisks:""}
I0208 11:22:57.107743 1 event.go:285] Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Warning' reason: 'RetrievePayloadFailed' Retrieving payload failed version="" image="registry.build05.ci.openshift.org/ci-ln-dkrq3mk/release@sha256:0ce4ae5cb1eade573f95edae6c2cec05580f94609d02cd3bf85b450be0d362ca" failure=Unable to download and prepare the update: timed out waiting for the condition
I0208 11:22:57.107819 1 sync_worker.go:993] Running sync for role "openshift-marketplace/marketplace-operator" (648 of 834)
Again the suspicious delay, this time it is 4m, not 2m. This manifest was
reported by Evgeni to fail later. This delay is very suspicous because it
matches the timeout spent in RetrievePayload.
Above, we see:
> I0208 11:18:57.106115 1 sync_worker.go:1013] Done syncing for clusterrole "marketplace-operator" (647 of 834)
> I0208 11:18:57.106371 1 sync_worker.go:811] Detected while considering cluster version generation 4: version changed...)
So we finish one manifest, then run RetrievePayload, it takes 4m to execute,
and we do not start the next manifest until that. These 2/4m delays accumulate
and we eventually hit some kind of timeout that bounds the whole apply
operation.
I0208 11:22:57.107887 1 task_graph.go:474] Canceled worker 1 while waiting for work
I0208 11:22:57.107900 1 sync_worker.go:1013] Done syncing for configmap "openshift-apiserver-operator/trusted-ca-bundle" (444 of 834)
I0208 11:22:57.107911 1 task_graph.go:474] Canceled worker 0 while waiting for work
This looks like the possible failure culprit: the workers get canceled. Unfortunately the "Running sync/Done syncing" messages do not log which worker runs them, could be helpful.
I0208 11:22:57.107918 1 task_graph.go:523] Workers finished
I0208 11:22:57.107925 1 task_graph.go:546] Result of work: [update context deadline exceeded at 8 of 834 Could not update role "openshift-marketplace/marketplace-operator" (648 of 834)]
I0208 11:22:57.107938 1 sync_worker.go:1169] Summarizing 1 errors
I0208 11:22:57.107947 1 sync_worker.go:1173] Update error 648 of 834: UpdatePayloadFailed Could not update role "openshift-marketplace/marketplace-operator" (648 of 834) (context.deadlineExceededError: context deadline exceeded)
E0208 11:22:57.107966 1 sync_worker.go:654] unable to synchronize image (waiting 3m39.457405047s): Could not update role "openshift-marketplace/marketplace-operator" (648 of 834)
Here's the error.