Skip to content

Commit

Permalink
Improve klog (client-go logs) handling (#11632)
Browse files Browse the repository at this point in the history 
* 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/[email protected]/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/[email protected]/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="<nil>"
time="2023-11-17T20:58:32Z" level=info msg="pkg/mod/k8s.io/[email protected]/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/[email protected]/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="<nil>"
time="2023-11-17T20:58:34Z" level=info msg="pkg/mod/k8s.io/[email protected]/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/[email protected]/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="<nil>"

time="2023-11-17T20:58:40Z" level=info msg="pkg/mod/k8s.io/[email protected]/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/[email protected]/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="<nil>"
time="2023-11-17T20:58:48Z" level=info msg="pkg/mod/k8s.io/[email protected]/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/[email protected]/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="<nil>"
time="2023-11-17T20:59:05Z" level=info msg="pkg/mod/k8s.io/[email protected]/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/[email protected]/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="<nil>"
time="2023-11-17T20:59:30Z" level=fatal msg="failed to sync caches"
```
  • Loading branch information
@alpeb @olix0r
alpeb authored and olix0r committed Dec 6, 2023
1 parent 284d76b commit 64bccd9
Show file tree
Hide file tree
Showing 3 changed files with 27 additions and 15 deletions.
1 change: 1 addition & 0 deletions go.mod
View file
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,7 @@ require (

require (
github.com/AdaLogics/go-fuzz-headers v0.0.0-20230106234847-43070de90fa1
github.com/bombsimon/logrusr/v4 v4.1.0
github.com/prometheus/client_model v0.4.0
gopkg.in/yaml.v2 v2.4.0
k8s.io/utils v0.0.0-20230220204549-a5ecb0141aa5
Expand Down
2 changes: 2 additions & 0 deletions go.sum
View file
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,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=
Expand Down
39 changes: 24 additions & 15 deletions pkg/flags/flags.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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",
Expand All @@ -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)
}
Expand All @@ -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")
}
}

Expand Down

0 comments on commit 64bccd9

Please sign in to comment.