Skip to content

Commit e803fc0

Browse files
committed
feat(observability): add structured slog logging to eviction/expiration loops and cluster lifecycle
Introduce a `WithLogger[T](*slog.Logger)` option on `HyperCache` that wires a structured `slog.Logger` through the wrapper's background loops and lifecycle surfaces. Previously the eviction loop, expiration loop, and cluster-join startup ran fully silent, requiring operators to infer activity from counters. Changes: - `eviction loop starting/stopped` logged with interval, max_per_tick, and algorithm; per-tick `eviction tick` at Info when items evicted, Debug when idle; `eviction triggered` on manual `TriggerEviction` calls with coalesced triggers at Debug. - `expiration loop starting/stopped`; per-tick `expiration tick` with the same Info/Debug shape. - `peer added/removed to membership` records in DistMemory so dynamic cluster joins are visible to log-based observers. - `hypercache-server` binary wired via `WithLogger` so new records surface in the binary's JSON output alongside existing dist-transport logs. Defaults to `slog.DiscardHandler` so library-mode embedded uses stay silent. Passing nil resets to the discard handler. Tests in `hypercache_logging_test.go` assert the eviction/expiration startup contract on a real cache instance with a JSON-captured logger; `tests/integration/dist_logging_test.go` covers cluster-join + AddPeer records against a real DistMemory node.
1 parent 7b090ea commit e803fc0

10 files changed

Lines changed: 1049 additions & 657 deletions

File tree

CHANGELOG.md

Lines changed: 438 additions & 656 deletions
Large diffs are not rendered by default.

cmd/hypercache-server/main.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -377,6 +377,10 @@ func buildHyperCache(ctx context.Context, cfg envConfig, logger *slog.Logger) (*
377377
hypercache.WithMgmtAuth(mgmtReadAuth),
378378
hypercache.WithMgmtControlAuth(mgmtAdminAuth),
379379
),
380+
// Surfaces eviction/expiration loop start, per-tick activity,
381+
// and the cluster-join startup summary in the binary's JSON
382+
// log stream. Without this the HyperCache wrapper runs silent.
383+
hypercache.WithLogger[backend.DistMemory](logger),
380384
)
381385

382386
hc, err := hypercache.New(ctx, hypercache.GetDefaultManager(), hcCfg)

config.go

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
package hypercache
1313

1414
import (
15+
"log/slog"
1516
"strings"
1617
"time"
1718

@@ -164,6 +165,32 @@ func WithEvictionInterval[T backend.IBackendConstrain](evictionInterval time.Dur
164165
}
165166
}
166167

