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 <[email protected]>
bitnami-labs · Jan 26, 2024 · 40c279f · vavsab · Mar 12, 2024 · agarcia-oss
1 parent 9edf747
commit 40c279f
Show file tree

Hide file tree

Showing 9 changed files with 112 additions and 62 deletions.
diff --git a/cmd/controller/main.go b/cmd/controller/main.go
@@ -4,14 +4,15 @@ import (
 	goflag "flag"
 	"fmt"
 	"io"
-	"log"
+	"log/slog"
 	"os"
 	"time"
 
 	flag "github.com/spf13/pflag"
 
 	"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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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)
 			}
 		}