Bug 1884028

Summary:	Logging is broken due to mix of k8s.io/klog v1 and v2
Product:	OpenShift Container Platform	Reporter:	Adam Kaplan <adam.kaplan>
Component:	openshift-controller-manager	Assignee:	Corey Daley <cdaley>
Status:	CLOSED ERRATA	QA Contact:	wewang <wewang>
Severity:	high	Docs Contact:
Priority:	high
Version:	4.6	CC:	aos-bugs, jhadvig, jokerman, mfojtik, sttts, yapei
Target Milestone:	---
Target Release:	4.6.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:	devex
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:	1883461	Environment:
Last Closed:	2020-10-27 16:47:06 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:

Description Adam Kaplan 2020-09-30 19:48:19 UTC

+++ This bug was initially created as a clone of Bug #1883461 +++

k8s.io/klog moved to v2 in client-go and frieds. The operator does not use v2 yet and hence, we lose one half of the logging output (v2).

--- Additional comment from Stefan Schimanski on 2020-09-29 11:09:06 UTC ---

I did some tests using openshift-apiserver that uses kube component-base to add klog command line flags:

$ ./openshift-apiserver start --config asfd --v=4
I0929 13:04:18.354425   53628 cmd.go:57] v1 klog
I0929 13:04:18.354506   53628 cmd.go:58] v2 klog
I0929 13:04:18.354512   53628 cmd.go:61] v2 V(2) klog
I0929 13:04:18.354515   53628 cmd.go:64] v2 V(4) klog

So this means that we DO NOT set verbosity for v1 klog, and hence lose all the klogv1.V(2).Infof output.

Comment 1 Adam Kaplan 2020-09-30 19:50:02 UTC

Affects both openshift-controller-manager and cluster-openshift-controller-manager-operator

Comment 4 wewang 2020-10-10 02:38:28 UTC

Now ocm-o and ocm are using v2 klog, so verified it.
Version: 
4.6.0-0.nightly-2020-10-09-153352


Steps:
1. openhsift controller manager operator log
sh-4.4# /usr/bin/cluster-openshift-controller-manager-operator operator --config ask --v=4
F1010 02:34:32.669180      52 cmd.go:129] open ask: no such file or directory
goroutine 1 [running]:
k8s.io/klog/v2.stacks(0xc00012c001, 0xc000600160, 0x4e, 0xa3)
	k8s.io/klog/v2.0/klog.go:996 +0xb9
k8s.io/klog/v2.(*loggingT).output(0x3434f40, 0xc000000003, 0x0, 0x0, 0xc0001c48c0, 0x3365473, 0x6, 0x81, 0x1fc6100)
	k8s.io/klog/v2.0/klog.go:945 +0x191
k8s.io/klog/v2.(*loggingT).printDepth(0x3434f40, 0x3, 0x0, 0x0, 0x1, 0xc000885c38, 0x1, 0x1)
	k8s.io/klog/v2.0/klog.go:718 +0x165
k8s.io/klog/v2.(*loggingT).print(...)
	k8s.io/klog/v2.0/klog.go:703
k8s.io/klog/v2.Fatal(...)
	k8s.io/klog/v2.0/klog.go:1443
github.com/openshift/library-go/pkg/controller/controllercmd.(*ControllerCommandConfig).NewCommandWithContext.func1(0xc00025c2c0, 0xc000035d10, 0x0, 0x3)
	github.com/openshift/library-go.0-20200915114203-ee518dab897a/pkg/controller/controllercmd/cmd.go:129 +0x6fe
github.com/spf13/cobra.(*Command).execute(0xc00025c2c0, 0xc000035ce0, 0x3, 0x3, 0xc00025c2c0, 0xc000035ce0)
	github.com/spf13/cobra.0/command.go:846 +0x2c2
github.com/spf13/cobra.(*Command).ExecuteC(0xc00025c000, 0xc00012e120, 0x3434980, 0x0)
	github.com/spf13/cobra.0/command.go:950 +0x375
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra.0/command.go:887
main.main()
	github.com/openshift/cluster-openshift-controller-manager-operator/cmd/cluster-openshift-controller-manager-operator/main.go:29 +0x155

goroutine 35 [chan receive]:
k8s.io/klog/v2.(*loggingT).flushDaemon(0x3434f40)
	k8s.io/klog/v2.0/klog.go:1131 +0x8b
created by k8s.io/klog/v2.init.0
	k8s.io/klog/v2.0/klog.go:416 +0xd8


2. openshift controller manager log
sh-4.4$ /usr/bin/openshift-controller-manager start --config ask --v=4
F1010 02:27:18.693641      32 cmd.go:59] open ask: no such file or directory
goroutine 1 [running]:
k8s.io/klog/v2.stacks(0xc000134001, 0xc000534160, 0x4d, 0xa3)
	k8s.io/klog/v2.0/klog.go:996 +0xb9
k8s.io/klog/v2.(*loggingT).output(0x38e7320, 0xc000000003, 0x0, 0x0, 0xc000b2a150, 0x35f8e1b, 0x6, 0x3b, 0x185b700)
	k8s.io/klog/v2.0/klog.go:945 +0x191
k8s.io/klog/v2.(*loggingT).printDepth(0x38e7320, 0xc000000003, 0x0, 0x0, 0x1, 0xc000c9fb90, 0x1, 0x1)
	k8s.io/klog/v2.0/klog.go:718 +0x165
k8s.io/klog/v2.(*loggingT).print(...)
	k8s.io/klog/v2.0/klog.go:703
k8s.io/klog/v2.Fatal(...)
	k8s.io/klog/v2.0/klog.go:1436
github.com/openshift/openshift-controller-manager/pkg/cmd/openshift-controller-manager.NewOpenShiftControllerManagerCommand.func1(0xc000256580, 0xc000b84720, 0x0, 0x3)
	github.com/openshift/openshift-controller-manager/pkg/cmd/openshift-controller-manager/cmd.go:59 +0x40b
github.com/spf13/cobra.(*Command).execute(0xc000256580, 0xc000b846f0, 0x3, 0x3, 0xc000256580, 0xc000b846f0)
	github.com/spf13/cobra.0/command.go:846 +0x2c2
github.com/spf13/cobra.(*Command).ExecuteC(0xc0002562c0, 0xc0002562c0, 0x0, 0x0)
	github.com/spf13/cobra.0/command.go:950 +0x375
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra.0/command.go:887
main.main()
	github.com/openshift/openshift-controller-manager/cmd/openshift-controller-manager/main.go:65 +0x2f3

goroutine 19 [chan receive]:
k8s.io/klog/v2.(*loggingT).flushDaemon(0x38e7320)
	k8s.io/klog/v2.0/klog.go:1131 +0x8b
created by k8s.io/klog/v2.init.0
	k8s.io/klog/v2.0/klog.go:416 +0xd8

Comment 6 errata-xmlrpc 2020-10-27 16:47:06 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