From 91d52a4579e723d271047ac8a6ceed236a6eb931 Mon Sep 17 00:00:00 2001 From: Johannes Aubart Date: Fri, 5 Sep 2025 13:39:00 +0200 Subject: [PATCH 1/2] feat: add helper function for logging requeues --- pkg/logging/logger.go | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/pkg/logging/logger.go b/pkg/logging/logger.go index 7120116..13a1420 100644 --- a/pkg/logging/logger.go +++ b/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 { @@ -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 +} From 7b70a5363226325e4f2c0c9de7aaebb5285e35de Mon Sep 17 00:00:00 2001 From: Johannes Aubart Date: Fri, 5 Sep 2025 16:46:38 +0200 Subject: [PATCH 2/2] add tests for LogRequeue function --- pkg/logging/implementation.go | 4 +- pkg/logging/logger.go | 6 +- pkg/logging/logging_suite_test.go | 117 ++++++++++++++++++++++++++++++ 3 files changed, 123 insertions(+), 4 deletions(-) diff --git a/pkg/logging/implementation.go b/pkg/logging/implementation.go index f7cf585..e211713 100644 --- a/pkg/logging/implementation.go +++ b/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: diff --git a/pkg/logging/logger.go b/pkg/logging/logger.go index 13a1420..461b173 100644 --- a/pkg/logging/logger.go +++ b/pkg/logging/logger.go @@ -87,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. @@ -97,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. @@ -215,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. diff --git a/pkg/logging/logging_suite_test.go b/pkg/logging/logging_suite_test.go index 7f5a48d..3d06297 100644 --- a/pkg/logging/logging_suite_test.go +++ b/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{}