Bug 1940652
| Summary: | Bump logging to level 5 | ||
|---|---|---|---|
| Product: | OpenShift Container Platform | Reporter: | Jack Ottofaro <jack.ottofaro> |
| Component: | Cluster Version Operator | Assignee: | Jack Ottofaro <jack.ottofaro> |
| Status: | CLOSED ERRATA | QA Contact: | Yang Yang <yanyang> |
| Severity: | medium | Docs Contact: | |
| Priority: | medium | ||
| Version: | 4.5 | CC: | aos-bugs, jialiu, jokerman, lmohanty, wking, yanyang |
| Target Milestone: | --- | ||
| Target Release: | 4.5.z | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | 1873900 | Environment: | |
| Last Closed: | 2021-04-28 14:23:53 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: | 1873900 | ||
| Bug Blocks: | |||
|
Description
Jack Ottofaro
2021-03-18 19:23:14 UTC
Hi Jack, I'm going to verify it. Could you please hint me how can I trigger the trace level log? Thanks. v5 should give you access to:
$ git --no-pager grep 'klog.V.5' origin/release-4.5 -- pkg/cvo
origin/release-4.5:pkg/cvo/cvo_test.go: klog.V(5).Infof("updated object to %#v", obj)
origin/release-4.5:pkg/cvo/status.go: klog.V(5).Infof("initialize new history completed=%t desired=%#v", completed, desired)
origin/release-4.5:pkg/cvo/status.go: klog.V(5).Infof("merge into existing history completed=%t desired=%#v last=%#v", completed, desired, last)
origin/release-4.5:pkg/cvo/status.go: klog.V(5).Infof("must add a new history entry completed=%t desired=%#v != last=%#v", completed, desired, last)
origin/release-4.5:pkg/cvo/status.go: if klog.V(5) && len(config.Status.History) > 1 {
origin/release-4.5:pkg/cvo/status.go: klog.V(5).Infof("Synchronizing errs=%#v status=%#v", validationErrs, status)
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Starting sync worker")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Stopped worker")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Wait finished")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Work updated")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("No change, waiting")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("No work, waiting")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Previous sync status: %#v", reporter.previousStatus)
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Sync succeeded, reconciling")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Worker shut down")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Dropping status report from earlier in sync loop")
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Status change %#v", update)
origin/release-4.5:pkg/cvo/sync_worker.go: if klog.V(5) {
origin/release-4.5:pkg/cvo/sync_worker.go: klog.V(5).Infof("Manifest: %s", string(task.Manifest.Raw))
For example, 4.5.37 CI doesn't have 'merge into existing history':
$ curl -s https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/release-openshift-origin-installer-launch-aws/1377215339498049536/artifacts/launch/pods/openshift-cluster-version_cluster-version-operator-8dc8b5fc4-fxhnt_cluster-version-operator.log | grep 'merge into existing history'
While recent 4.5 nightlies do:
$ curl -s https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/periodic-ci-openshift-release-master-nightly-4.5-e2e-aws/1377872648524009472/artifacts/e2e-aws/gather-extra/artifacts/pods/openshift-cluster-version_cluster-version-operator-744cf5c97f-fkd2r_cluster-version-operator.log | grep 'merge into existing history' | head -n1
I0402 07:15:39.344456 1 status.go:79] merge into existing history completed=false desired=v1.Update{Version:"4.5.0-0.nightly-2021-04-02-061143", Image:"registry.build02.ci.openshift.org/ci-op-jdcvygb3/release@sha256:573aec4324c3013f6305b807b3e383dfda96f503d70386221f58966483b6a00d", Force:false} last=&v1.UpdateHistory{State:"Partial", StartedTime:v1.Time{Time:time.Time{wall:0x0, ext:63752942657, loc:(*time.Location)(0x271c5c0)}}, CompletionTime:(*v1.Time)(nil), Version:"4.5.0-0.nightly-2021-04-02-061143", Image:"registry.build02.ci.openshift.org/ci-op-jdcvygb3/release@sha256:573aec4324c3013f6305b807b3e383dfda96f503d70386221f58966483b6a00d", Verified:false}
Trevor, I appreciate your help.
For a fresh installed cluster with 4.5.0-0.nightly-2021-04-02-061143, we can see many v5 logs "merge into existing history" in the cvo pod log:
# cat 1.log |grep "merge into existing history"
I0404 08:40:17.040642 1 status.go:79] merge into existing history completed=true desired=v1.Update{Version:"4.5.0-0.nightly-2021-04-02-061143", Image:"registry.ci.openshift.org/ocp/release@sha256:573aec4324c3013f6305b807b3e383dfda96f503d70386221f58966483b6a00d", Force:false} last=&v1.UpdateHistory{State:"Completed", StartedTime:v1.Time{Time:time.Time{wall:0x0, ext:63753119866, loc:(*time.Location)(0x271c5c0)}}, CompletionTime:(*v1.Time)(0xc000aa15e0), Version:"4.5.0-0.nightly-2021-04-02-061143", Image:"registry.ci.openshift.org/ocp/release@sha256:573aec4324c3013f6305b807b3e383dfda96f503d70386221f58966483b6a00d", Verified:false}
While a 4.5.36 cluster does not have that log:
# cat 2.log | grep "merge into existing history completed"
Moving it to verified.
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.5.38 bug fix update), 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-2021:1300 |