Merge pull request #121 from hyp3rd/feat/dist-mem-cache

feat(observability): add structured slog logging to eviction/expiration loops and cluster lifecycle

Author: hyp3rd

CHANGELOG.md

@@ -377,6 +377,10 @@ func buildHyperCache(ctx context.Context, cfg envConfig, logger *slog.Logger) (*
 			hypercache.WithMgmtAuth(mgmtReadAuth),
 			hypercache.WithMgmtControlAuth(mgmtAdminAuth),
 		),
+		// Surfaces eviction/expiration loop start, per-tick activity,
+		// and the cluster-join startup summary in the binary's JSON
+		// log stream. Without this the HyperCache wrapper runs silent.
+		hypercache.WithLogger[backend.DistMemory](logger),
 	)
 
 	hc, err := hypercache.New(ctx, hypercache.GetDefaultManager(), hcCfg)

cmd/hypercache-server/main.go

@@ -12,6 +12,7 @@
 package hypercache
 
 import (
+	"log/slog"
 	"strings"
 	"time"
 
@@ -164,6 +165,32 @@ func WithEvictionInterval[T backend.IBackendConstrain](evictionInterval time.Dur
 	}
 }
 
+// WithLogger sets the structured logger used by HyperCache for background-
+// loop and lifecycle events: eviction-loop trigger, expiration-loop trigger,
+// management HTTP server startup, and (when paired with a DistMemory
+// backend) the cluster-shape summary at boot.
+//
+// Defaults to a discard handler so library-mode embedded uses stay silent.
+// The hypercache-server binary wires its own slog.Logger here so operators
+// see structured JSON for every background task without needing the OTel
+// metrics pipeline. Pass nil to reset to the default discard handler.
+//
+// Note: the DistMemory backend has its own WithDistLogger option for
+// distributed-transport events (heartbeat, hint replay, rebalance). The
+// two are intentionally separate so an embedded user can silence one
+// surface without affecting the other.
+func WithLogger[T backend.IBackendConstrain](logger *slog.Logger) Option[T] {
+	return func(cache *HyperCache[T]) {
+		if logger == nil {
+			cache.logger = slog.New(slog.DiscardHandler)
+
+			return
+		}
+
+		cache.logger = logger
+	}
+}
+
 // WithExpirationTriggerBuffer sets the buffer size of the expiration trigger channel.
 // If set to <= 0, the default (capacity/2, minimum 1) is used.
 func WithExpirationTriggerBuffer[T backend.IBackendConstrain](size int) Option[T] {

config.go

@@ -9,6 +9,7 @@ package hypercache
 
 import (
 	"context"
+	"log/slog"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -72,6 +73,12 @@ type HyperCache[T backend.IBackendConstrain] struct {
 	StatsCollector stats.ICollector
 	// Optional management HTTP server
 	mgmtHTTP *ManagementHTTPServer
+	// Structured logger. Defaults to a no-op (slog.New(slog.DiscardHandler))
+	// so the cache stays silent unless the operator opts into observability
+	// via WithLogger. Used for background-loop start/tick and for cache-
+	// lifecycle events that operators want to follow without standing up
+	// the OTel metrics pipeline.
+	logger *slog.Logger
 }
 
 // touchBackend is the optional interface a backend implements when it wants

hypercache.go

@@ -2,6 +2,7 @@ package hypercache
 
 import (
 	"context"
+	"log/slog"
 	"runtime"
 	"time"
 
@@ -134,6 +135,11 @@ func newHyperCacheBase[T backend.IBackendConstrain](b backend.IBackend[T]) *Hype
 		// key's data shard and eviction shard map to the same logical position.
 		// Users can override with WithEvictionShardCount; <=1 disables sharding.
 		evictionShardCount: cache.ShardCount,
+		// Default to a discard handler so library-mode embedded uses stay
+		// silent unless the operator opts in via WithLogger. The
+		// hypercache-server binary wires a structured slog.Logger here so
+		// background-loop and cluster lifecycle events surface in JSON.
+		logger: slog.New(slog.DiscardHandler),
 	}
 }
 

hypercache_construct.go

@@ -2,6 +2,7 @@ package hypercache
 
 import (
 	"context"
+	"log/slog"
 	"time"
 
 	"github.com/hyp3rd/sectools/pkg/converters"
@@ -61,6 +62,13 @@ func (hyperCache *HyperCache[T]) startEvictionRoutine(ctx context.Context) {
 		return
 	}
 
+	hyperCache.logger.Info(
+		"eviction loop starting",
+		slog.Duration("interval", hyperCache.evictionInterval),
+		slog.Int("max_per_tick", int(hyperCache.maxEvictionCount)),
+		slog.String("algorithm", hyperCache.evictionAlgorithmName),
+	)
+
 	tick := time.NewTicker(hyperCache.evictionInterval)
 
 	go func() {
@@ -70,11 +78,13 @@ func (hyperCache *HyperCache[T]) startEvictionRoutine(ctx context.Context) {
 				hyperCache.evictionLoop(ctx)
 			case <-ctx.Done():
 				tick.Stop()
+				hyperCache.logger.Info("eviction loop stopped", slog.String("reason", "context_canceled"))
 
 				return
 
 			case <-hyperCache.stop:
 				tick.Stop()
+				hyperCache.logger.Info("eviction loop stopped", slog.String("reason", "stop_signal"))
 
 				return
 			}
@@ -89,6 +99,9 @@ func (hyperCache *HyperCache[T]) evictionLoop(ctx context.Context) {
 	// Enqueue the eviction loop in the worker pool to avoid blocking the main goroutine if the eviction loop is slow
 	hyperCache.workerPool.Enqueue(func() error {
 		hyperCache.StatsCollector.Incr("eviction_loop_count", 1)
+
+		start := time.Now()
+
 		defer hyperCache.StatsCollector.Timing("eviction_loop_duration", time.Now().UnixNano())
 
 		var evictedCount uint
@@ -133,10 +146,35 @@ func (hyperCache *HyperCache[T]) evictionLoop(ctx context.Context) {
 
 		hyperCache.StatsCollector.Gauge("evicted_item_count", evictedCount64)
 
+		hyperCache.logEvictionTick(evictedCount, itemCount, time.Since(start))
+
 		return nil
 	})
 }
 
+// logEvictionTick emits a single-line tick log so operators can grep
+// for `eviction tick`. Info when items were evicted, Debug for idle
+// ticks — the metric counters cover the idle case so we don't drown
+// logs in noise.
+func (hyperCache *HyperCache[T]) logEvictionTick(evicted uint, remaining int64, elapsed time.Duration) {
+	if evicted > 0 {
+		hyperCache.logger.Info(
+			"eviction tick",
+			slog.Uint64("evicted", uint64(evicted)),
+			slog.Int64("items_remaining", remaining),
+			slog.Duration("elapsed", elapsed),
+		)
+
+		return
+	}
+
+	hyperCache.logger.Debug(
+		"eviction tick (idle)",
+		slog.Int64("items", remaining),
+		slog.Duration("elapsed", elapsed),
+	)
+}
+
 // evictItem is a helper function that removes an item from the cache and returns the key of the evicted item.
 // If no item can be evicted, it returns a false.
 func (hyperCache *HyperCache[T]) evictItem(ctx context.Context) (string, bool) {
@@ -177,6 +215,11 @@ func (hyperCache *HyperCache[T]) TriggerEviction(_ context.Context) {
 
 	select {
 	case hyperCache.evictCh <- true:
+		hyperCache.logger.Info("eviction triggered", slog.String("source", "manual"))
 	default:
+		// Trigger channel full; previous trigger already in-flight.
+		// Log at debug — the coalesced trigger is intentional, not
+		// an error worth waking the operator over.
+		hyperCache.logger.Debug("eviction trigger coalesced (already pending)")
 	}
 }

hypercache_eviction.go

@@ -2,6 +2,7 @@ package hypercache
 
 import (
 	"context"
+	"log/slog"
 	"time"
 
 	"github.com/hyp3rd/hypercache/internal/constants"
@@ -11,6 +12,12 @@ import (
 
 // startExpirationRoutine launches the expiration loop and listens to manual triggers and stop signals.
 func (hyperCache *HyperCache[T]) startExpirationRoutine(ctx context.Context) {
+	hyperCache.logger.Info(
+		"expiration loop starting",
+		slog.Duration("interval", hyperCache.expirationInterval),
+		slog.Duration("debounce", hyperCache.expirationDebounceInterval),
+	)
+
 	go func() {
 		var tick *time.Ticker
 
@@ -61,13 +68,17 @@ func (hyperCache *HyperCache[T]) handleExpirationSelect(ctx context.Context, tic
 			tick.Stop()
 		}
 
+		hyperCache.logger.Info("expiration loop stopped", slog.String("reason", "context_canceled"))
+
 		return true
 
 	case <-hyperCache.stop:
 		if tick != nil {
 			tick.Stop()
 		}
 
+		hyperCache.logger.Info("expiration loop stopped", slog.String("reason", "stop_signal"))
+
 		return true
 	}
 
@@ -107,6 +118,9 @@ func (hyperCache *HyperCache[T]) execTriggerExpiration() {
 func (hyperCache *HyperCache[T]) expirationLoop(ctx context.Context) {
 	hyperCache.workerPool.Enqueue(func() error {
 		hyperCache.StatsCollector.Incr("expiration_loop_count", 1)
+
+		start := time.Now()
+
 		defer hyperCache.StatsCollector.Timing("expiration_loop_duration", time.Now().UnixNano())
 
 		var (
@@ -138,9 +152,28 @@ func (hyperCache *HyperCache[T]) expirationLoop(ctx context.Context) {
 			hyperCache.StatsCollector.Incr("item_expired_count", 1)
 		}
 
-		hyperCache.StatsCollector.Gauge("item_count", int64(hyperCache.backend.Count(ctx)))
+		itemCount := int64(hyperCache.backend.Count(ctx))
+		hyperCache.StatsCollector.Gauge("item_count", itemCount)
 		hyperCache.StatsCollector.Gauge("expired_item_count", expiredCount)
 
+		// Mirror the eviction-tick shape: Info only when there's
+		// actual work, Debug for idle ticks so background noise
+		// doesn't drown out the events operators care about.
+		if expiredCount > 0 {
+			hyperCache.logger.Info(
+				"expiration tick",
+				slog.Int64("expired", expiredCount),
+				slog.Int64("items_remaining", itemCount),
+				slog.Duration("elapsed", time.Since(start)),
+			)
+		} else {
+			hyperCache.logger.Debug(
+				"expiration tick (idle)",
+				slog.Int64("items", itemCount),
+				slog.Duration("elapsed", time.Since(start)),
+			)
+		}
+
 		return nil
 	})
 }