From 40c279fb9320f32aa91d04fa1572c5cf7e933cdf Mon Sep 17 00:00:00 2001 From: "M. Essam" Date: Fri, 26 Jan 2024 11:27:08 +0200 Subject: [PATCH] Implement structured logging (#1438) **Description of the change** Change controller logging to use `log/slog`. **Benefits** 1. Allow structured logging. 2. Allow changing logging format between text and JSON. 3. Allow changing logging level. **Possible drawbacks** N/A **Applicable issues** - fixes #1285 **Additional information** * I took the liberty of removing log at line 91 in pkg/controller/main.go as it only served as a separator * To implement the functionality of `--log-info-to-stdout`, I had to implement a custom handler that would hand logs down to one of two slog.Loggers in place of the package in `pkg/log` that handled this previously --------- Signed-off-by: M Essam Hamed --- cmd/controller/main.go | 21 ++++++- helm/sealed-secrets/README.md | 2 + helm/sealed-secrets/templates/deployment.yaml | 8 +++ helm/sealed-secrets/values.yaml | 6 ++ pkg/controller/controller.go | 33 ++++++----- pkg/controller/keyregistry.go | 6 +- pkg/controller/main.go | 20 +++---- pkg/controller/server.go | 21 +++---- pkg/log/log.go | 57 ++++++++++++------- 9 files changed, 112 insertions(+), 62 deletions(-) diff --git a/cmd/controller/main.go b/cmd/controller/main.go index 330e028d5..8171fb8d3 100644 --- a/cmd/controller/main.go +++ b/cmd/controller/main.go @@ -4,7 +4,7 @@ import ( goflag "flag" "fmt" "io" - "log" + "log/slog" "os" "time" @@ -12,6 +12,7 @@ import ( "github.com/bitnami-labs/sealed-secrets/pkg/controller" "github.com/bitnami-labs/sealed-secrets/pkg/flagenv" + "github.com/bitnami-labs/sealed-secrets/pkg/log" "github.com/bitnami-labs/sealed-secrets/pkg/pflagenv" ssv1alpha1 "github.com/bitnami-labs/sealed-secrets/pkg/apis/sealedsecrets/v1alpha1" @@ -52,6 +53,8 @@ func bindControllerFlags(f *controller.Flags, fs *flag.FlagSet) { fs.BoolVar(&f.SkipRecreate, "skip-recreate", false, "if true the controller will skip listening for managed secret changes to recreate them. This helps on limited permission environments.") fs.BoolVar(&f.LogInfoToStdout, "log-info-stdout", false, "if true the controller will log info to stdout.") + fs.StringVar(&f.LogLevel, "log-level", "INFO", "Log level (INFO|ERROR).") + fs.StringVar(&f.LogFormat, "log-format", "text", "Log format (text|json).") fs.DurationVar(&f.KeyRenewPeriod, "rotate-period", defaultKeyRenewPeriod, "") _ = fs.MarkDeprecated("rotate-period", "please use key-renew-period instead") @@ -85,14 +88,26 @@ func mainE(w io.Writer, fs *flag.FlagSet, gofs *goflag.FlagSet, args []string) e return err } + // Set logging + logLevel := slog.Level(0) + logLevel.UnmarshalText([]byte(flags.LogLevel)) + opts := &slog.HandlerOptions{ + Level: logLevel, + } + if flags.LogInfoToStdout { + slog.SetDefault(slog.New(log.New(os.Stdout, os.Stderr, flags.LogFormat, opts))) + } else { + slog.SetDefault(slog.New(log.New(os.Stderr, os.Stderr, flags.LogFormat, opts))) + } + ssv1alpha1.AcceptDeprecatedV1Data = flags.AcceptV1Data - fmt.Fprintf(w, "controller version: %s\n", VERSION) if printVersion { + fmt.Fprintf(w, "controller version: %s\n", VERSION) return nil } - log.Printf("Starting sealed-secrets controller version: %s\n", VERSION) + slog.Info("Starting sealed-secrets controller", "version", VERSION) if err := controller.Main(&flags, VERSION); err != nil { panic(err) } diff --git a/helm/sealed-secrets/README.md b/helm/sealed-secrets/README.md index c2beb3793..174998636 100644 --- a/helm/sealed-secrets/README.md +++ b/helm/sealed-secrets/README.md @@ -101,6 +101,8 @@ The command removes all the Kubernetes components associated with the chart and | `privateKeyAnnotations` | Map of annotations to be set on the sealing keypairs | `{}` | | `privateKeyLabels` | Map of labels to be set on the sealing keypairs | `{}` | | `logInfoStdout` | Specifies whether the Sealed Secrets controller will log info to stdout | `false` | +| `logLevel` | Specifies log level of controller (INFO,ERROR) | `""` | +| `logFormat` | Specifies log format (text,json) | `""` | | `command` | Override default container command | `[]` | | `args` | Override default container args | `[]` | | `livenessProbe.enabled` | Enable livenessProbe on Sealed Secret containers | `true` | diff --git a/helm/sealed-secrets/templates/deployment.yaml b/helm/sealed-secrets/templates/deployment.yaml index 32318887b..00728cfb4 100644 --- a/helm/sealed-secrets/templates/deployment.yaml +++ b/helm/sealed-secrets/templates/deployment.yaml @@ -120,6 +120,14 @@ spec: {{- if .Values.logInfoStdout }} - --log-info-stdout {{- end }} + {{- if .Values.logLevel }} + - --log-level + - {{ .Values.logLevel }} + {{- end }} + {{- if .Values.logFormat }} + - --log-format + - {{ .Values.logFormat }} + {{- end }} {{- end }} image: {{ printf "%s/%s:%s" .Values.image.registry .Values.image.repository .Values.image.tag }} imagePullPolicy: {{ .Values.image.pullPolicy }} diff --git a/helm/sealed-secrets/values.yaml b/helm/sealed-secrets/values.yaml index b91b04e27..c7aed265c 100644 --- a/helm/sealed-secrets/values.yaml +++ b/helm/sealed-secrets/values.yaml @@ -94,6 +94,12 @@ privateKeyLabels: {} ## @param logInfoStdout Specifies whether the Sealed Secrets controller will log info to stdout ## logInfoStdout: false +## @param logLevel Specifies log level of controller (INFO,ERROR) +## +logLevel: "" +## @param logFormat Specifies log format (text,json) +## +logFormat: "" ## @param command Override default container command ## command: [] diff --git a/pkg/controller/controller.go b/pkg/controller/controller.go index 3af594714..1adc16bb4 100644 --- a/pkg/controller/controller.go +++ b/pkg/controller/controller.go @@ -6,6 +6,7 @@ import ( "encoding/json" "errors" "fmt" + "log/slog" "reflect" "strings" "time" @@ -33,7 +34,6 @@ import ( ssscheme "github.com/bitnami-labs/sealed-secrets/pkg/client/clientset/versioned/scheme" ssv1alpha1client "github.com/bitnami-labs/sealed-secrets/pkg/client/clientset/versioned/typed/sealedsecrets/v1alpha1" ssinformer "github.com/bitnami-labs/sealed-secrets/pkg/client/informers/externalversions" - "github.com/bitnami-labs/sealed-secrets/pkg/log" "github.com/bitnami-labs/sealed-secrets/pkg/multidocyaml" ) @@ -82,7 +82,10 @@ func NewController(clientset kubernetes.Interface, ssclientset ssclientset.Inter utilruntime.Must(ssscheme.AddToScheme(scheme.Scheme)) eventBroadcaster := record.NewBroadcaster() - eventBroadcaster.StartLogging(log.Infof) + eventBroadcaster.StartLogging(func(format string, args ...interface{}) { + // Must use Sprintf to ensure slog doesn't interpret args... as key-value pairs + slog.Info(fmt.Sprintf(format, args...)) + }) eventBroadcaster.StartRecordingToSink(&v1.EventSinkImpl{Interface: clientset.CoreV1().Events("")}) recorder := eventBroadcaster.NewRecorder(scheme.Scheme, corev1.EventSource{Component: "sealed-secrets"}) @@ -125,7 +128,7 @@ func watchSealedSecrets(ssinformer ssinformer.SharedInformerFactory, queue workq if sealedSecretChanged(oldObj, newObj) { queue.Add(key) } else { - log.Infof("update suppressed, no changes in sealed secret spec of %v", key) + slog.Info("update suppressed, no changes in spec", "sealed-secret", key) } } }, @@ -163,20 +166,20 @@ func watchSecrets(sinformer informers.SharedInformerFactory, ssclientset ssclien DeleteFunc: func(obj interface{}) { skey, err := cache.DeletionHandlingMetaNamespaceKeyFunc(obj) if err != nil { - log.Errorf("failed to fetch Secret key: %v", err) + slog.Error("failed to fetch Secret key", "error", err) return } ns, name, err := cache.SplitMetaNamespaceKey(skey) if err != nil { - log.Errorf("failed to get namespace and name from key: %v", err) + slog.Error("failed to get namespace and name from key", "secret", skey, "error", err) return } ssecret, err := ssclientset.BitnamiV1alpha1().SealedSecrets(ns).Get(context.Background(), name, metav1.GetOptions{}) if err != nil { if !k8serrors.IsNotFound(err) { - log.Errorf("failed to get SealedSecret: %v", err) + slog.Error("failed to get SealedSecret", "secret", skey, "error", err) } return } @@ -187,7 +190,7 @@ func watchSecrets(sinformer informers.SharedInformerFactory, ssclientset ssclien sskey, err := cache.MetaNamespaceKeyFunc(ssecret) if err != nil { - log.Errorf("failed to fetch SealedSecret key: %v", err) + slog.Error("failed to fetch SealedSecret key", "secret", skey, "error", err) return } @@ -242,7 +245,7 @@ func (c *Controller) Run(stopCh <-chan struct{}) { c.runWorker(context.Background()) }, time.Second, stopCh) - log.Errorf("Shutting down controller") + slog.Error("Shutting down controller") } func (c *Controller) runWorker(ctx context.Context) { @@ -264,15 +267,15 @@ func (c *Controller) processNextItem(ctx context.Context) bool { c.queue.Forget(key) } else if isImmutableError(err) { // Do not retry updating immutable fields of an immutable secret - log.Errorf(formatImmutableError(key.(string))) + slog.Error(formatImmutableError(key.(string))) c.queue.Forget(key) utilruntime.HandleError(err) } else if c.queue.NumRequeues(key) < maxRetries { - log.Errorf("Error updating %s, will retry: %v", key, err) + slog.Error("Error updating, will retry", "key", key, "error", err) c.queue.AddRateLimited(key) } else { // err != nil and too many retries - log.Errorf("Error updating %s, giving up: %v", key, err) + slog.Error("Error updating, giving up", "key", key, "error", err) c.queue.Forget(key) utilruntime.HandleError(err) } @@ -284,7 +287,7 @@ func (c *Controller) unseal(ctx context.Context, key string) (unsealErr error) { unsealRequestsTotal.Inc() obj, exists, err := c.ssInformer.GetIndexer().GetByKey(key) if err != nil { - log.Errorf("Error fetching object with key %s from store: %v", key, err) + slog.Error("Error fetching object from store", "key", key, "error", err) unsealErrorsTotal.WithLabelValues("fetch", "").Inc() return err } @@ -295,7 +298,7 @@ func (c *Controller) unseal(ctx context.Context, key string) (unsealErr error) { // TODO: remove this feature flag in a subsequent release. if c.oldGCBehavior { - log.Infof("SealedSecret %s has gone, deleting Secret", key) + slog.Info("SealedSecret has gone, deleting Secret", "sealed-secret", key) ns, name, err := cache.SplitMetaNamespaceKey(key) if err != nil { return err @@ -312,7 +315,7 @@ func (c *Controller) unseal(ctx context.Context, key string) (unsealErr error) { if err != nil { return err } - log.Infof("Updating %s", key) + slog.Info("Updating", "key", key) // any exit of this function at this point will cause an update to the status subresource // of the SealedSecret custom resource. The return value of the unseal function is available @@ -321,7 +324,7 @@ func (c *Controller) unseal(ctx context.Context, key string) (unsealErr error) { defer func() { if err := c.updateSealedSecretStatus(ssecret, unsealErr); err != nil { // Non-fatal. Log and continue. - log.Errorf("Error updating SealedSecret %s status: %v", key, err) + slog.Error("Error updating SealedSecret status", "sealed-secret", key, "error", err) unsealErrorsTotal.WithLabelValues("status", ssecret.GetNamespace()).Inc() } else { ObserveCondition(ssecret) diff --git a/pkg/controller/keyregistry.go b/pkg/controller/keyregistry.go index d35872bf3..4bb1d8e75 100644 --- a/pkg/controller/keyregistry.go +++ b/pkg/controller/keyregistry.go @@ -6,11 +6,11 @@ import ( "crypto/x509" "encoding/pem" "fmt" + "log/slog" "sync" "time" "github.com/bitnami-labs/sealed-secrets/pkg/crypto" - "github.com/bitnami-labs/sealed-secrets/pkg/log" "k8s.io/client-go/kubernetes" certUtil "k8s.io/client-go/util/cert" ) @@ -61,8 +61,8 @@ func (kr *KeyRegistry) generateKey(ctx context.Context, validFor time.Duration, if err := kr.registerNewKey(generatedName, key, cert, time.Now()); err != nil { return "", err } - log.Infof("New key written to %s/%s\n", kr.namespace, generatedName) - log.Infof("Certificate is \n%s\n", pem.EncodeToMemory(&pem.Block{Type: certUtil.CertificateBlockType, Bytes: cert.Raw})) + slog.Info("New key written", "namespace", kr.namespace, "name", generatedName) + slog.Info("Certificate generated", "certificate", pem.EncodeToMemory(&pem.Block{Type: certUtil.CertificateBlockType, Bytes: cert.Raw})) return generatedName, nil } diff --git a/pkg/controller/main.go b/pkg/controller/main.go index 0a8841080..2e4919c5a 100644 --- a/pkg/controller/main.go +++ b/pkg/controller/main.go @@ -5,6 +5,7 @@ import ( "crypto/rand" "crypto/x509" "io" + "log/slog" "os" "os/signal" "sort" @@ -25,7 +26,6 @@ import ( "github.com/bitnami-labs/sealed-secrets/pkg/client/clientset/versioned" sealedsecrets "github.com/bitnami-labs/sealed-secrets/pkg/client/clientset/versioned" ssinformers "github.com/bitnami-labs/sealed-secrets/pkg/client/informers/externalversions" - "github.com/bitnami-labs/sealed-secrets/pkg/log" ) var ( @@ -51,6 +51,8 @@ type Flags struct { UpdateStatus bool SkipRecreate bool LogInfoToStdout bool + LogLevel string + LogFormat string PrivateKeyAnnotations string PrivateKeyLabels string } @@ -60,7 +62,7 @@ func initKeyPrefix(keyPrefix string) (string, error) { } func initKeyRegistry(ctx context.Context, client kubernetes.Interface, r io.Reader, namespace, prefix, label string, keysize int) (*KeyRegistry, error) { - log.Infof("Searching for existing private keys") + slog.Info("Searching for existing private keys") secretList, err := client.CoreV1().Secrets(namespace).List(ctx, metav1.ListOptions{ LabelSelector: keySelector.String(), }) @@ -83,12 +85,11 @@ func initKeyRegistry(ctx context.Context, client kubernetes.Interface, r io.Read for _, secret := range items { key, certs, err := readKey(secret) if err != nil { - log.Errorf("Error reading key %s: %v", secret.Name, err) + slog.Error("Error reading key", "secret", secret.Name, "error", err) } if err := keyRegistry.registerNewKey(secret.Name, key, certs[0], certs[0].NotBefore); err != nil { return nil, err } - log.Infof("----- %s", secret.Name) } return keyRegistry, nil } @@ -123,7 +124,7 @@ func initKeyRenewal(ctx context.Context, registry *KeyRegistry, period, validFor // wrapper function to log error thrown by generateKey function keyGenFunc := func() { if _, err := registry.generateKey(ctx, validFor, cn, privateKeyAnnotations, privateKeyLabels); err != nil { - log.Errorf("Failed to generate new key : %v\n", err) + slog.Error("Failed to generate new key", "error", err) } } if period == 0 { @@ -142,9 +143,6 @@ func initKeyRenewal(ctx context.Context, registry *KeyRegistry, period, validFor func Main(f *Flags, version string) error { registerMetrics(version) - if f.LogInfoToStdout { - log.SetInfoToStdout() - } config, err := rest.InClusterConfig() if err != nil { @@ -193,7 +191,7 @@ func Main(f *Flags, version string) error { namespace := v1.NamespaceAll if !f.NamespaceAll || f.AdditionalNamespaces != "" { namespace = myNamespace() - log.Infof("Starting informer for namespace: %s\n", namespace) + slog.Info("Starting informer", "namespace", namespace) } var tweakopts func(*metav1.ListOptions) = nil @@ -221,7 +219,7 @@ func Main(f *Flags, version string) error { for _, ns := range addNS { if _, err := clientset.CoreV1().Namespaces().Get(ctx, ns, metav1.GetOptions{}); err != nil { if errors.IsNotFound(err) { - log.Errorf("Warning: namespace '%s' doesn't exist\n", ns) + slog.Error("namespace doesn't exist", "namespace", ns) continue } return err @@ -233,7 +231,7 @@ func Main(f *Flags, version string) error { } ctlr.oldGCBehavior = f.OldGCBehavior ctlr.updateStatus = f.UpdateStatus - log.Infof("Starting informer for namespace: %s\n", ns) + slog.Info("Starting informer", "namespace", ns) go ctlr.Run(stop) } } diff --git a/pkg/controller/server.go b/pkg/controller/server.go index 0c11f0974..38147481e 100644 --- a/pkg/controller/server.go +++ b/pkg/controller/server.go @@ -4,12 +4,13 @@ import ( "crypto/x509" "encoding/pem" "io" + "log" + "log/slog" "net/http" "time" "github.com/prometheus/client_golang/prometheus/promhttp" - "github.com/bitnami-labs/sealed-secrets/pkg/log" flag "github.com/spf13/pflag" "github.com/throttled/throttled" "github.com/throttled/throttled/store/memstore" @@ -48,14 +49,14 @@ func httpserver(cp certProvider, sc secretChecker, sr secretRotator, burst int, mux.Handle("/v1/verify", Instrument("/v1/verify", httpRateLimiter.RateLimit(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { content, err := io.ReadAll(r.Body) if err != nil { - log.Errorf("Error handling /v1/verify request: %v", err) + slog.Error("Error handling /v1/verify request", "error", err) w.WriteHeader(http.StatusBadRequest) return } valid, err := sc(content) if err != nil { - log.Errorf("Error validating secret: %v", err) + slog.Error("Error validating secret", "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -71,14 +72,14 @@ func httpserver(cp certProvider, sc secretChecker, sr secretRotator, burst int, mux.Handle("/v1/rotate", Instrument("/v1/rotate", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { content, err := io.ReadAll(r.Body) if err != nil { - log.Errorf("Error handling /v1/rotate request: %v", err) + slog.Error("Error handling /v1/rotate request", "error", err) w.WriteHeader(http.StatusBadRequest) return } newSecret, err := sr(content) if err != nil { - log.Errorf("Error rotating secret: %v", err) + slog.Error("Error rotating secret", "error", err) w.WriteHeader(http.StatusInternalServerError) return } @@ -91,7 +92,7 @@ func httpserver(cp certProvider, sc secretChecker, sr secretRotator, burst int, mux.Handle("/v1/cert.pem", Instrument("/v1/cert.pem", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { certs, err := cp() if err != nil { - log.Errorf("cannot get certificates: %v", err) + slog.Error("cannot get certificates", "error", err) http.Error(w, "cannot get certificate", http.StatusInternalServerError) return } @@ -110,10 +111,10 @@ func httpserver(cp certProvider, sc secretChecker, sr secretRotator, burst int, WriteTimeout: *writeTimeout, } - log.Infof("HTTP server serving on %s", server.Addr) + slog.Info("HTTP server serving", "addr", server.Addr) go func() { err := server.ListenAndServe() - log.Errorf("HTTP server exiting: %v", err) + slog.Error("HTTP server exiting", "error", err) }() return &server } @@ -130,10 +131,10 @@ func httpserverMetrics() *http.Server { WriteTimeout: *writeTimeout, } - log.Infof("HTTP metrics server serving on %s", server.Addr) + slog.Info("HTTP metrics server serving", "addr", server.Addr) go func() { err := server.ListenAndServe() - log.Errorf("HTTP metrics server exiting: %v", err) + slog.Error("HTTP metrics server exiting", "error", err) }() return &server } diff --git a/pkg/log/log.go b/pkg/log/log.go index 032bba35c..41e1509cc 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -1,36 +1,53 @@ package log import ( - "log" - "os" + "context" + "io" + "log/slog" ) -var ( - infoLogger *log.Logger - errorLogger *log.Logger -) - -func init() { - infoLogger = log.New(os.Stderr, "", 0) - errorLogger = log.New(os.Stderr, "", 0) +// MultiStreamHandler slog handler for directing different +type MultiStreamHandler struct { + level slog.Level + lowHandler slog.Handler + highHandler slog.Handler } -func SetInfoToStdout() { - infoLogger.SetOutput(os.Stdout) +// New returns new MultiStreamHandler +func New(outLow, outHigh io.Writer, format string, opts *slog.HandlerOptions) *MultiStreamHandler { + if format == "json" { + return &MultiStreamHandler{ + level: opts.Level.Level(), + lowHandler: slog.NewJSONHandler(outLow, opts), + highHandler: slog.NewJSONHandler(outHigh, opts), + } + } + return &MultiStreamHandler{ + level: opts.Level.Level(), + lowHandler: slog.NewTextHandler(outLow, opts), + highHandler: slog.NewTextHandler(outHigh, opts), + } } -func Infof(format string, v ...interface{}) { - infoLogger.Printf(format, v...) +// Enabled check if log level is enabled +func (m *MultiStreamHandler) Enabled(ctx context.Context, level slog.Level) bool { + return level >= m.level.Level() } -func Errorf(format string, v ...interface{}) { - errorLogger.Printf(format, v...) +// Handle pass to Low or High handlers based on log level +func (m *MultiStreamHandler) Handle(ctx context.Context, r slog.Record) error { + if r.Level <= slog.LevelInfo.Level() { + return m.lowHandler.Handle(ctx, r) + } + return m.highHandler.Handle(ctx, r) } -func Fatal(v ...any) { - errorLogger.Fatal(v...) +func (m *MultiStreamHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + // Not used within the code + panic("Not implemented") } -func Panic(v ...any) { - errorLogger.Panic(v...) +func (m *MultiStreamHandler) WithGroup(string) slog.Handler { + // Not used within the code + panic("Not implemented") }