From d7ea773d41a0ff9048ba1dd9c7fe75e75ca6c16d Mon Sep 17 00:00:00 2001
From: "Dr. Stefan Schimanski" <stefan.schimanski@gmail.com>
Date: Tue, 21 Nov 2023 19:57:30 +0100
Subject: [PATCH] bbolt-cache: debug log when cleaning objects, and throttle to
 once per 1s

Signed-off-by: Dr. Stefan Schimanski <stefan.schimanski@gmail.com>
---
 cmd/xgql/main.go              |  2 +-
 internal/cache/bbolt_cache.go | 12 +++++++++++-
 internal/cache/cleaner.go     | 20 +++++++++++++++++++-
 3 files changed, 31 insertions(+), 3 deletions(-)

diff --git a/cmd/xgql/main.go b/cmd/xgql/main.go
index 46109ea..831d47f 100644
--- a/cmd/xgql/main.go
+++ b/cmd/xgql/main.go
@@ -216,7 +216,7 @@ func main() { //nolint:gocyclo
 	var camid []clients.NewCacheMiddlewareFn
 	// wrap client.Cache in cache.*BBoltCache if cacheFile is specified.
 	if *cacheFile != "" {
-		camid = append(camid, cache.WithBBoltCache(*cacheFile))
+		camid = append(camid, cache.WithBBoltCache(*cacheFile, cache.WithLogger(log)))
 	}
 	// enable live queries
 	camid = append(camid, clients.WithLiveQueries)
diff --git a/internal/cache/bbolt_cache.go b/internal/cache/bbolt_cache.go
index be67821..3b92a65 100644
--- a/internal/cache/bbolt_cache.go
+++ b/internal/cache/bbolt_cache.go
@@ -40,6 +40,7 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/client/apiutil"
 
 	"github.com/crossplane/crossplane-runtime/pkg/errors"
+	"github.com/crossplane/crossplane-runtime/pkg/logging"
 
 	"github.com/upbound/xgql/internal/clients"
 )
@@ -152,6 +153,13 @@ func wrapCacheTranform(prev, next toolscache.TransformFunc) toolscache.Transform
 // Option is an option for a cache.
 type Option func(*BBoltCache)
 
+// WithLogger wires a logger into the bbolt cache.
+func WithLogger(o logging.Logger) Option {
+	return func(c *BBoltCache) {
+		c.log = o
+	}
+}
+
 // Cache implements cache.Cache.
 var _ cache.Cache = &BBoltCache{}
 
@@ -173,6 +181,8 @@ type BBoltCache struct {
 	unmarshalFn UnmarshalFn
 
 	running atomic.Bool
+
+	log logging.Logger
 }
 
 // NewBBoltCache creates a new cache.
@@ -196,7 +206,7 @@ func NewBBoltCache(cache cache.Cache, scheme *runtime.Scheme, file string, opts
 		ca.db = db
 	}
 	if ca.cleaner == nil {
-		ca.cleaner = NewCleaner[client.Object, string](getKey, ca.cleanup)
+		ca.cleaner = NewCleaner[client.Object, string](getKey, ca.cleanup, WithLoggerCleanerOpt[client.Object, string](ca.log))
 	}
 	return ca, nil
 }
diff --git a/internal/cache/cleaner.go b/internal/cache/cleaner.go
index 60e575a..b918d34 100644
--- a/internal/cache/cleaner.go
+++ b/internal/cache/cleaner.go
@@ -24,6 +24,8 @@ import (
 	"time"
 
 	"k8s.io/utils/clock"
+
+	"github.com/crossplane/crossplane-runtime/pkg/logging"
 )
 
 // Cleaner cleans up objects after a given duration.
@@ -92,10 +94,19 @@ type cleaner[T any, K cmp.Ordered] struct {
 	mu      sync.Mutex
 	exps    []expKey[K]
 	refs    map[K]expRef[T]
+
+	log logging.Logger
 }
 
 type CleanerOpt[T any, K cmp.Ordered] func(*cleaner[T, K])
 
+// WithLoggerCleanerOpt wires the logger into the cleaner.
+func WithLoggerCleanerOpt[T any, K cmp.Ordered](log logging.Logger) CleanerOpt[T, K] {
+	return func(c *cleaner[T, K]) {
+		c.log = log
+	}
+}
+
 // NewCleaner creates a cleaner for objects of type T, identified by comparable key K,
 // using cleanFn for cleanup.
 func NewCleaner[T any, K cmp.Ordered](keyFn func(T) K, cleanFn func([]T) error, opts ...CleanerOpt[T, K]) *cleaner[T, K] {
@@ -105,6 +116,7 @@ func NewCleaner[T any, K cmp.Ordered](keyFn func(T) K, cleanFn func([]T) error,
 		clock:   clock.RealClock{},
 		signal:  make(chan struct{}),
 		refs:    make(map[K]expRef[T]),
+		log:     logging.NewNopLogger(),
 	}
 	for _, opt := range opts {
 		opt(c)
@@ -142,12 +154,18 @@ func (c *cleaner[T, K]) Start(ctx context.Context) error {
 		}
 		objs, exp := c.collect(c.clock.Now())
 		if len(objs) > 0 {
+			c.log.Debug("cleaning up objects", "count", len(objs), "next", exp)
 			if err := c.cleanFn(objs); err != nil {
+				// exit Start and stop the cache
 				return err
 			}
 		}
 		if !exp.IsZero() {
-			wakeup = c.clock.After(exp.Sub(c.clock.Now()))
+			after := exp.Sub(c.clock.Now())
+			if after < time.Second {
+				after = time.Second
+			}
+			wakeup = c.clock.After(after)
 		}
 	}
 }