Bugzilla (bugzilla.redhat.com) will be under maintenance for infrastructure upgrades and will not be available on July 31st between 12:30 AM - 05:30 AM UTC. We appreciate your understanding and patience. You can follow status.redhat.com for details.
Bug 1880285 - Cluster Version Operator should have a tool to explain the logs
Summary: Cluster Version Operator should have a tool to explain the logs
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Cluster Version Operator
Version: 4.6
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ---
: 4.6.0
Assignee: aos-team-ota
QA Contact: Johnny Liu
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-09-18 08:06 UTC by Vadim Rutkovsky
Modified: 2020-10-27 16:42 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: No Doc Update
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-10-27 16:42:20 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github openshift cluster-version-operator pull 452 0 None closed Bug 1880285: hack/log-explainer: Render CVO logs for easier analysis 2020-11-27 13:02:21 UTC
Red Hat Product Errata RHBA-2020:4196 0 None None None 2020-10-27 16:42:45 UTC

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


Note You need to log in before you can comment on or make changes to this bug.