feat: add helper function for logging requeues (#137)

* feat: add helper function for logging requeues

* add tests for LogRequeue function

Author: Diaphteiros

pkg/logging/implementation.go

@@ -132,7 +132,9 @@ func determineZapConfig(loggerConfig *Config) zap.Config {
 	return zapConfig
 }
 
-func levelToVerbosity(level LogLevel) int {
+// LevelToVerbosity converts the given LogLevel to a verbosity level understood by zapr.
+// Unknown LogLevels are silently treated as INFO.
+func LevelToVerbosity(level LogLevel) int {
 	var res int
 	switch level {
 	case DEBUG:

pkg/logging/logger.go

@@ -8,8 +8,10 @@ import (
 	"context"
 	"fmt"
 	"strings"
+	"time"
 
 	"github.com/go-logr/logr"
+	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 )
 
 type Logger struct {
@@ -85,7 +87,7 @@ func ParseLogFormat(raw string) (LogFormat, error) {
 // Enabled tests whether logging at the provided level is enabled.
 // This deviates from the logr Enabled() function, which doesn't take an argument.
 func (l Logger) Enabled(lvl LogLevel) bool {
-	return l.internal.GetSink() != nil && l.internal.GetSink().Enabled(levelToVerbosity(lvl))
+	return l.internal.GetSink() != nil && l.internal.GetSink().Enabled(LevelToVerbosity(lvl))
 }
 
 // Info logs a non-error message with the given key/value pairs as context.
@@ -95,7 +97,7 @@ func (l Logger) Enabled(lvl LogLevel) bool {
 // variable information.  The key/value pairs should alternate string
 // keys and arbitrary values.
 func (l Logger) Info(msg string, keysAndValues ...interface{}) {
-	l.internal.V(levelToVerbosity(INFO)).Info(msg, keysAndValues...)
+	l.internal.V(LevelToVerbosity(INFO)).Info(msg, keysAndValues...)
 }
 
 // Error logs an error, with the given message and key/value pairs as context.
@@ -213,7 +215,7 @@ func NewContextWithDiscard(ctx context.Context) context.Context {
 
 // Debug logs a message at DEBUG level.
 func (l Logger) Debug(msg string, keysAndValues ...interface{}) {
-	l.internal.V(levelToVerbosity(DEBUG)).Info(msg, keysAndValues...)
+	l.internal.V(LevelToVerbosity(DEBUG)).Info(msg, keysAndValues...)
 }
 
 // Log logs at the given log level. It can be used to log at dynamically determined levels.
@@ -252,3 +254,19 @@ func (l Logger) WithNameAndContext(ctx context.Context, name string) (Logger, co
 	ctx = NewContext(ctx, log)
 	return log, ctx
 }
+
+// LogRequeue takes a reconcile.Result and prints a log message on the desired verbosity if the result indicates a requeue.
+// Logs at debug level, unless another verbosity is provided. Any but the first verbosity argument is ignored.
+// No message is logged if no requeue is specified in the reconcile.Result.
+// Returns the provided reconcile.Result unchanged.
+func (l Logger) LogRequeue(rr reconcile.Result, verbosity ...LogLevel) reconcile.Result {
+	if rr.RequeueAfter > 0 {
+		v := DEBUG
+		if len(verbosity) > 0 {
+			v = verbosity[0]
+		}
+		nextRequeueTime := time.Now().Add(rr.RequeueAfter)
+		l.Log(v, "Requeuing object for reconciliation", "after", rr.RequeueAfter.String(), "at", nextRequeueTime.Format(time.RFC3339))
+	}
+	return rr
+}

pkg/logging/logging_suite_test.go

@@ -5,13 +5,17 @@
 package logging_test
 
 import (
+	"fmt"
 	"reflect"
 	"testing"
+	"time"
 
 	"github.com/go-logr/logr"
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
+	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 
+	"github.com/openmcp-project/controller-utils/pkg/collections"
 	"github.com/openmcp-project/controller-utils/pkg/logging"
 )
 
@@ -43,4 +47,117 @@ var _ = Describe("Logging Framework Tests", func() {
 		Expect(reflect.DeepEqual(log, compareToLogger)).To(BeTrue(), "calling log.WithValues should not modify the logger")
 	})
 
+	Context("LogRequeue", func() {
+
+		var log logging.Logger
+		var sink *TestLogSink
+
+		BeforeEach(func() {
+			sink = NewTestLogSink(logging.DEBUG)
+			log = logging.Wrap(logr.New(sink))
+		})
+
+		It("should not log anything if RequeueAfter is 0", func() {
+			log.LogRequeue(reconcile.Result{})
+			Expect(sink.Messages.Size()).To(Equal(0))
+		})
+
+		It("should log a message if RequeueAfter is set", func() {
+			now := time.Now()
+			requeueAfter := 42 * time.Second
+			log.LogRequeue(reconcile.Result{RequeueAfter: requeueAfter})
+			Expect(sink.Messages.Size()).To(Equal(1))
+			msg := sink.Messages.Poll()
+			Expect(msg.Verbosity).To(Equal(logging.LevelToVerbosity(logging.DEBUG)))
+			Expect(msg.Message).To(Equal("Requeuing object for reconciliation"))
+			Expect(msg.KeysAndVals).To(HaveKeyWithValue("after", requeueAfter.String()))
+			Expect(msg.KeysAndVals).To(HaveKey("at"))
+			at, err := time.Parse(time.RFC3339, msg.KeysAndVals["at"].(string))
+			Expect(err).NotTo(HaveOccurred())
+			Expect(at).To(BeTemporally("~", now.Add(requeueAfter), time.Second))
+		})
+
+		It("should log at the provided verbosity level", func() {
+			now := time.Now()
+			requeueAfter := 42 * time.Second
+			log.LogRequeue(reconcile.Result{RequeueAfter: requeueAfter}, logging.INFO)
+			Expect(sink.Messages.Size()).To(Equal(1))
+			msg := sink.Messages.Poll()
+			Expect(msg.Verbosity).To(Equal(logging.LevelToVerbosity(logging.INFO)))
+			Expect(msg.Message).To(Equal("Requeuing object for reconciliation"))
+			Expect(msg.KeysAndVals).To(HaveKeyWithValue("after", requeueAfter.String()))
+			Expect(msg.KeysAndVals).To(HaveKey("at"))
+			at, err := time.Parse(time.RFC3339, msg.KeysAndVals["at"].(string))
+			Expect(err).NotTo(HaveOccurred())
+			Expect(at).To(BeTemporally("~", now.Add(requeueAfter), time.Second))
+		})
+
+	})
+
 })
+
+func NewTestLogSink(level logging.LogLevel) *TestLogSink {
+	return &TestLogSink{
+		Messages:     collections.NewLinkedList[*LogMessage](),
+		enabledLevel: level,
+	}
+}
+
+type TestLogSink struct {
+	Messages     collections.Queue[*LogMessage]
+	enabledLevel logging.LogLevel
+}
+
+type LogMessage struct {
+	Error       error
+	Verbosity   int
+	Message     string
+	KeysAndVals map[string]any
+}
+
+// Enabled implements logr.LogSink.
+func (t *TestLogSink) Enabled(level int) bool {
+	return t.enabledLevel >= logging.LogLevel(level)
+}
+
+// Error implements logr.LogSink.
+func (t *TestLogSink) Error(err error, msg string, keysAndValues ...any) {
+	t.log(int(logging.ERROR), err, msg, keysAndValues...)
+}
+
+// Info implements logr.LogSink.
+func (t *TestLogSink) Info(level int, msg string, keysAndValues ...any) {
+	t.log(level, nil, msg, keysAndValues...)
+}
+
+func (t *TestLogSink) log(verbosity int, err error, msg string, keysAndValues ...any) {
+	kv := make(map[string]any, (len(keysAndValues)+1)/2)
+	for i := 0; i < len(keysAndValues)-1; i += 2 {
+		k, ok := keysAndValues[i].(string)
+		if !ok {
+			k = fmt.Sprint(keysAndValues[i])
+		}
+		kv[k] = keysAndValues[i+1]
+	}
+	_ = t.Messages.Push(&LogMessage{
+		Error:       err,
+		Verbosity:   verbosity,
+		Message:     msg,
+		KeysAndVals: kv,
+	})
+}
+
+// Init implements logr.LogSink.
+func (t *TestLogSink) Init(_ logr.RuntimeInfo) {}
+
+// WithName implements logr.LogSink.
+func (t *TestLogSink) WithName(name string) logr.LogSink {
+	panic("not implemented")
+}
+
+// WithValues implements logr.LogSink.
+func (t *TestLogSink) WithValues(keysAndValues ...any) logr.LogSink {
+	panic("not implemented")
+}
+
+var _ logr.LogSink = &TestLogSink{}