Description of problem: Cluster Version Operator log is verbose, so its hard to find necessary details. The repo should have a tool which helps engineers parse the important details about reconciliation cycle
This is an internal tool, not something we ship as part of the product. No need for QE or docs.
Download https://raw.githubusercontent.com/openshift/cluster-version-operator/master/hack/log-explainer.py, it is working well. $ oc -n openshift-cluster-version logs cluster-version-operator-fcdcdbd97-rc7sh > cvo.log $ wget https://raw.githubusercontent.com/openshift/cluster-version-operator/master/hack/log-explainer.py $ chmod +x log-explainer.py $ cat cvo.log | ./log-explainer.py WARNING:root:not finished: clusteroperator kube-scheduler $ w3m ./index.html Cluster-version operator log version ClusterVersionOperator 4.6.0-202008261930.p0-2114f13 start_time 2020-09-21 02:30:45.065723 stop_time 2020-09-21 02:43:29.596346 threads 1 Leader election Leader lease acquired in 0:00:01.117203. 2020-09-21 02:30:46.122378 leaderelection.go attempting to acquire leader lease openshift-cluster-version/version... 2020-09-21 02:30:46.182926 leaderelection.go successfully acquired lease openshift-cluster-version/version Peripheral goroutines available updates sync Goroutine beings logging 0:00:01.218365 after the initial container log entry and is last seen 0:00:42.450075 before the final container log entry. cluster version sync Goroutine beings logging 0:00:01.218538 after the initial container log entry and is last seen 0:00:12.465111 before the final container log entry. metrics Goroutine beings logging 0:00:01.058175 after the initial container log entry and is last seen 0:12:43.472399 before the final container log entry. upgradeable Goroutine beings logging 0:00:01.218365 after the initial container log entry and is last seen 0:00:42.450112 before the final container log entry. Unclassified log lines 2020-09-21 02:30:45.083720 payload.go Loading updatepayload from "/" 2020-09-21 02:30:46.121593 cvo.go Verifying release authenticity: All release image digests must have GPG signatures from verifier-public-key-redhat (567E347AD0044ADE55BA8A5F199E2F91FD431D51: Red Hat, Inc. (release key 2) , B08B659EE86AF623BC90E8DB938A80CAF21541EB: Red Hat, Inc. (beta key 2) ) - will check for signatures in containers/image format at serial signature store wrapping config maps in openshift-config-managed with label "release.openshift.io/verification-signatures", parallel signature store wrapping containers/image signature store under https://storage.googleapis.com/openshift-release/official/signatures/openshift/release, containers/image signature store under https://mirror.openshift.com/pub/openshift-v4/signatures/openshift/release 2020-09-21 02:30:46.122246 start.go Waiting on 2 outstanding goroutines. 2020-09-21 02:30:46.184190 event.go Event(v1.ObjectReference{Kind:"ConfigMap", Namespace:"openshift-cluster-version", Name:"version", UID:"8fcbcbe6-2bda-4fba-84f2-263738cca7ec", APIVersion:"v1", ResourceVersion:"3357894", FieldPath:""}): type: 'Normal' reason: 'LeaderElection' jialiubug-lw86v-master-2.c.openshift-qe.internal_dfcfe9b8-b8bb-4c8c-b4bb-835e0bb5b4d0 became leader 2020-09-21 02:30:46.284717 payload.go Loading updatepayload from "/" 2020-09-21 02:30:46.286002 event.go Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'RetrievePayload' retrieving payload version="" image="quay.io/openshift-release-dev/ocp-release@sha256:960ec73733150827076cbb5fa2c1f5aaa9a94bfbce1b4897e46432a56ac976c1" 2020-09-21 02:30:46.286334 event.go Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'VerifyPayload' verifying payload version="" image="quay.io/openshift-release-dev/ocp-release@sha256:960ec73733150827076cbb5fa2c1f5aaa9a94bfbce1b4897e46432a56ac976c1" 2020-09-21 02:30:46.907383 event.go Event(v1.ObjectReference{Kind:"ClusterVersion", Namespace:"openshift-cluster-version", Name:"version", UID:"", APIVersion:"config.openshift.io/v1", ResourceVersion:"", FieldPath:""}): type: 'Normal' reason: 'PayloadLoaded' payload loaded version="4.6.0-fc.4" image="quay.io/openshift-release-dev/ocp-release@sha256:960ec73733150827076cbb5fa2c1f5aaa9a94bfbce1b4897e46432a56ac976c1" 2020-09-21 02:30:47.223760 cvo.go Cluster version changed, waiting for newer event 2020-09-21 02:30:48.412055 request.go Throttling request took 1.037639448s, request: GET:https://api-int.jialiubug.qe.gcp.devcluster.openshift.com:6443/apis/storage.k8s.io/v1beta1?timeout=32s 2020-09-21 02:32:47.260697 request.go Throttling request took 1.04461286s, request: GET:https://api-int.jialiubug.qe.gcp.devcluster.openshift.com:6443/apis/imageregistry.operator.openshift.io/v1?timeout=32s 2020-09-21 02:36:51.806825 request.go Throttling request took 1.030985892s, request: GET:https://api-int.jialiubug.qe.gcp.devcluster.openshift.com:6443/apis/discovery.k8s.io/v1beta1?timeout=32s 2020-09-21 02:40:42.306727 apiext.go Updating CRD kubecontrollermanagers.operator.openshift.io 2020-09-21 02:40:43.372760 request.go Throttling request took 1.028491458s, request: GET:https://api-int.jialiubug.qe.gcp.devcluster.openshift.com:6443/apis/monitoring.coreos.com/v1?timeout=32s 2020-09-21 02:43:21.337309 request.go Throttling request took 1.018648784s, request: GET:https://api-int.jialiubug.qe.gcp.devcluster.openshift.com:6443/apis/operator.openshift.io/v1?timeout=32s Sync cycles quay.io/openshift-release-dev/ocp-release@sha256:960ec73733150827076cbb5fa2c1f5aaa9a94bfbce1b4897e46432a56ac976c1 Updating (force=false) Attempt 0 failure: 2020-09-21 02:30:46.284605 - 2020-09-21 02:36:28.198451 lines 339 result [Cluster operator kube-apiserver is still updating] manifests attempted 93 Failed manifests: 2020-09-21 02:36:28.197958 error running apply for clusteroperator "kube-apiserver" (93 of 602): Cluster operator kube-apiserver is still updating Attempt 1 failure: 2020-09-21 02:36:50.502395 - 2020-09-21 02:42:32.419551 lines 377 result [Cluster operator kube-controller-manager is still updating Cluster operator kube-scheduler is still updating] manifests attempted 111 Failed manifests: 2020-09-21 02:42:32.417395 error running apply for clusteroperator "kube-controller-manager" (102 of 602): Cluster operator kube-controller-manager is still updating 2020-09-21 02:42:32.417420 error running apply for clusteroperator "kube-scheduler" (111 of 602): Cluster operator kube-scheduler is still updating Attempt 2 success: 2020-09-21 02:43:19.784377 - 2020-09-21 02:43:20.216393 lines 355 result [] manifests attempted 111
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 (OpenShift Container Platform 4.6 GA Images), and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2020:4196