Bug 1885249

Summary: openshift-state-metrics: Logging is broken due to mix of k8s.io/klog v1 and v2
Product: OpenShift Container Platform Reporter: Sergiusz Urbaniak <surbania>
Component: MonitoringAssignee: Pawel Krupa <pkrupa>
Status: CLOSED ERRATA QA Contact: Junqi Zhao <juzhao>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 4.6CC: alegrand, anpicker, erooth, kakkoyun, lcosic, pkrupa, surbania, wking
Target Milestone: ---   
Target Release: 4.7.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-02-24 15:23:10 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 Sergiusz Urbaniak 2020-10-05 13:46:18 UTC 
This bug was initially created as a copy of Bug #1883461

I am copying this bug because: 



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).
Comment 1 W. Trevor King 2020-10-07 18:15:48 UTC 
Back to assigned, because [1] is reverting to unstick bug 1886111.

[1]: https://github.com/openshift/openshift-state-metrics/pull/61
Comment 4 Junqi Zhao 2020-10-13 10:43:40 UTC 
tested with 4.7.0-0.ci-2020-10-12-222453， use a non-exist config file,we can see klog/v2 in the log, but there still mix of k8s.io/klog v1 and v2, see from "goroutine 17 [chan receive]" and "goroutine 7 [chan receive]" part 


sh-4.4$ openshift-state-metrics --kubeconfig=asfd --v=4  
I1013 10:40:56.632853      40 main.go:66] Using default collectors
I1013 10:40:56.632928      40 main.go:73] Using all namespace
I1013 10:40:56.632941      40 main.go:89] metric white- blacklisting: blacklisting the following items: 
F1013 10:40:56.633121      40 build_config.go:111] cannot create buildconfig client: stat asfd: no such file or directory
goroutine 1 [running]:
k8s.io/klog/v2.stacks(0xc000010001, 0xc0001ea460, 0x7a, 0x98)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:996 +0xb9
k8s.io/klog/v2.(*loggingT).output(0x216aae0, 0xc000000003, 0x0, 0x0, 0xc0004ab500, 0x20c73d7, 0xf, 0x6f, 0x0)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:945 +0x191
k8s.io/klog/v2.(*loggingT).printf(0x216aae0, 0x3, 0x0, 0x0, 0x169fcd5, 0x24, 0xc00029baa0, 0x1, 0x1)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:733 +0x17a
k8s.io/klog/v2.Fatalf(...)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:1463
github.com/openshift/openshift-state-metrics/pkg/collectors.createBuildConfigListWatch(0x0, 0x0, 0x7ffc69c0c339, 0x4, 0x0, 0x0, 0x40e198, 0x30, 0x15d25a0)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/build_config.go:111 +0xe8
github.com/openshift/openshift-state-metrics/pkg/collectors.reflectorPerNamespace(0x185d820, 0xc000046040, 0x1652f60, 0xc0000ee580, 0x186db40, 0xc0000c4c40, 0x0, 0x0, 0x7ffc69c0c339, 0x4, ...)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:227 +0xda
github.com/openshift/openshift-state-metrics/pkg/collectors.(*Builder).buildBuildConfigCollector(0xc0004ab490, 0x8030102)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:161 +0x25c
github.com/openshift/openshift-state-metrics/pkg/collectors.glob..func13(0xc0004ab490, 0xc0004c6a80)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:112 +0x2b
github.com/openshift/openshift-state-metrics/pkg/collectors.(*Builder).Build(0xc0004ab490, 0x1737690, 0x1826840, 0xc0004ac730)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:99 +0x12c
main.main()
	/go/src/github.com/openshift/openshift-state-metrics/main.go:106 +0x7a9

goroutine 17 [chan receive]:
k8s.io/klog.(*loggingT).flushDaemon(0x216aa00)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/klog.go:1010 +0x8b
created by k8s.io/klog.init.0
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/klog.go:411 +0xd8

goroutine 7 [chan receive]:
k8s.io/klog/v2.(*loggingT).flushDaemon(0x216aae0)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:1131 +0x8b
created by k8s.io/klog/v2.init.0
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:416 +0xd8

goroutine 19 [runnable]:
bytes.(*Buffer).grow(0xc000126c40, 0x1e, 0x216a600)
	/usr/lib/golang/src/bytes/buffer.go:128 +0x238
bytes.(*Buffer).Write(0xc000126c40, 0xc000126c68, 0x1e, 0x40, 0x20, 0x38, 0xd)
	/usr/lib/golang/src/bytes/buffer.go:172 +0xd0
k8s.io/klog/v2.(*loggingT).formatHeader(0x216aae0, 0x0, 0x20c7151, 0x7, 0x72, 0x1)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:639 +0x48c
k8s.io/klog/v2.(*loggingT).header(0x216aae0, 0xc000000000, 0x0, 0x0, 0xc000000180, 0x4, 0xc00005b6a0)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:603 +0x95
k8s.io/klog/v2.(*loggingT).printf(0x216aae0, 0x0, 0x0, 0x0, 0x16c69ac, 0x38, 0xc0000a4f40, 0x1, 0x1)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:722 +0x46
k8s.io/klog/v2.Infof(...)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:1363
main.telemetryServer(0x1826840, 0xc0004ac730, 0x167af22, 0x7, 0x51)
	/go/src/github.com/openshift/openshift-state-metrics/main.go:114 +0x1a6
