Bug 1880285

Summary: Cluster Version Operator should have a tool to explain the logs
Product: OpenShift Container Platform Reporter: Vadim Rutkovsky <vrutkovs>
Component: Cluster Version OperatorAssignee: Over the Air Updates <aos-team-ota>
Status: CLOSED ERRATA QA Contact: Johnny Liu <jialiu>
Severity: low Docs Contact:
Priority: unspecified    
Version: 4.6CC: aos-bugs, jokerman, wking, yanyang
Target Milestone: ---   
Target Release: 4.6.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-10-27 16:42:20 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Vadim Rutkovsky 2020-09-18 08:06:28 UTC
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

Comment 2 W. Trevor King 2020-09-18 23:29:41 UTC
This is an internal tool, not something we ship as part of the product.  No need for QE or docs.

Comment 3 Johnny Liu 2020-09-21 02:55:36 UTC
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

Comment 6 errata-xmlrpc 2020-10-27 16:42:20 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 (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