From e843d115962fb217712a6ee1f24be46d526040bd Mon Sep 17 00:00:00 2001
From: Oleg Kunitsyn <114359669+hiddenmarten@users.noreply.github.com>
Date: Thu, 12 Dec 2024 04:18:07 +0100
Subject: [PATCH] feat: Introduce logs in json format using log/slog (#102)

* 99: Introduce global logger using log/slog and update debug messages with it

* 99: Update all log messages using global logger, eliminate log dependency

* 99: Add bracket
---
 main.go | 49 ++++++++++++++++++++++++++++++-------------------
 1 file changed, 30 insertions(+), 19 deletions(-)

diff --git a/main.go b/main.go
index a16b437..b2dd604 100644
--- a/main.go
+++ b/main.go
@@ -4,7 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
+	"log/slog"
 	"os"
 	"strings"
 	"time"
@@ -36,9 +36,24 @@ var (
 	listTimeoutSeconds     = int64(60)
 	executionFailedCounter = 0
 
-	debug = os.Getenv("DEBUG") == "true"
+	logger       *slog.Logger  // Global logger
+	programLevel slog.LevelVar // Info by default
 )
 
+func init() {
+	// Create a new logger, either in JSON or text format
+	if os.Getenv("JSON_LOG") == "true" {
+		logger = slog.New(slog.NewJSONHandler(os.Stderr, nil))
+	} else {
+		logger = slog.New(slog.NewTextHandler(os.Stderr, nil))
+	}
+
+	// Set the log level based on the DEBUG environment variable
+	if os.Getenv("DEBUG") == "true" {
+		programLevel.Set(slog.LevelDebug)
+	}
+}
+
 func main() {
 	for {
 		start := time.Now()
@@ -47,17 +62,17 @@ func main() {
 			panic("failed to create Kubernetes clients: " + err.Error())
 		}
 		eventManager := kevent.NewEventManager(kubernetesClient, "k8s-ttl-controller")
-		if err := Reconcile(kubernetesClient, dynamicClient, eventManager); err != nil {
-			log.Printf("Error during execution: %s", err.Error())
+		if err = Reconcile(kubernetesClient, dynamicClient, eventManager); err != nil {
+			logger.Info(fmt.Sprintf("Error during execution: %s", err.Error()))
 			executionFailedCounter++
 			if executionFailedCounter > MaximumFailedExecutionBeforePanic {
 				panic(fmt.Errorf("execution failed %d times: %w", executionFailedCounter, err))
 			}
 		} else if executionFailedCounter > 0 {
-			log.Printf("Execution was successful after %d failed attempts, resetting counter to 0", executionFailedCounter)
+			logger.Info(fmt.Sprintf("Execution was successful after %d failed attempts, resetting counter to 0", executionFailedCounter))
 			executionFailedCounter = 0
 		}
-		log.Printf("Execution took %dms, sleeping for %s", time.Since(start).Milliseconds(), ExecutionInterval)
+		logger.Info(fmt.Sprintf("Execution took %dms, sleeping for %s", time.Since(start).Milliseconds(), ExecutionInterval))
 		time.Sleep(ExecutionInterval)
 	}
 }
@@ -71,9 +86,7 @@ func Reconcile(kubernetesClient kubernetes.Interface, dynamicClient dynamic.Inte
 	if err != nil {
 		return err
 	}
-	if debug {
-		log.Println("[Reconcile] Found", len(resources), "API resources")
-	}
+	logger.Debug(fmt.Sprintf("[Reconcile] Found %d API resources", len(resources)))
 	timeout := make(chan bool, 1)
 	result := make(chan bool, 1)
 	go func() {
@@ -98,7 +111,7 @@ func getStartTime(item unstructured.Unstructured) metav1.Time {
 		if err == nil {
 			return metav1.NewTime(t)
 		}
-		log.Printf("Failed to parse refreshed-at timestamp '%s' for %s/%s: %s", refreshedAt, item.GetKind(), item.GetName(), err)
+		logger.Info("Failed to parse refreshed-at timestamp '%s' for %s/%s: %s", refreshedAt, item.GetKind(), item.GetName(), err)
 	}
 	return item.GetCreationTimestamp()
 }
@@ -134,15 +147,13 @@ func DoReconcile(dynamicClient dynamic.Interface, eventManager *kevent.EventMana
 			for list == nil || continueToken != "" {
 				list, err = dynamicClient.Resource(gvr).List(context.TODO(), metav1.ListOptions{TimeoutSeconds: &listTimeoutSeconds, Continue: continueToken, Limit: ListLimit})
 				if err != nil {
-					log.Printf("Error checking %s from %s: %s", gvr.Resource, gvr.GroupVersion(), err)
+					logger.Info(fmt.Sprintf("Error checking %s from %s: %s", gvr.Resource, gvr.GroupVersion(), err))
 					continue
 				}
 				if list != nil {
 					continueToken = list.GetContinue()
 				}
-				if debug {
-					log.Println("Checking", len(list.Items), gvr.Resource, "from", gvr.GroupVersion())
-				}
+				logger.Debug(fmt.Sprintf("Checking %d %s from %s", len(list.Items), gvr.Resource, gvr.GroupVersion()))
 				for _, item := range list.Items {
 					ttl, exists := item.GetAnnotations()[AnnotationTTL]
 					if !exists {
@@ -150,26 +161,26 @@ func DoReconcile(dynamicClient dynamic.Interface, eventManager *kevent.EventMana
 					}
 					ttlInDuration, err = str2duration.ParseDuration(ttl)
 					if err != nil {
-						log.Printf("[%s/%s] has an invalid TTL '%s': %s\n", apiResource.Name, item.GetName(), ttl, err)
+						logger.Info(fmt.Sprintf("[%s/%s] has an invalid TTL '%s': %s", apiResource.Name, item.GetName(), ttl, err))
 						continue
 					}
 					ttlExpired := time.Now().After(getStartTime(item).Add(ttlInDuration))
 					if ttlExpired {
 						durationSinceExpired := time.Since(getStartTime(item).Add(ttlInDuration)).Round(time.Second)
-						log.Printf("[%s/%s] is configured with a TTL of %s, which means it has expired %s ago", apiResource.Name, item.GetName(), ttl, durationSinceExpired)
+						logger.Info(fmt.Sprintf("[%s/%s] is configured with a TTL of %s, which means it has expired %s ago", apiResource.Name, item.GetName(), ttl, durationSinceExpired))
 						err = dynamicClient.Resource(gvr).Namespace(item.GetNamespace()).Delete(context.TODO(), item.GetName(), metav1.DeleteOptions{})
 						if err != nil {
-							log.Printf("[%s/%s] failed to delete: %s\n", apiResource.Name, item.GetName(), err)
+							logger.Info(fmt.Sprintf("[%s/%s] failed to delete: %s", apiResource.Name, item.GetName(), err))
 							eventManager.Create(item.GetNamespace(), item.GetKind(), item.GetName(), "FailedToDeleteExpiredTTL", "Unable to delete expired resource:"+err.Error(), true)
 							// XXX: Should we retry with GracePeriodSeconds set to &0 to force immediate deletion after the first attempt failed?
 						} else {
-							log.Printf("[%s/%s] deleted", apiResource.Name, item.GetName())
+							logger.Info(fmt.Sprintf("[%s/%s] deleted", apiResource.Name, item.GetName()))
 							eventManager.Create(item.GetNamespace(), item.GetKind(), item.GetName(), "DeletedExpiredTTL", "Deleted resource because "+ttl+" or more has elapsed", false)
 						}
 						// Cool off a tiny bit to avoid hitting the API too often
 						time.Sleep(ThrottleDuration)
 					} else {
-						log.Printf("[%s/%s] is configured with a TTL of %s, which means it will expire in %s", apiResource.Name, item.GetName(), ttl, time.Until(getStartTime(item).Add(ttlInDuration)).Round(time.Second))
+						logger.Info(fmt.Sprintf("[%s/%s] is configured with a TTL of %s, which means it will expire in %s", apiResource.Name, item.GetName(), ttl, time.Until(getStartTime(item).Add(ttlInDuration)).Round(time.Second)))
 					}
 				}
 				// Cool off a tiny bit to avoid hitting the API too often