Add log level support

Signed-off-by: Monis Khan <mok@vmware.com>

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)
 	}

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

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
 }
 

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.

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

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
+}

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)
+}

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...)
+}