Bug 1867518
| Summary: | [oc] oc should not print so many goroutines when ANY command fails | ||
|---|---|---|---|
| Product: | OpenShift Container Platform | Reporter: | RamaKasturi <knarra> |
| Component: | oc | Assignee: | Maciej Szulik <maszulik> |
| Status: | CLOSED ERRATA | QA Contact: | RamaKasturi <knarra> |
| Severity: | medium | Docs Contact: | |
| Priority: | low | ||
| Version: | 4.6 | CC: | aos-bugs, jiazha, jokerman, mfojtik, xxia |
| Target Milestone: | --- | Keywords: | Reopened |
| Target Release: | 4.7.0 | Flags: | mfojtik:
needinfo?
|
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | LifecycleReset | ||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: |
Cause:
Recent changes in logging libraries which oc depends on go stack trace were being printed.
Consequence:
Using any loglevel caused stack traces being printed making any debugging harder.
Fix:
Increase level at which those stack traces are being printed.
Result:
Currently using loglevel 6 and above will only print those stack traces. Anything below 6 will not.
|
Story Points: | --- |
| Clone Of: | Environment: | ||
| Last Closed: | 2021-02-24 15:15:27 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
RamaKasturi
2020-08-10 09:20:57 UTC
Making field urgent because blocking me to debug some oc command failure with `--v` for some testings. This is happening b/c your requested verbosity level is higher than 2, so this is not a bug. Also tried running the command below where there is no verbosity mentioned and i do see go routine crash for this as well
[ramakasturinarra@dhcp35-60 ~]$ oc get events -n openshift-marketplace --sort-by='.lastTimestamp'
F0817 15:35:05.729608 20848 sorter.go:353] Field {.lastTimestamp} in [][][]reflect.Value is an unsortable type: interface, err: unsortable type: <nil>
goroutine 1 [running]:
k8s.io/klog/v2.stacks(0xc0000e4001, 0xc0003ee0f0, 0x99, 0xeb)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/v2/klog.go:996 +0xb8
k8s.io/klog/v2.(*loggingT).output(0x53a1020, 0xc000000003, 0x0, 0x0, 0xc00140e310, 0x4f07359, 0x9, 0x161, 0x0)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/v2/klog.go:945 +0x19d
k8s.io/klog/v2.(*loggingT).printf(0x53a1020, 0x3, 0x0, 0x0, 0x30215b7, 0x31, 0xc001c01550, 0x4, 0x4)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/v2/klog.go:733 +0x17a
k8s.io/klog/v2.Fatalf(...)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/v2/klog.go:1456
k8s.io/kubectl/pkg/cmd/get.(*TableSorter).Less(0xc00200ef90, 0x0, 0x36, 0x18e0e6f)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/kubectl/pkg/cmd/get/sorter.go:353 +0x2d7
sort.medianOfThree(0x366f6c0, 0xc00200ef90, 0x0, 0x36, 0x6c)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/sort/sort.go:76 +0x49
sort.doPivot(0x366f6c0, 0xc00200ef90, 0x0, 0x1b5, 0xc00200ca40, 0xc000afa0d0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/sort/sort.go:101 +0x5b1
sort.quickSort(0x366f6c0, 0xc00200ef90, 0x0, 0x1b5, 0x12)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/sort/sort.go:190 +0x9a
sort.Sort(0x366f6c0, 0xc00200ef90)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/sort/sort.go:218 +0x79
k8s.io/kubectl/pkg/cmd/get.(*TableSorter).Sort(...)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/kubectl/pkg/cmd/get/sorter.go:359
k8s.io/kubectl/pkg/cmd/get.(*SortingPrinter).PrintObj(0xc000ae9fb0, 0x362f180, 0xc000a67c20, 0x3601120, 0xc00033a180, 0x0, 0x1)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/kubectl/pkg/cmd/get/sorter.go:56 +0x208
k8s.io/kubectl/pkg/cmd/get.(*TablePrinter).PrintObj(0xc001c7be80, 0x362f2c0, 0xc0003d3088, 0x3601120, 0xc00033a180, 0xc0001cc6a0, 0xc000a527a8)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/kubectl/pkg/cmd/get/table_printer.go:41 +0x1ba
k8s.io/cli-runtime/pkg/printers.ResourcePrinterFunc.PrintObj(0xc0004fec80, 0x362f2c0, 0xc0003d3088, 0x3601120, 0xc00033a180, 0x0, 0x20)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/cli-runtime/pkg/printers/interface.go:31 +0x4e
k8s.io/kubectl/pkg/cmd/get.(*GetOptions).Run(0xc000a6e780, 0x36cd5c0, 0xc00136be90, 0xc0014d58c0, 0xc000600440, 0x1, 0x4, 0x0, 0x0)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/kubectl/pkg/cmd/get/get.go:579 +0x83a
k8s.io/kubectl/pkg/cmd/get.NewCmdGet.func1(0xc0014d58c0, 0xc000600440, 0x1, 0x4)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/kubectl/pkg/cmd/get/get.go:167 +0x12d
github.com/spf13/cobra.(*Command).execute(0xc0014d58c0, 0xc000600400, 0x4, 0x4, 0xc0014d58c0, 0xc000600400)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/github.com/spf13/cobra/command.go:846 +0x2aa
github.com/spf13/cobra.(*Command).ExecuteC(0xc0011ed8c0, 0x2, 0xc0011ed8c0, 0x2)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/github.com/spf13/cobra/command.go:950 +0x349
github.com/spf13/cobra.(*Command).Execute(...)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/github.com/spf13/cobra/command.go:887
main.main()
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/cmd/oc/oc.go:110 +0x853
goroutine 19 [chan receive]:
k8s.io/klog/v2.(*loggingT).flushDaemon(0x53a1020)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/v2/klog.go:1131 +0x8b
created by k8s.io/klog/v2.init.0
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/v2/klog.go:416 +0xd6
goroutine 5 [syscall]:
os/signal.signal_recv(0x0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/runtime/sigqueue.go:147 +0x9c
os/signal.loop()
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/os/signal/signal_unix.go:29 +0x41
goroutine 6 [chan receive]:
k8s.io/klog.(*loggingT).flushDaemon(0x53a0f40)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/klog.go:1010 +0x8b
created by k8s.io/klog.init.0
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/klog/klog.go:411 +0xd6
goroutine 40 [select]:
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x31a9090, 0x3603b80, 0xc000de7830, 0x1, 0xc0000f0300)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:167 +0x13f
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x31a9090, 0x12a05f200, 0x0, 0xc000a32401, 0xc0000f0300)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:133 +0xaa
k8s.io/apimachinery/pkg/util/wait.Until(...)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:90
k8s.io/apimachinery/pkg/util/wait.Forever(0x31a9090, 0x12a05f200)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:81 +0x4f
created by k8s.io/component-base/logs.InitLogs
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/k8s.io/component-base/logs/logs.go:58 +0x8a
goroutine 41 [select]:
io.(*pipe).Read(0xc0002dd8b0, 0xc00162d000, 0x1000, 0x1000, 0x2a454c0, 0x1, 0x2)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/io/pipe.go:50 +0xe7
io.(*PipeReader).Read(0xc0013012d8, 0xc00162d000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/io/pipe.go:127 +0x4c
bufio.(*Scanner).Scan(0xc0015d6400, 0x0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/bufio/scan.go:213 +0xa4
github.com/openshift/oc/pkg/cli/admin/mustgather.newPrefixWriter.func1(0xc0015d6400, 0x36055a0, 0xc0000e4008, 0x2fc665e, 0x17)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/pkg/cli/admin/mustgather/mustgather.go:393 +0x14d
created by github.com/openshift/oc/pkg/cli/admin/mustgather.newPrefixWriter
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/pkg/cli/admin/mustgather/mustgather.go:392 +0x1c1
goroutine 282 [IO wait]:
internal/poll.runtime_pollWait(0x7fa92094ddd8, 0x72, 0xffffffffffffffff)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc0011d5198, 0x72, 0x3300, 0x339b, 0xffffffffffffffff)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0011d5180, 0xc0016ac000, 0x339b, 0x339b, 0x0, 0x0, 0x0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/internal/poll/fd_unix.go:169 +0x1cf
net.(*netFD).Read(0xc0011d5180, 0xc0016ac000, 0x339b, 0x339b, 0x203000, 0x0, 0x2377)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc0000e5b58, 0xc0016ac000, 0x339b, 0x339b, 0x0, 0x0, 0x0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/net/net.go:184 +0x68
crypto/tls.(*atLeastReader).Read(0xc00020eb40, 0xc0016ac000, 0x339b, 0x339b, 0x16cc, 0x35ffdc0, 0xc000df5920)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/crypto/tls/conn.go:780 +0x60
bytes.(*Buffer).ReadFrom(0xc001676258, 0x35ffb20, 0xc00020eb40, 0x41c475, 0x2b91760, 0x2eb4460)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/bytes/buffer.go:204 +0xb4
crypto/tls.(*Conn).readFromUntil(0xc001676000, 0x36050c0, 0xc0000e5b58, 0x5, 0xc0000e5b58, 0x9d5)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/crypto/tls/conn.go:802 +0xec
crypto/tls.(*Conn).readRecordOrCCS(0xc001676000, 0x0, 0x0, 0xc00020ea60)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/crypto/tls/conn.go:609 +0x124
crypto/tls.(*Conn).readRecord(...)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/crypto/tls/conn.go:577
crypto/tls.(*Conn).Read(0xc001676000, 0xc001692000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/crypto/tls/conn.go:1255 +0x161
bufio.(*Reader).Read(0xc0009aa6c0, 0xc000166e38, 0x9, 0x9, 0xc000df5cc0, 0x0, 0x9964d5)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/bufio/bufio.go:226 +0x26a
io.ReadAtLeast(0x35ff8c0, 0xc0009aa6c0, 0xc000166e38, 0x9, 0x9, 0x9, 0xc0000ca050, 0x0, 0x35ffdc0)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/io/io.go:310 +0x87
io.ReadFull(...)
/opt/rh/go-toolset-1.13/root/usr/lib/go-toolset-1.13-golang/src/io/io.go:329
golang.org/x/net/http2.readFrameHeader(0xc000166e38, 0x9, 0x9, 0x35ff8c0, 0xc0009aa6c0, 0x0, 0x0, 0xc0011a87b0, 0x0)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/golang.org/x/net/http2/frame.go:237 +0x87
golang.org/x/net/http2.(*Framer).ReadFrame(0xc000166e00, 0xc0011a87b0, 0x0, 0x0, 0x0)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/golang.org/x/net/http2/frame.go:492 +0xa1
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc000df5fb8, 0x0, 0x0)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/golang.org/x/net/http2/transport.go:1794 +0xbe
golang.org/x/net/http2.(*ClientConn).readLoop(0xc00114e900)
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/golang.org/x/net/http2/transport.go:1716 +0xa3
created by golang.org/x/net/http2.(*Transport).newClientConn
/builddir/build/BUILD/openshift-clients-git-3707.b058f59/__gopath/src/github.com/openshift/oc/vendor/golang.org/x/net/http2/transport.go:695 +0x62f
I’m adding UpcomingSprint, because I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint. Both of these problems require upstream approval, stacktraces is https://github.com/kubernetes/kubernetes/pull/94663 sorting empty fields https://github.com/kubernetes/kubernetes/pull/94666 With that I'm moving this to 4.7 I’m adding UpcomingSprint, because I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint. This bug hasn't had any activity in the last 30 days. Maybe the problem got resolved, was a duplicate of something else, or became less pressing for some reason - or maybe it's still relevant but just hasn't been looked at yet. As such, we're marking this bug as "LifecycleStale" and decreasing the severity/priority. If you have further information on the current state of the bug, please update it, otherwise this bug can be closed in about 7 days. The information can be, for example, that the problem still occurs, that you still want the feature, that more information is needed, or that the bug is (for whatever reason) no longer relevant. Additionally, you can add LifecycleFrozen into Keywords if you think this bug should never be marked as stale. Please consult with bug assignee before you do that. Removing LifecycleState as the issue is still reproducible. I’m adding UpcomingSprint, because I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint. This bug hasn't had any activity in the last 30 days. Maybe the problem got resolved, was a duplicate of something else, or became less pressing for some reason - or maybe it's still relevant but just hasn't been looked at yet. As such, we're marking this bug as "LifecycleStale" and decreasing the severity/priority. If you have further information on the current state of the bug, please update it, otherwise this bug can be closed in about 7 days. The information can be, for example, that the problem still occurs, that you still want the feature, that more information is needed, or that the bug is (for whatever reason) no longer relevant. Additionally, you can add LifecycleFrozen into Keywords if you think this bug should never be marked as stale. Please consult with bug assignee before you do that. This will be fixed when we bump to k8s 1.20, iow. when https://github.com/openshift/oc/pull/648 lands. The LifecycleStale keyword was removed because the bug got commented on recently. The bug assignee was notified. This bug hasn't had any activity in the last 30 days. Maybe the problem got resolved, was a duplicate of something else, or became less pressing for some reason - or maybe it's still relevant but just hasn't been looked at yet. As such, we're marking this bug as "LifecycleStale" and decreasing the severity/priority. If you have further information on the current state of the bug, please update it, otherwise this bug can be closed in about 7 days. The information can be, for example, that the problem still occurs, that you still want the feature, that more information is needed, or that the bug is (for whatever reason) no longer relevant. Additionally, you can add LifecycleFrozen into Keywords if you think this bug should never be marked as stale. Please consult with bug assignee before you do that. This landed in https://github.com/openshift/oc/pull/660 The LifecycleStale keyword was removed because the bug moved to QE and the bug got commented on recently. The bug assignee was notified. The core issue here is that goroutines started being printed at low levels. As part of the solution we bumped the level from 2 to 6, see https://github.com/kubernetes/kubernetes/pull/94663. Iow. you will still see goroutines printed when something fails, but they won't show up until you specify -v=6 or higher. Verified with the payload below and i see that when using verbose greater than 6 or higher oc client version >=4.6 will always print goroutine crash if something fails and we cannot get the similar behaviour as oc client version <=4.5 due to upstream changes. Also trying with verbose <=5 will always print the actual error and does not print any go routine crash and <5 is sufficient for majority of oc debugging. When requested for a health of a OCP cluster which is not available with verbose 2 below is what i see: [knarra@knarra openshift-client-linux-4.7.0-0.nightly-2021-01-07-034013]$ ./oc get --raw=/healthz --v 2 Unable to connect to the server: dial tcp: lookup api.knarra01074.qe.devcluster.openshift.com on 10.75.5.25:53: no such host [knarra@knarra openshift-client-linux-4.7.0-0.nightly-2021-01-07-034013]$ ./oc adm node-logs ip-10-0-216-43.us-east-2.compute.internal --since today --loglevel=2 error: the server rejected our request for an unknown reason parameter 'since' is invalid: date must be a relative time of the form '(+|-)[0-9]+(s|m|h|d)' or a date in 'YYYY-MM-DD HH:MM:SS' form [knarra@knarra openshift-client-linux-4.7.0-0.nightly-2021-01-07-034013]$ oc version -o yaml clientVersion: buildDate: "2020-12-22T02:22:23Z" compiler: gc gitCommit: 8fbc95fdb0e31194797127fd79b891857fed36ac gitTreeState: clean gitVersion: 4.7.0-202012220147.p0-8fbc95f goVersion: go1.15.5 major: "" minor: "" platform: linux/amd64 openshiftVersion: 4.7.0-0.nightly-2021-01-07-181010 serverVersion: buildDate: "2021-01-07T08:20:38Z" compiler: gc gitCommit: 74cd459bbb9c4faa57ece429d35e8a3167e87a7b gitTreeState: clean gitVersion: v1.20.0+74cd459 goVersion: go1.15.5 major: "1" minor: "20" platform: linux/amd64 Based on the above moving the bug to verified state. 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 |