created by main.main
	/go/src/github.com/openshift/openshift-state-metrics/main.go:104 +0x79b
Comment 6 Junqi Zhao 2020-10-22 01:16:12 UTC 
tested with 4.7.0-0.nightly-2020-10-21-001511, issue is fixed, no mix of k8s.io/klog v1 and v2
# oc -n openshift-monitoring rsh -c openshift-state-metrics openshift-state-metrics-cb67d9588-jj8mz
sh-4.4$ openshift-state-metrics --kubeconfig=asfd --v=4 
I1022 01:12:21.254486      18 main.go:66] Using default collectors
I1022 01:12:21.254544      18 main.go:73] Using all namespace
I1022 01:12:21.254554      18 main.go:89] metric white- blacklisting: blacklisting the following items: 
F1022 01:12:21.255734      18 build_config.go:111] cannot create buildconfig client: stat asfd: no such file or directory
goroutine 1 [running]:
k8s.io/klog/v2.stacks(0xc0000ae001, 0xc0001e80a0, 0x7a, 0x98)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:996 +0xb9
k8s.io/klog/v2.(*loggingT).output(0x21bd240, 0xc000000003, 0x0, 0x0, 0xc0001e2310, 0x2119157, 0xf, 0x6f, 0x0)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:945 +0x191
k8s.io/klog/v2.(*loggingT).printf(0x21bd240, 0x3, 0x0, 0x0, 0x16c9168, 0x24, 0xc000069aa0, 0x1, 0x1)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:733 +0x17a
k8s.io/klog/v2.Fatalf(...)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:1463
github.com/openshift/openshift-state-metrics/pkg/collectors.createBuildConfigListWatch(0x0, 0x0, 0x7fffb2703204, 0x4, 0x0, 0x0, 0x40e198, 0x30, 0x15f6400)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/build_config.go:111 +0xe8
github.com/openshift/openshift-state-metrics/pkg/collectors.reflectorPerNamespace(0x188d140, 0xc0000aa018, 0x167a480, 0xc00048ab00, 0x189d720, 0xc000498380, 0x0, 0x0, 0x7fffb2703204, 0x4, ...)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:227 +0xda
github.com/openshift/openshift-state-metrics/pkg/collectors.(*Builder).buildBuildConfigCollector(0xc0001e22a0, 0x8030104)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:161 +0x25c
github.com/openshift/openshift-state-metrics/pkg/collectors.glob..func13(0xc0001e22a0, 0xc0001d8cf0)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:112 +0x2b
github.com/openshift/openshift-state-metrics/pkg/collectors.(*Builder).Build(0xc0001e22a0, 0x1766298, 0x18547a0, 0xc00007aa00)
	/go/src/github.com/openshift/openshift-state-metrics/pkg/collectors/builder.go:99 +0x12c
main.main()
	/go/src/github.com/openshift/openshift-state-metrics/main.go:106 +0x7a9

goroutine 20 [chan receive]:
k8s.io/klog/v2.(*loggingT).flushDaemon(0x21bd240)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:1131 +0x8b
created by k8s.io/klog/v2.init.0
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:416 +0xd8

goroutine 25 [semacquire]:
sync.runtime_SemacquireMutex(0x21bd25c, 0x0, 0x1)
	/usr/lib/golang/src/runtime/sema.go:71 +0x47
sync.(*Mutex).lockSlow(0x21bd258)
	/usr/lib/golang/src/sync/mutex.go:138 +0x105
sync.(*Mutex).Lock(...)
	/usr/lib/golang/src/sync/mutex.go:81
k8s.io/klog/v2.(*loggingT).output(0x21bd240, 0xc000000000, 0x0, 0x0, 0xc000491c70, 0x2118ed1, 0x7, 0x72, 0x0)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:882 +0x811
k8s.io/klog/v2.(*loggingT).printf(0x21bd240, 0x0, 0x0, 0x0, 0x16efdb4, 0x38, 0xc000094f40, 0x1, 0x1)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:733 +0x17a
k8s.io/klog/v2.Infof(...)
	/go/src/github.com/openshift/openshift-state-metrics/vendor/k8s.io/klog/v2/klog.go:1363
main.telemetryServer(0x18547a0, 0xc00007aa00, 0x16a4174, 0x7, 0x51)
	/go/src/github.com/openshift/openshift-state-metrics/main.go:114 +0x1a6
created by main.main
	/go/src/github.com/openshift/openshift-state-metrics/main.go:104 +0x79b
Comment 10 errata-xmlrpc 2021-02-24 15:23:10 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 (Moderate: OpenShift Container Platform 4.7.0 security, bug fix, and enhancement 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/RHSA-2020:5633