logging enhancement (#246)

Added:
- stacktrace to log entry
- cmd flag to enable/disable stacktrace (by default stacktrace enabled,
stacktrace log level = error)

To disable stacktrace in logs, one should explicitly provide
`--enable-stacktrace=false` flag or set corresponding env var
(`ENABLE_STACKTRACE=false`).

Fixed:
- fallback to default logger, if context does not contain logger
- sensitive data in logged tls v1.Secret is now omitted

Fixes: #235

---------

Signed-off-by: Artem Bortnikov <artem.bortnikov@telekom.com>

Author: aobort

cmd/app/commandline.go

@@ -28,16 +28,17 @@ import (
 )
 
 type Flags struct {
-	Kubeconfig      string
-	MetricsAddress  string
-	ProbeAddress    string
-	LeaderElection  bool
-	SecureMetrics   bool
-	EnableHTTP2     bool
-	DisableWebhooks bool
-	LogLevel        string
-	StacktraceLevel string
-	Dev             bool
+	Kubeconfig       string
+	MetricsAddress   string
+	ProbeAddress     string
+	LeaderElection   bool
+	SecureMetrics    bool
+	EnableHTTP2      bool
+	DisableWebhooks  bool
+	LogLevel         string
+	StacktraceLevel  string
+	EnableStacktrace bool
+	Dev              bool
 }
 
 func ParseCmdLine() Flags {
@@ -54,6 +55,7 @@ func ParseCmdLine() Flags {
 	pflag.Bool("enable-http2", false, "If set, HTTP/2 will be enabled for the metrics and webhook servers.")
 	pflag.Bool("disable-webhooks", false, "If set, the webhooks will be disabled.")
 	pflag.String("log-level", "info", "Logger verbosity level.Applicable values are debug, info, warn, error.")
+	pflag.Bool("enable-stacktrace", true, "If set log entries will contain stacktrace.")
 	pflag.String("stacktrace-level", "error", "Logger level to add stacktrace. "+
 		"Applicable values are debug, info, warn, error.")
 	pflag.Bool("dev", false, "development mode.")
@@ -75,16 +77,17 @@ func ParseCmdLine() Flags {
 	}
 
 	return Flags{
-		Kubeconfig:      viper.GetString("kubeconfig"),
-		MetricsAddress:  viper.GetString("metrics-bind-address"),
-		ProbeAddress:    viper.GetString("health-probe-bind-address"),
-		LeaderElection:  viper.GetBool("leader-elect"),
-		SecureMetrics:   viper.GetBool("metrics-secure"),
-		EnableHTTP2:     viper.GetBool("enable-http2"),
-		DisableWebhooks: viper.GetBool("disable-webhooks"),
-		LogLevel:        viper.GetString("log-level"),
-		StacktraceLevel: viper.GetString("stacktrace-level"),
-		Dev:             viper.GetBool("dev"),
+		Kubeconfig:       viper.GetString("kubeconfig"),
+		MetricsAddress:   viper.GetString("metrics-bind-address"),
+		ProbeAddress:     viper.GetString("health-probe-bind-address"),
+		LeaderElection:   viper.GetBool("leader-elect"),
+		SecureMetrics:    viper.GetBool("metrics-secure"),
+		EnableHTTP2:      viper.GetBool("enable-http2"),
+		DisableWebhooks:  viper.GetBool("disable-webhooks"),
+		LogLevel:         viper.GetString("log-level"),
+		StacktraceLevel:  viper.GetString("stacktrace-level"),
+		EnableStacktrace: viper.GetBool("enable-stacktrace"),
+		Dev:              viper.GetBool("dev"),
 	}
 }
 
@@ -107,8 +110,9 @@ func exitUsage(err error) {
 
 func LogParameters(flags Flags) log.Parameters {
 	return log.Parameters{
-		LogLevel:        flags.LogLevel,
-		StacktraceLevel: flags.StacktraceLevel,
-		Development:     flags.Dev,
+		LogLevel:         flags.LogLevel,
+		StacktraceLevel:  flags.StacktraceLevel,
+		EnableStacktrace: flags.EnableStacktrace,
+		Development:      flags.Dev,
 	}
 }

go.mod

@@ -12,8 +12,6 @@ require (
 	github.com/spf13/pflag v1.0.5
 	github.com/spf13/viper v1.19.0
 	go.etcd.io/etcd/client/v3 v3.5.14
-	go.uber.org/zap v1.27.0
-	go.uber.org/zap/exp v0.2.0
 	k8s.io/api v0.30.2
 	k8s.io/apimachinery v0.30.2
 	k8s.io/client-go v0.30.2
@@ -72,6 +70,7 @@ require (
 	go.etcd.io/etcd/api/v3 v3.5.14 // indirect
 	go.etcd.io/etcd/client/pkg/v3 v3.5.14 // indirect
 	go.uber.org/multierr v1.11.0 // indirect
+	go.uber.org/zap v1.27.0 // indirect
 	golang.org/x/exp v0.0.0-20230905200255-921286631fa9 // indirect
 	golang.org/x/net v0.25.0 // indirect
 	golang.org/x/oauth2 v0.18.0 // indirect

go.sum

@@ -167,8 +167,6 @@ go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0=
 go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
 go.uber.org/zap v1.27.0 h1:aJMhYGrd5QSmlpLMr2MftRKl7t8J8PTZPA732ud/XR8=
 go.uber.org/zap v1.27.0/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E=
-go.uber.org/zap/exp v0.2.0 h1:FtGenNNeCATRB3CmB/yEUnjEFeJWpB/pMcy7e2bKPYs=
-go.uber.org/zap/exp v0.2.0/go.mod h1:t0gqAIdh1MfKv9EwN/dLwfZnJxe9ITAZN78HEWPFWDQ=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
 golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=

internal/controller/etcdcluster_controller.go

@@ -378,7 +378,7 @@ func (r *EtcdClusterReconciler) getTLSConfig(ctx context.Context, cluster *etcda
 			log.Error(ctx, err, "failed to get server trusted CA secret")
 			return nil, err
 		}
-		log.Debug(ctx, "secret read", "server trusted CA secret") // serverCASecret,
+		log.Debug(ctx, "secret read", "server trusted CA secret", serverCASecret)
 
 		caCertPool = x509.NewCertPool()
 
@@ -398,7 +398,7 @@ func (r *EtcdClusterReconciler) getTLSConfig(ctx context.Context, cluster *etcda
 			log.Error(ctx, err, "failed to get root client secret")
 			return nil, err
 		}
-		log.Debug(ctx, "secret read", "root client secret") // rootSecret,
+		log.Debug(ctx, "secret read", "root client secret", rootSecret)
 
 		cert, err = tls.X509KeyPair(rootSecret.Data["tls.crt"], rootSecret.Data["tls.key"])
 		if err != nil {

internal/log/handler.go

@@ -0,0 +1,142 @@
+/*
+Copyright 2024 The etcd-operator Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package log
+
+import (
+	"context"
+	"io"
+	"log/slog"
+	"os"
+	"slices"
+	"strings"
+	"time"
+
+	corev1 "k8s.io/api/core/v1"
+)
+
+var sensitiveDataKeys = []string{"key", "crt", "password", "secret", "token"}
+
+const sensitiveDataReplacement = "OMITTED"
+
+type Handler struct {
+	slog.Handler
+	writer            io.Writer
+	level             slog.Leveler
+	stacktraceEnabled bool
+	stacktraceLevel   slog.Leveler
+}
+
+func NewHandler(opts ...Option) *Handler {
+	handler := &Handler{
+		writer:          os.Stdout,
+		level:           slog.LevelInfo,
+		stacktraceLevel: slog.LevelError,
+	}
+	applyForHandler(handler, opts...)
+	handler.Handler = slog.NewJSONHandler(handler.writer, &slog.HandlerOptions{
+		Level:       handler.level,
+		ReplaceAttr: replaceCommonKeyValues,
+	})
+
+	return handler
+}
+
+func (h *Handler) stacktrace(level slog.Level) bool {
+	return h.stacktraceEnabled && level >= h.stacktraceLevel.Level()
+}
+
+func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool {
+	return h.Handler.Enabled(ctx, level)
+}
+
+func (h *Handler) Handle(ctx context.Context, r slog.Record) error {
+	if h.stacktrace(r.Level) {
+		trace := getStacktrace(4)
+		r.AddAttrs(slog.Attr{Key: "stacktrace", Value: slog.AnyValue(trace)})
+	}
+	return h.Handler.Handle(ctx, r)
+}
+
+func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	redacted := make([]slog.Attr, 0)
+	for _, attr := range attrs {
+		redacted = append(redacted, redactAttr(attr))
+	}
+	handler := h.clone()
+	handler.Handler = handler.Handler.WithAttrs(redacted)
+	return handler
+}
+
+func (h *Handler) WithGroup(name string) slog.Handler {
+	handler := h.clone()
+	handler.Handler = handler.Handler.WithGroup(name)
+	return handler
+}
+
+func (h *Handler) clone() *Handler {
+	return &Handler{
+		Handler:           h.Handler,
+		writer:            h.writer,
+		level:             h.level,
+		stacktraceEnabled: h.stacktraceEnabled,
+		stacktraceLevel:   h.stacktraceLevel,
+	}
+}
+
+func replaceCommonKeyValues(_ []string, a slog.Attr) slog.Attr {
+	if a.Key == slog.MessageKey {
+		a.Key = "message"
+		return a
+	}
+	if a.Key == slog.TimeKey {
+		v := a.Value
+		t := v.Time().Format(time.RFC3339)
+		a.Value = slog.StringValue(t)
+	}
+	return a
+}
+
+func redactAttr(attr slog.Attr) slog.Attr {
+	// more redacting function could be added
+	redacted := redactKubernetesSecretAttr(attr)
+	return redacted
+}
+
+func redactKubernetesSecretAttr(attr slog.Attr) slog.Attr {
+	val := attr.Value.Any()
+	sec, ok := val.(*corev1.Secret)
+	if !ok {
+		return attr
+	}
+	res := sec.DeepCopy()
+	data := res.Data
+	for k, v := range data {
+		if !slices.ContainsFunc(sensitiveDataKeys, func(s string) bool {
+			return strings.Contains(k, s)
+		}) {
+			data[k] = v
+			continue
+		}
+		data[k] = []byte(sensitiveDataReplacement)
+	}
+
+	res.Data = data
+	return slog.Attr{
+		Key:   attr.Key,
+		Value: slog.AnyValue(res),
+	}
+}

internal/log/logger.go

@@ -22,30 +22,28 @@ import (
 	"os"
 
 	"github.com/go-logr/logr"
-	"go.uber.org/zap"
-	"go.uber.org/zap/exp/zapslog"
-	"go.uber.org/zap/zapcore"
 )
 
-func mapLogLevel(level string) zapcore.Level {
+func mapLogLevel(level string) slog.Level {
 	switch level {
 	case "debug":
-		return zapcore.DebugLevel
+		return slog.LevelDebug
 	case "info":
-		return zapcore.InfoLevel
+		return slog.LevelInfo
 	case "warn":
-		return zapcore.WarnLevel
+		return slog.LevelWarn
 	case "error":
-		return zapcore.ErrorLevel
+		return slog.LevelError
 	default:
-		return zapcore.InfoLevel
+		return slog.LevelInfo
 	}
 }
 
 type Parameters struct {
-	LogLevel        string
-	StacktraceLevel string
-	Development     bool
+	LogLevel         string
+	StacktraceLevel  string
+	EnableStacktrace bool
+	Development      bool
 }
 
 // Setup initializes the logger and returns a new context with the logger attached.
@@ -63,52 +61,47 @@ type Parameters struct {
 //	  Development:     true,
 //	})
 func Setup(ctx context.Context, p Parameters) context.Context {
-	encoderConfig := zapcore.EncoderConfig{
-		MessageKey:     "message",
-		LevelKey:       "level",
-		TimeKey:        "time",
-		CallerKey:      "caller",
-		StacktraceKey:  "stacktrace",
-		EncodeLevel:    zapcore.CapitalLevelEncoder,
-		EncodeTime:     zapcore.RFC3339TimeEncoder,
-		EncodeDuration: zapcore.StringDurationEncoder,
-		EncodeCaller:   zapcore.ShortCallerEncoder,
-		EncodeName:     zapcore.FullNameEncoder,
-	}
-	encoder := zapcore.NewJSONEncoder(encoderConfig)
-	writer := os.Stderr
+	w := os.Stderr
 	if p.Development {
-		encoder = zapcore.NewConsoleEncoder(encoderConfig)
-		writer = os.Stdout
+		w = os.Stdout
 	}
-
-	core := zapcore.NewCore(encoder, writer, mapLogLevel(p.LogLevel))
-	logger := zap.New(core, zap.AddStacktrace(mapLogLevel(p.StacktraceLevel)))
-	l := slog.New(zapslog.NewHandler(logger.Core(), &zapslog.HandlerOptions{AddSource: p.Development}))
+	handler := NewHandler(
+		WithWriter(w),
+		WithLevel(mapLogLevel(p.LogLevel)),
+		WithStacktrace(p.EnableStacktrace, mapLogLevel(p.StacktraceLevel)))
+	l := slog.New(handler)
 	return logr.NewContextWithSlogLogger(ctx, l)
 }
 
 // Info logs an informational message with optional key-value pairs.
 func Info(ctx context.Context, msg string, keysAndValues ...interface{}) {
-	logr.FromContextAsSlogLogger(ctx).With(keysAndValues...).Info(msg)
+	fromContextOrDefault(ctx).With(keysAndValues...).Info(msg)
 }
 
 // Debug logs a debug message with optional key-value pairs.
 func Debug(ctx context.Context, msg string, keysAndValues ...interface{}) {
-	logr.FromContextAsSlogLogger(ctx).With(keysAndValues...).Debug(msg)
+	fromContextOrDefault(ctx).With(keysAndValues...).Debug(msg)
 }
 
 // Warn logs a warning message with optional key-value pairs.
 func Warn(ctx context.Context, msg string, keysAndValues ...interface{}) {
-	logr.FromContextAsSlogLogger(ctx).With(keysAndValues...).Warn(msg)
+	fromContextOrDefault(ctx).With(keysAndValues...).Warn(msg)
 }
 
 // Error logs an error message with optional key-value pairs.
 func Error(ctx context.Context, err error, msg string, keysAndValues ...interface{}) {
-	logr.FromContextAsSlogLogger(ctx).With(keysAndValues...).Error(msg, slog.Any("error", err))
+	fromContextOrDefault(ctx).With(keysAndValues...).Error(msg, slog.Any("error", err))
 }
 
 // WithValues adds additional key-value pairs to the context's logger.
 func WithValues(ctx context.Context, keysAndValues ...interface{}) context.Context {
-	return logr.NewContextWithSlogLogger(ctx, logr.FromContextAsSlogLogger(ctx).With(keysAndValues...))
+	return logr.NewContextWithSlogLogger(ctx, fromContextOrDefault(ctx).With(keysAndValues...))
+}
+
+func fromContextOrDefault(ctx context.Context) *slog.Logger {
+	var l *slog.Logger
+	if l = logr.FromContextAsSlogLogger(ctx); l == nil {
+		l = slog.Default()
+	}
+	return l
 }