168+
// WithLogger sets the structured logger used by HyperCache for background-
169+
// loop and lifecycle events: eviction-loop trigger, expiration-loop trigger,
170+
// management HTTP server startup, and (when paired with a DistMemory
171+
// backend) the cluster-shape summary at boot.
172+
//
173+
// Defaults to a discard handler so library-mode embedded uses stay silent.
174+
// The hypercache-server binary wires its own slog.Logger here so operators
175+
// see structured JSON for every background task without needing the OTel
176+
// metrics pipeline. Pass nil to reset to the default discard handler.
177+
//
178+
// Note: the DistMemory backend has its own WithDistLogger option for
179+
// distributed-transport events (heartbeat, hint replay, rebalance). The
180+
// two are intentionally separate so an embedded user can silence one
181+
// surface without affecting the other.
182+
func WithLogger[T backend.IBackendConstrain](logger *slog.Logger) Option[T] {
183+
return func(cache *HyperCache[T]) {
184+
if logger == nil {
185+
cache.logger = slog.New(slog.DiscardHandler)
186+
187+
return
188+
}
189+
190+
cache.logger = logger
191+
}
192+
}
193+
167194
// WithExpirationTriggerBuffer sets the buffer size of the expiration trigger channel.
168195
// If set to <= 0, the default (capacity/2, minimum 1) is used.
169196
func WithExpirationTriggerBuffer[T backend.IBackendConstrain](size int) Option[T] {

hypercache.go

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ package hypercache
99

1010
import (
1111
"context"
12+
"log/slog"
1213
"sync"
1314
"sync/atomic"
1415
"time"
@@ -72,6 +73,12 @@ type HyperCache[T backend.IBackendConstrain] struct {
7273
StatsCollector stats.ICollector
7374
// Optional management HTTP server
7475
mgmtHTTP *ManagementHTTPServer
76+
// Structured logger. Defaults to a no-op (slog.New(slog.DiscardHandler))
77+
// so the cache stays silent unless the operator opts into observability
78+
// via WithLogger. Used for background-loop start/tick and for cache-
79+
// lifecycle events that operators want to follow without standing up
80+
// the OTel metrics pipeline.
81+
logger *slog.Logger
7582
}
7683

7784
// touchBackend is the optional interface a backend implements when it wants

hypercache_construct.go

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ package hypercache
22

33
import (
44
"context"
5+
"log/slog"
56
"runtime"
67
"time"
78

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

hypercache_eviction.go

Lines changed: 43 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ package hypercache
22

33
import (
44
"context"
5+
"log/slog"
56
"time"
67

78
"github.com/hyp3rd/sectools/pkg/converters"
@@ -61,6 +62,13 @@ func (hyperCache *HyperCache[T]) startEvictionRoutine(ctx context.Context) {
6162
return
6263
}
6364

65+
hyperCache.logger.Info(
66+
"eviction loop starting",
67+
slog.Duration("interval", hyperCache.evictionInterval),
68+
slog.Int("max_per_tick", int(hyperCache.maxEvictionCount)),
69+
slog.String("algorithm", hyperCache.evictionAlgorithmName),
70+
)
71+
6472
tick := time.NewTicker(hyperCache.evictionInterval)
6573

6674
go func() {
@@ -70,11 +78,13 @@ func (hyperCache *HyperCache[T]) startEvictionRoutine(ctx context.Context) {
7078
hyperCache.evictionLoop(ctx)
7179
case <-ctx.Done():
7280
tick.Stop()
81+
hyperCache.logger.Info("eviction loop stopped", slog.String("reason", "context_canceled"))
7382

7483
return
7584

7685
case <-hyperCache.stop:
7786
tick.Stop()
87+
hyperCache.logger.Info("eviction loop stopped", slog.String("reason", "stop_signal"))
7888

7989
return
8090
}
@@ -89,6 +99,9 @@ func (hyperCache *HyperCache[T]) evictionLoop(ctx context.Context) {
8999
// Enqueue the eviction loop in the worker pool to avoid blocking the main goroutine if the eviction loop is slow
90100
hyperCache.workerPool.Enqueue(func() error {
91101
hyperCache.StatsCollector.Incr("eviction_loop_count", 1)
102+
103+
start := time.Now()
104+
92105
defer hyperCache.StatsCollector.Timing("eviction_loop_duration", time.Now().UnixNano())
93106

94107
var evictedCount uint
@@ -133,10 +146,35 @@ func (hyperCache *HyperCache[T]) evictionLoop(ctx context.Context) {
133146

134147
hyperCache.StatsCollector.Gauge("evicted_item_count", evictedCount64)
135148

149+
hyperCache.logEvictionTick(evictedCount, itemCount, time.Since(start))
150+
136151
return nil
137152
})
138153
}
139154

155+
// logEvictionTick emits a single-line tick log so operators can grep
156+
// for `eviction tick`. Info when items were evicted, Debug for idle
157+
// ticks — the metric counters cover the idle case so we don't drown
158+
// logs in noise.
159+
func (hyperCache *HyperCache[T]) logEvictionTick(evicted uint, remaining int64, elapsed time.Duration) {
160+
if evicted > 0 {
161+
hyperCache.logger.Info(
162+
"eviction tick",
163+
slog.Uint64("evicted", uint64(evicted)),
164+
slog.Int64("items_remaining", remaining),
165+
slog.Duration("elapsed", elapsed),
166+
)
167+
168+
return
169+
}
170+
171+
hyperCache.logger.Debug(
172+
"eviction tick (idle)",
173+
slog.Int64("items", remaining),
174+
slog.Duration("elapsed", elapsed),
175+
)
176+
}
177+
140178
// evictItem is a helper function that removes an item from the cache and returns the key of the evicted item.
141179
// If no item can be evicted, it returns a false.
142180
func (hyperCache *HyperCache[T]) evictItem(ctx context.Context) (string, bool) {
@@ -177,6 +215,11 @@ func (hyperCache *HyperCache[T]) TriggerEviction(_ context.Context) {
177215

178216
select {
179217
case hyperCache.evictCh <- true:
218+
hyperCache.logger.Info("eviction triggered", slog.String("source", "manual"))
180219
default:
220+
// Trigger channel full; previous trigger already in-flight.
221+
// Log at debug — the coalesced trigger is intentional, not
222+
// an error worth waking the operator over.
223+
hyperCache.logger.Debug("eviction trigger coalesced (already pending)")
181224
}
182225
}

hypercache_expiration.go

Lines changed: 34 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ package hypercache
22

33
import (
44
"context"
5+
"log/slog"
56
"time"
67

78
"github.com/hyp3rd/hypercache/internal/constants"
@@ -11,6 +12,12 @@ import (
1112

1213
// startExpirationRoutine launches the expiration loop and listens to manual triggers and stop signals.
1314
func (hyperCache *HyperCache[T]) startExpirationRoutine(ctx context.Context) {
15+
hyperCache.logger.Info(
16+
"expiration loop starting",
17+
slog.Duration("interval", hyperCache.expirationInterval),
18+
slog.Duration("debounce", hyperCache.expirationDebounceInterval),
19+
)
20+
1421
go func() {
1522
var tick *time.Ticker
1623

@@ -61,13 +68,17 @@ func (hyperCache *HyperCache[T]) handleExpirationSelect(ctx context.Context, tic
6168
tick.Stop()
6269
}
6370

71+
hyperCache.logger.Info("expiration loop stopped", slog.String("reason", "context_canceled"))
72+
6473
return true
6574

6675
case <-hyperCache.stop:
6776
if tick != nil {
6877
tick.Stop()
6978
}
7079

80+
hyperCache.logger.Info("expiration loop stopped", slog.String("reason", "stop_signal"))
81+
7182
return true
7283
}
7384

@@ -107,6 +118,9 @@ func (hyperCache *HyperCache[T]) execTriggerExpiration() {
107118
func (hyperCache *HyperCache[T]) expirationLoop(ctx context.Context) {
108119
hyperCache.workerPool.Enqueue(func() error {
109120
hyperCache.StatsCollector.Incr("expiration_loop_count", 1)
121+
122+
start := time.Now()
123+
110124
defer hyperCache.StatsCollector.Timing("expiration_loop_duration", time.Now().UnixNano())
111125

112126
var (
@@ -138,9 +152,28 @@ func (hyperCache *HyperCache[T]) expirationLoop(ctx context.Context) {
138152
hyperCache.StatsCollector.Incr("item_expired_count", 1)
139153
}
140154

141-
hyperCache.StatsCollector.Gauge("item_count", int64(hyperCache.backend.Count(ctx)))
155+
itemCount := int64(hyperCache.backend.Count(ctx))
156+
hyperCache.StatsCollector.Gauge("item_count", itemCount)
142157
hyperCache.StatsCollector.Gauge("expired_item_count", expiredCount)
143158

159+
// Mirror the eviction-tick shape: Info only when there's
160+
// actual work, Debug for idle ticks so background noise
161+
// doesn't drown out the events operators care about.
162+
if expiredCount > 0 {
163+
hyperCache.logger.Info(
164+
"expiration tick",
165+
slog.Int64("expired", expiredCount),
166+
slog.Int64("items_remaining", itemCount),
167+
slog.Duration("elapsed", time.Since(start)),
168+
)
169+
} else {
170+
hyperCache.logger.Debug(
171+
"expiration tick (idle)",
172+
slog.Int64("items", itemCount),
173+
slog.Duration("elapsed", time.Since(start)),
174+
)
175+
}
176+
144177
return nil
145178
})
146179
}

0 commit comments

Comments
 (0)