From a5643e3738e33974613be313bf17838f7c87ddee Mon Sep 17 00:00:00 2001 From: Monis Khan Date: Tue, 10 Nov 2020 09:57:29 -0500 Subject: [PATCH] Add log level support Signed-off-by: Monis Khan --- internal/config/concierge/config.go | 5 ++ internal/config/concierge/types.go | 3 + internal/config/supervisor/config.go | 5 ++ internal/config/supervisor/types.go | 3 + internal/plog/doc.go | 22 ++++++ internal/plog/level.go | 64 +++++++++++++++++ internal/plog/level_test.go | 103 +++++++++++++++++++++++++++ internal/plog/plog.go | 35 +++++++++ 8 files changed, 240 insertions(+) create mode 100644 internal/plog/doc.go create mode 100644 internal/plog/level.go create mode 100644 internal/plog/level_test.go create mode 100644 internal/plog/plog.go diff --git a/internal/config/concierge/config.go b/internal/config/concierge/config.go index 9d448a0b3..20555a7da 100644 --- a/internal/config/concierge/config.go +++ b/internal/config/concierge/config.go @@ -13,6 +13,7 @@ import ( "sigs.k8s.io/yaml" "go.pinniped.dev/internal/constable" + "go.pinniped.dev/internal/plog" ) const ( @@ -49,6 +50,10 @@ func FromPath(path string) (*Config, error) { return nil, fmt.Errorf("validate names: %w", err) } + if err := plog.ValidateAndSetLogLevelGlobally(config.LogLevel); err != nil { + return nil, fmt.Errorf("validate log level: %w", err) + } + if config.Labels == nil { config.Labels = make(map[string]string) } diff --git a/internal/config/concierge/types.go b/internal/config/concierge/types.go index 47326541c..fc8517b5f 100644 --- a/internal/config/concierge/types.go +++ b/internal/config/concierge/types.go @@ -3,6 +3,8 @@ package concierge +import "go.pinniped.dev/internal/plog" + // Config contains knobs to setup an instance of the Pinniped Concierge. type Config struct { DiscoveryInfo DiscoveryInfoSpec `json:"discovery"` @@ -10,6 +12,7 @@ type Config struct { NamesConfig NamesConfigSpec `json:"names"` KubeCertAgentConfig KubeCertAgentSpec `json:"kubeCertAgent"` Labels map[string]string `json:"labels"` + LogLevel plog.LogLevel `json:"logLevel"` } // DiscoveryInfoSpec contains configuration knobs specific to diff --git a/internal/config/supervisor/config.go b/internal/config/supervisor/config.go index c831c71ef..5c7308c5d 100644 --- a/internal/config/supervisor/config.go +++ b/internal/config/supervisor/config.go @@ -13,6 +13,7 @@ import ( "sigs.k8s.io/yaml" "go.pinniped.dev/internal/constable" + "go.pinniped.dev/internal/plog" ) // FromPath loads an Config from a provided local file path, inserts any @@ -37,6 +38,10 @@ func FromPath(path string) (*Config, error) { return nil, fmt.Errorf("validate names: %w", err) } + if err := plog.ValidateAndSetLogLevelGlobally(config.LogLevel); err != nil { + return nil, fmt.Errorf("validate log level: %w", err) + } + return &config, nil } diff --git a/internal/config/supervisor/types.go b/internal/config/supervisor/types.go index 060b88edf..8a487d772 100644 --- a/internal/config/supervisor/types.go +++ b/internal/config/supervisor/types.go @@ -3,10 +3,13 @@ package supervisor +import "go.pinniped.dev/internal/plog" + // Config contains knobs to setup an instance of the Pinniped Supervisor. type Config struct { Labels map[string]string `json:"labels"` NamesConfig NamesConfigSpec `json:"names"` + LogLevel plog.LogLevel `json:"logLevel"` } // NamesConfigSpec configures the names of some Kubernetes resources for the Supervisor. diff --git a/internal/plog/doc.go b/internal/plog/doc.go new file mode 100644 index 000000000..41cc3071b --- /dev/null +++ b/internal/plog/doc.go @@ -0,0 +1,22 @@ +// Copyright 2020 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +// Package plog implements a thin layer over klog to help enforce pinniped's logging convention. +// Logs are always structured as a constant message with key and value pairs of related metadata. +// The logging levels in order of increasing verbosity are: +// error, warning, info, debug, trace and all. +// error and warning logs are always emitted (there is no way for the end user to disable them), +// and thus should be used sparingly. Ideally, logs at these levels should be actionable. +// info should be reserved for "nice to know" information. It should be possible to run a production +// pinniped server at the info log level with no performance degradation due to high log volume. +// debug should be used for information targeted at developers and to aid in support cases. Care must +// be taken at this level to not leak any secrets into the log stream. That is, even though debug may +// cause performance issues in production, it must not cause security issues in production. +// trace should be used to log information related to timing (i.e. the time it took a controller to sync). +// Just like debug, trace should not leak secrets into the log stream. trace will likely leak information +// about the current state of the process, but that, along with performance degradation, is expected. +// all is reserved for the most verbose and security sensitive information. At this level, full request +// metadata such as headers and parameters along with the body may be logged. This level is completely +// unfit for production use both from a performance and security standpoint. Using it is generally an +// act of desperation to determine why the system is broken. +package plog diff --git a/internal/plog/level.go b/internal/plog/level.go new file mode 100644 index 000000000..b1a0bf111 --- /dev/null +++ b/internal/plog/level.go @@ -0,0 +1,64 @@ +// Copyright 2020 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "strconv" + + "k8s.io/component-base/logs" + + "go.pinniped.dev/internal/constable" +) + +// LogLevel is an enum that controls verbosity of logs. +// Valid values in order of increasing verbosity are leaving it unset, info, debug, trace and all. +type LogLevel string + +const ( + // LevelWarning (i.e. leaving the log level unset) maps to klog log level 0. + LevelWarning LogLevel = "" + // LevelInfo maps to klog log level 2. + LevelInfo LogLevel = "info" + // LevelDebug maps to klog log level 4. + LevelDebug LogLevel = "debug" + // LevelTrace maps to klog log level 6. + LevelTrace LogLevel = "trace" + // LevelAll maps to klog log level 100 (conceptually it is log level 8). + LevelAll LogLevel = "all" + + errInvalidLogLevel = constable.Error("invalid log level, valid choices are the empty string, info, debug, trace and all") +) + +const ( + klogLevelWarning = iota * 2 + klogLevelInfo + klogLevelDebug + klogLevelTrace + klogLevelAll +) + +func ValidateAndSetLogLevelGlobally(level LogLevel) error { + var klogLogLevel int + + switch level { + case LevelWarning: + klogLogLevel = klogLevelWarning // unset means minimal logs (Error and Warning) + case LevelInfo: + klogLogLevel = klogLevelInfo + case LevelDebug: + klogLogLevel = klogLevelDebug + case LevelTrace: + klogLogLevel = klogLevelTrace + case LevelAll: + klogLogLevel = klogLevelAll + 100 // make all really mean all + default: + return errInvalidLogLevel + } + + if _, err := logs.GlogSetter(strconv.Itoa(klogLogLevel)); err != nil { + panic(err) // programmer error + } + + return nil +} diff --git a/internal/plog/level_test.go b/internal/plog/level_test.go new file mode 100644 index 000000000..2f3ad9d49 --- /dev/null +++ b/internal/plog/level_test.go @@ -0,0 +1,103 @@ +// Copyright 2020 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "strconv" + "testing" + + "github.com/stretchr/testify/require" + "k8s.io/component-base/logs" + "k8s.io/klog/v2" +) + +func TestValidateAndSetLogLevelGlobally(t *testing.T) { + originalLogLevel := getKlogLevel(t) + + tests := []struct { + name string + level LogLevel + wantLevel klog.Level + wantErr string + }{ + { + name: "unset", + wantLevel: 0, + }, + { + name: "warning", + level: LevelWarning, + wantLevel: 0, + }, + { + name: "info", + level: LevelInfo, + wantLevel: 2, + }, + { + name: "debug", + level: LevelDebug, + wantLevel: 4, + }, + { + name: "trace", + level: LevelTrace, + wantLevel: 6, + }, + { + name: "all", + level: LevelAll, + wantLevel: 108, + }, + { + name: "invalid level", + level: "panda", + wantLevel: originalLogLevel, + wantErr: errInvalidLogLevel.Error(), + }, + } + for _, tt := range tests { + tt := tt // capture range variable + t.Run(tt.name, func(t *testing.T) { + defer func() { + undoGlobalLogLevelChanges(t, originalLogLevel) + }() + + err := ValidateAndSetLogLevelGlobally(tt.level) + require.Equal(t, tt.wantErr, errString(err)) + require.Equal(t, tt.wantLevel, getKlogLevel(t)) + }) + } + + require.Equal(t, originalLogLevel, getKlogLevel(t)) +} + +func getKlogLevel(t *testing.T) klog.Level { + t.Helper() + + // hack around klog not exposing a Get method + for i := klog.Level(0); i < 256; i++ { + if klog.V(i).Enabled() { + continue + } + return i - 1 + } + + t.Fatal("unknown log level") + return 0 +} + +func errString(err error) string { + if err == nil { + return "" + } + + return err.Error() +} + +func undoGlobalLogLevelChanges(t *testing.T, originalLogLevel klog.Level) { + t.Helper() + _, err := logs.GlogSetter(strconv.Itoa(int(originalLogLevel))) + require.NoError(t, err) +} diff --git a/internal/plog/plog.go b/internal/plog/plog.go new file mode 100644 index 000000000..b22450fbb --- /dev/null +++ b/internal/plog/plog.go @@ -0,0 +1,35 @@ +// Copyright 2020 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import "k8s.io/klog/v2" + +func Error(err error, msg string, keysAndValues ...interface{}) { + klog.ErrorS(err, msg, keysAndValues...) +} + +func Warning(msg string, keysAndValues ...interface{}) { + // klog's structured logging has no concept of a warning (i.e. no WarningS function) + // Thus we use info at log level zero as a proxy + // klog's info logs have an I prefix and its warning logs have a W prefix + // Since we lose the W prefix by using InfoS, just add a key to make these easier to find + keysAndValues = append([]interface{}{"warning", "true"}, keysAndValues...) + klog.V(klogLevelWarning).InfoS(msg, keysAndValues...) +} + +func Info(msg string, keysAndValues ...interface{}) { + klog.V(klogLevelInfo).InfoS(msg, keysAndValues...) +} + +func Debug(msg string, keysAndValues ...interface{}) { + klog.V(klogLevelDebug).InfoS(msg, keysAndValues...) +} + +func Trace(msg string, keysAndValues ...interface{}) { + klog.V(klogLevelTrace).InfoS(msg, keysAndValues...) +} + +func All(msg string, keysAndValues ...interface{}) { + klog.V(klogLevelAll).InfoS(msg, keysAndValues...) +}