Introduce logs in json format using logrus

go.mod

@@ -33,6 +33,7 @@ require (
 	github.com/modern-go/reflect2 v1.0.2 // indirect
 	github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect
 	github.com/pkg/errors v0.9.1 // indirect
+	github.com/sirupsen/logrus v1.9.3 // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
 	github.com/x448/float16 v0.8.4 // indirect
 	golang.org/x/net v0.26.0 // indirect

go.sum

@@ -73,12 +73,15 @@ github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRI
 github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8=
 github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4=
+github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
+github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
 github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
+github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
@@ -111,6 +114,7 @@ golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJ
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.21.0 h1:rF+pYz3DAGSQAxAu1CbC7catZg4ebC4UIeIhKxBZvws=
 golang.org/x/sys v0.21.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/term v0.21.0 h1:WVXCp+/EBEHOj53Rvu+7KiT/iElMrO8ACK16SMZ3jaA=

main.go

@@ -3,13 +3,12 @@ package main
 import (
 	"context"
 	"errors"
-	"fmt"
-	"log"
 	"os"
 	"strings"
 	"time"
 
 	"github.com/TwiN/kevent"
+	"github.com/sirupsen/logrus"
 	str2duration "github.com/xhit/go-str2duration/v2"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
@@ -36,28 +35,42 @@ var (
 	listTimeoutSeconds     = int64(60)
 	executionFailedCounter = 0
 
-	debug = os.Getenv("DEBUG") == "true"
+	debug    = os.Getenv("DEBUG") == "true"
+	jsonLogs = os.Getenv("JSON_LOGS") == "true"
 )
 
+func init() {
+	if jsonLogs {
+		logrus.SetFormatter(&logrus.JSONFormatter{})
+	} else {
+		logrus.SetFormatter(&logrus.TextFormatter{})
+	}
+	if debug {
+		logrus.SetLevel(logrus.DebugLevel)
+	} else {
+		logrus.SetLevel(logrus.InfoLevel)
+	}
+}
+
 func main() {
 	for {
 		start := time.Now()
 		kubernetesClient, dynamicClient, err := CreateClients()
 		if err != nil {
-			panic("failed to create Kubernetes clients: " + err.Error())
+			logrus.WithError(err).Panic("failed to create Kubernetes clients")
 		}
 		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 {
+			logrus.WithError(err).Error("Error during execution")
 			executionFailedCounter++
 			if executionFailedCounter > MaximumFailedExecutionBeforePanic {
-				panic(fmt.Errorf("execution failed %d times: %w", executionFailedCounter, err))
+				logrus.WithError(err).Panicf("execution failed %d times", executionFailedCounter)
 			}
 		} else if executionFailedCounter > 0 {
-			log.Printf("Execution was successful after %d failed attempts, resetting counter to 0", executionFailedCounter)
+			logrus.Infof("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)
+		logrus.Infof("Execution took %dms, sleeping for %s", time.Since(start).Milliseconds(), ExecutionInterval)
 		time.Sleep(ExecutionInterval)
 	}
 }
@@ -72,7 +85,7 @@ func Reconcile(kubernetesClient kubernetes.Interface, dynamicClient dynamic.Inte
 		return err
 	}
 	if debug {
-		log.Println("[Reconcile] Found", len(resources), "API resources")
+		logrus.Debugf("[Reconcile] Found %d API resources", len(resources))
 	}
 	timeout := make(chan bool, 1)
 	result := make(chan bool, 1)
@@ -98,7 +111,10 @@ 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)
+		logrus.WithFields(logrus.Fields{
+			"kind": item.GetKind(),
+			"name": item.GetName(),
+		}).Warnf("Failed to parse refreshed-at timestamp '%s': %s", refreshedAt, err)
 	}
 	return item.GetCreationTimestamp()
 }
@@ -134,14 +150,17 @@ 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)
+					logrus.WithFields(logrus.Fields{
+						"resource":     gvr.Resource,
+						"groupVersion": gvr.GroupVersion(),
+					}).Errorf("Error checking: %s", err)
 					continue
 				}
 				if list != nil {
 					continueToken = list.GetContinue()
 				}
 				if debug {
-					log.Println("Checking", len(list.Items), gvr.Resource, "from", gvr.GroupVersion())
+					logrus.Debugf("Checking %d %s from %s", len(list.Items), gvr.Resource, gvr.GroupVersion())
 				}
 				for _, item := range list.Items {
 					ttl, exists := item.GetAnnotations()[AnnotationTTL]
@@ -150,26 +169,44 @@ 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)
+						logrus.WithFields(logrus.Fields{
+							"resource": apiResource.Name,
+							"name":     item.GetName(),
+						}).Warnf("Invalid TTL '%s': %s", 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)
+						logrus.WithFields(logrus.Fields{
+							"resource":     apiResource.Name,
+							"name":         item.GetName(),
+							"ttl":          ttl,
+							"expiredSince": durationSinceExpired,
+						}).Info("Resource has expired")
 						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)
+							logrus.WithFields(logrus.Fields{
+								"resource": apiResource.Name,
+								"name":     item.GetName(),
+							}).Errorf("Failed to delete: %s", 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())
+							logrus.WithFields(logrus.Fields{
+								"resource": apiResource.Name,
+								"name":     item.GetName(),
+							}).Info("Resource deleted")
 							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(item.GetCreationTimestamp().Add(ttlInDuration)).Round(time.Second))
+						logrus.WithFields(logrus.Fields{
+							"resource":  apiResource.Name,
+							"name":      item.GetName(),
+							"ttl":       ttl,
+							"expiresIn": time.Until(item.GetCreationTimestamp().Add(ttlInDuration)).Round(time.Second),
+						}).Info("Resource will expire")
 					}
 				}
 				// Cool off a tiny bit to avoid hitting the API too often