From 60da003596f8460e4868b51533d5f1989dcea12d Mon Sep 17 00:00:00 2001 From: Artem Bortnikov Date: Thu, 6 Jun 2024 15:31:06 +0300 Subject: [PATCH 1/3] handle context without logger Signed-off-by: Artem Bortnikov --- internal/log/logger.go | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/internal/log/logger.go b/internal/log/logger.go index 3bd4415..372575a 100644 --- a/internal/log/logger.go +++ b/internal/log/logger.go @@ -90,25 +90,33 @@ func Setup(ctx context.Context, p Parameters) context.Context { // 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 } From 169a212a588e252ceaad894113b3ad183cfa9f75 Mon Sep 17 00:00:00 2001 From: Artem Bortnikov Date: Sun, 30 Jun 2024 15:20:11 +0300 Subject: [PATCH 2/3] custom handler and cmd flag to enable stacktrace Signed-off-by: Artem Bortnikov --- cmd/app/commandline.go | 50 ++++++++++--------- go.mod | 3 +- go.sum | 2 - internal/log/handler.go | 99 ++++++++++++++++++++++++++++++++++++++ internal/log/logger.go | 49 +++++++------------ internal/log/option.go | 70 +++++++++++++++++++++++++++ internal/log/stacktrace.go | 82 +++++++++++++++++++++++++++++++ 7 files changed, 296 insertions(+), 59 deletions(-) create mode 100644 internal/log/handler.go create mode 100644 internal/log/option.go create mode 100644 internal/log/stacktrace.go diff --git a/cmd/app/commandline.go b/cmd/app/commandline.go index 9ba7fcb..b98bc01 100644 --- a/cmd/app/commandline.go +++ b/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, } } diff --git a/go.mod b/go.mod index d74f419..56f5d18 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index a13159d..d60eb6e 100644 --- a/go.sum +++ b/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= diff --git a/internal/log/handler.go b/internal/log/handler.go new file mode 100644 index 0000000..32878f9 --- /dev/null +++ b/internal/log/handler.go @@ -0,0 +1,99 @@ +/* +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" + "time" +) + +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 { + handler := h.clone() + handler.Handler = handler.Handler.WithAttrs(attrs) + 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 +} diff --git a/internal/log/logger.go b/internal/log/logger.go index 372575a..380eb44 100644 --- a/internal/log/logger.go +++ b/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,28 +61,15 @@ 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) } diff --git a/internal/log/option.go b/internal/log/option.go new file mode 100644 index 0000000..c66c9ea --- /dev/null +++ b/internal/log/option.go @@ -0,0 +1,70 @@ +/* +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 ( + "io" + "log/slog" +) + +type Option interface { + apply(*Handler) +} + +type loggingLevel struct { + level slog.Leveler +} + +func (o loggingLevel) apply(h *Handler) { + h.level = o.level +} + +func WithLevel(l slog.Leveler) Option { + return loggingLevel{level: l} +} + +type stacktrace struct { + enabled bool + level slog.Leveler +} + +func (o stacktrace) apply(h *Handler) { + h.stacktraceEnabled = o.enabled + h.stacktraceLevel = o.level +} + +func WithStacktrace(enabled bool, level slog.Leveler) Option { + return stacktrace{enabled: enabled, level: level} +} + +type writer struct { + w io.Writer +} + +func (o writer) apply(h *Handler) { + h.writer = o.w +} + +func WithWriter(w io.Writer) Option { + return writer{w: w} +} + +func applyForHandler(h *Handler, opts ...Option) { + for _, opt := range opts { + opt.apply(h) + } +} diff --git a/internal/log/stacktrace.go b/internal/log/stacktrace.go new file mode 100644 index 0000000..f775076 --- /dev/null +++ b/internal/log/stacktrace.go @@ -0,0 +1,82 @@ +/* +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 ( + "fmt" + "runtime" +) + +type stack struct { + pcs []uintptr + frames *runtime.Frames + storage []uintptr +} + +func (s *stack) next() (runtime.Frame, bool) { + return s.frames.Next() +} + +type depth int + +const ( + first depth = iota + full +) + +func capture(skip int, depth depth) *stack { + st := &stack{ + storage: make([]uintptr, 64), + } + + switch depth { + case first: + st.pcs = st.storage[:1] + case full: + st.pcs = st.storage + } + + numFrames := runtime.Callers( + skip+2, + st.pcs, + ) + + if depth == full { + pcs := st.pcs + for numFrames == len(pcs) { + pcs = make([]uintptr, len(pcs)*2) + numFrames = runtime.Callers(skip+2, pcs) + } + + st.storage = pcs + st.pcs = pcs[:numFrames] + } else { + st.pcs = st.pcs[:numFrames] + } + + st.frames = runtime.CallersFrames(st.pcs) + return st +} + +func getStacktrace(skip int) []string { + st := capture(skip+1, full) + result := make([]string, 0) + for frame, more := st.next(); more; frame, more = st.next() { + result = append(result, fmt.Sprintf("%s:%d:%s", frame.File, frame.Line, frame.Function)) + } + return result +} From ece0b5d9c140f89fc3b82f328dca269d7a68b662 Mon Sep 17 00:00:00 2001 From: Artem Bortnikov Date: Sun, 30 Jun 2024 19:56:26 +0300 Subject: [PATCH 3/3] omit tls data from logged v1.Secrets Signed-off-by: Artem Bortnikov --- internal/controller/etcdcluster_controller.go | 4 +- internal/log/handler.go | 45 ++++++++++++++++++- 2 files changed, 46 insertions(+), 3 deletions(-) diff --git a/internal/controller/etcdcluster_controller.go b/internal/controller/etcdcluster_controller.go index 87aeab6..82cc706 100644 --- a/internal/controller/etcdcluster_controller.go +++ b/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 { diff --git a/internal/log/handler.go b/internal/log/handler.go index 32878f9..b40c024 100644 --- a/internal/log/handler.go +++ b/internal/log/handler.go @@ -21,9 +21,17 @@ import ( "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 @@ -64,8 +72,12 @@ func (h *Handler) Handle(ctx context.Context, r slog.Record) error { } 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(attrs) + handler.Handler = handler.Handler.WithAttrs(redacted) return handler } @@ -97,3 +109,34 @@ func replaceCommonKeyValues(_ []string, a slog.Attr) slog.Attr { } 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), + } +}