From b438ec41b9f3a8c0cf734a2053d747e12cde79af Mon Sep 17 00:00:00 2001 From: Alejandro Pedraza Date: Tue, 28 Nov 2023 09:25:13 -0500 Subject: [PATCH] Improve klog (client-go logs) handling (#11632) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Improve klog (client-go logs) handling Currently log entries in the go-based controllers originated in the client-go library are only visible if the controller’s log level is `debug`. If the log level is lower (`info`, `warn`, `error`), we lose possibly important information. If the log level is `debug` we receive a lot of entries, mostly irrelevant. client-go uses [klog](https://github.com/kubernetes/klog) for its logs, which relies on [logr](https://github.com/go-logr/logr) as its backend, which is just an interface allowing different implementations, one of which is logrus, which we use in our controllers. So in this change we bring the [logrusr](https://github.com/bombsimon/logrusr) library which implements logrus for logr. The verbosity level for klog is also tweaked a little bit, according to k8s [logging conventions](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md). Also, given that logging output is now handled completely by logrus, some of the klog config flags are no longer required. As an example of the new behavior in the proxy-injector logs, when removing the RBAC to list pods, we now see the complaints coming from client-go, which were invisible before at `info` level: ```console time="2023-11-17T20:58:30Z" level=info msg="running version dev-94ad50cd-alpeb" time="2023-11-17T20:58:30Z" level=info msg="starting admin server on :9995" time="2023-11-17T20:58:30Z" level=info msg="listening at :8443" time="2023-11-17T20:58:30Z" level=info msg="waiting for caches to sync" time="2023-11-17T20:58:30Z" level=info msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" time="2023-11-17T20:58:30Z" level=error msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="" time="2023-11-17T20:58:32Z" level=info msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" time="2023-11-17T20:58:32Z" level=error msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="" time="2023-11-17T20:58:34Z" level=info msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" time="2023-11-17T20:58:34Z" level=error msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="" time="2023-11-17T20:58:40Z" level=info msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" time="2023-11-17T20:58:40Z" level=error msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="" time="2023-11-17T20:58:48Z" level=info msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" time="2023-11-17T20:58:48Z" level=error msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="" time="2023-11-17T20:59:05Z" level=info msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" time="2023-11-17T20:59:05Z" level=error msg="pkg/mod/k8s.io/client-go@v0.28.3/tools/cache/reflector.go:229: Failed to watch *v1.PartialObjectMetadata: failed to list *v1.PartialObjectMetadata: pods is forbidden: User \"system:serviceaccount:linkerd:linkerd-proxy-injector\" cannot list resource \"pods\" in API group \"\" at the cluster scope" error="" time="2023-11-17T20:59:30Z" level=fatal msg="failed to sync caches" ``` --- go.mod | 1 + go.sum | 2 ++ pkg/flags/flags.go | 39 ++++++++++++++++++++++++--------------- 3 files changed, 27 insertions(+), 15 deletions(-) diff --git a/go.mod b/go.mod index ebcb20b73..f04f79420 100644 --- a/go.mod +++ b/go.mod @@ -54,6 +54,7 @@ require ( require ( github.com/AdaLogics/go-fuzz-headers v0.0.0-20230811130428-ced1acdcaa24 + github.com/bombsimon/logrusr/v4 v4.1.0 github.com/prometheus/client_model v0.5.0 gopkg.in/yaml.v2 v2.4.0 k8s.io/utils v0.0.0-20230505201702-9f6742963106 diff --git a/go.sum b/go.sum index 3c0b70905..d8e790c01 100644 --- a/go.sum +++ b/go.sum @@ -53,6 +53,8 @@ github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24 github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8= github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= +github.com/bombsimon/logrusr/v4 v4.1.0 h1:uZNPbwusB0eUXlO8hIUwStE6Lr5bLN6IgYgG+75kuh4= +github.com/bombsimon/logrusr/v4 v4.1.0/go.mod h1:pjfHC5e59CvjTBIU3V3sGhFWFAnsnhOR03TRc6im0l8= github.com/briandowns/spinner v0.0.0-20190212173954-5cf08d0ac778 h1:Dmz6bJXocvwkw7BOz4jpyVZReGrkjs+fBDWKn5tBES4= github.com/briandowns/spinner v0.0.0-20190212173954-5cf08d0ac778/go.mod h1:hw/JEQBIE+c/BLI4aKM8UU8v+ZqrD3h7HC27kKt8JQU= github.com/bshuster-repo/logrus-logstash-hook v1.0.0 h1:e+C0SB5R1pu//O4MQ3f9cFuPGoOVeF2fE4Og9otCc70= diff --git a/pkg/flags/flags.go b/pkg/flags/flags.go index 7df09f25d..f447ac6cc 100644 --- a/pkg/flags/flags.go +++ b/pkg/flags/flags.go @@ -6,6 +6,8 @@ import ( "os" "github.com/linkerd/linkerd2/pkg/version" + + "github.com/bombsimon/logrusr/v4" log "github.com/sirupsen/logrus" "github.com/spf13/pflag" "helm.sh/helm/v3/pkg/cli/values" @@ -28,11 +30,6 @@ const ( // func calls flag.Parse(), so it should be called after all other flags have // been configured. func ConfigureAndParse(cmd *flag.FlagSet, args []string) { - klog.InitFlags(nil) - flag.Set("stderrthreshold", "FATAL") - flag.Set("logtostderr", "false") - flag.Set("log_file", "/dev/null") - flag.Set("v", "0") logLevel := cmd.String("log-level", log.InfoLevel.String(), "log level, must be one of: panic, fatal, error, warn, info, debug, trace") logFormat := cmd.String("log-format", "plain", @@ -44,9 +41,11 @@ func ConfigureAndParse(cmd *flag.FlagSet, args []string) { //nolint:errcheck cmd.Parse(args) - // set log timestamps log.SetFormatter(getFormatter(*logFormat)) + klog.InitFlags(nil) + klog.SetLogger(logrusr.New(log.StandardLogger())) + setLogLevel(*logLevel) maybePrintVersionAndExit(*printVersion) } @@ -66,16 +65,26 @@ func setLogLevel(logLevel string) { } log.SetLevel(level) - if level >= log.DebugLevel { - flag.Set("stderrthreshold", "INFO") - flag.Set("logtostderr", "true") + // Loosely based on k8s logging conventions, except for 'tracing' that we + // bump to 10 (we can see in client-go source code that level is actually + // used) and `debug` to 6 (given that at level 7 and higher auth tokens get + // logged) + // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md + switch level { + case log.PanicLevel: + flag.Set("v", "0") + case log.FatalLevel: + flag.Set("v", "0") + case log.ErrorLevel: + flag.Set("v", "0") + case log.WarnLevel: + flag.Set("v", "0") + case log.InfoLevel: + flag.Set("v", "2") + case log.DebugLevel: flag.Set("v", "6") - // pipe klog entries to logrus - klog.SetOutput(log.StandardLogger().Writer()) - } - - if level >= log.TraceLevel { - flag.Set("v", "12") // At 7 and higher, authorization tokens get logged. + case log.TraceLevel: + flag.Set("v", "10") } }