From 68d523ccddc09a61a17f1f93c138c229b230cfb6 Mon Sep 17 00:00:00 2001 From: Marius van der Wijden Date: Tue, 1 Apr 2025 12:37:00 +0200 Subject: [PATCH 1/7] log: allow --vmodule to downgrade the log level --- log/handler_glog.go | 5 ----- 1 file changed, 5 deletions(-) diff --git a/log/handler_glog.go b/log/handler_glog.go index 739f8c5b42..d88e6ba64c 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -179,11 +179,6 @@ func (h *GlogHandler) WithGroup(name string) slog.Handler { // Handle implements slog.Handler, filtering a log record through the global, // local and backtrace filters, finally emitting it if either allow it through. func (h *GlogHandler) Handle(_ context.Context, r slog.Record) error { - // If the global log level allows, fast track logging - if slog.Level(h.level.Load()) <= r.Level { - return h.origin.Handle(context.Background(), r) - } - // Check callsite cache for previously calculated log levels h.lock.RLock() lvl, ok := h.siteCache[r.PC] From 0f03ee83e882ff3358e019fe69121315271b82b5 Mon Sep 17 00:00:00 2001 From: Marius van der Wijden Date: Tue, 1 Apr 2025 12:48:51 +0200 Subject: [PATCH 2/7] log: allow --vmodule to downgrade the log level --- log/handler_glog.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/log/handler_glog.go b/log/handler_glog.go index d88e6ba64c..0534d1bbb2 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -52,7 +52,8 @@ type GlogHandler struct { // to Google's glog logger. The returned handler implements Handler. func NewGlogHandler(h slog.Handler) *GlogHandler { return &GlogHandler{ - origin: h, + origin: h, + siteCache: make(map[uintptr]slog.Level), } } @@ -196,9 +197,10 @@ func (h *GlogHandler) Handle(_ context.Context, r slog.Record) error { h.siteCache[r.PC], lvl, ok = rule.level, rule.level, true } } - // If no rule matched, remember to drop log the next time + // If no rule matched, use the default log lvl if !ok { - h.siteCache[r.PC] = 0 + lvl = slog.Level(h.level.Load()) + h.siteCache[r.PC] = lvl } h.lock.Unlock() } From 64773bf6bc5b0810bdc2ca689140946b94d89e51 Mon Sep 17 00:00:00 2001 From: Marius van der Wijden Date: Sun, 6 Apr 2025 14:52:14 +0200 Subject: [PATCH 3/7] log: clear siteCache on setting the verbosity --- log/handler_glog.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/log/handler_glog.go b/log/handler_glog.go index 0534d1bbb2..e3c670c2a7 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -68,6 +68,8 @@ type pattern struct { // and source files can be raised using Vmodule. func (h *GlogHandler) Verbosity(level slog.Level) { h.level.Store(int32(level)) + // clear the cache to make sure the verbosity is applied correctly. + h.siteCache = make(map[uintptr]slog.Level) } // Vmodule sets the glog verbosity pattern. From 4fb7b3a24e3b8f9c605239e4c17a6baad97ee965 Mon Sep 17 00:00:00 2001 From: MariusVanDerWijden Date: Thu, 29 May 2025 11:21:13 +0200 Subject: [PATCH 4/7] log: use sync map --- log/handler_glog.go | 48 +++++++++++++++++++-------------------------- 1 file changed, 20 insertions(+), 28 deletions(-) diff --git a/log/handler_glog.go b/log/handler_glog.go index e3c670c2a7..4694d04a50 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -21,7 +21,6 @@ import ( "errors" "fmt" "log/slog" - "maps" "regexp" "runtime" "strconv" @@ -42,18 +41,17 @@ type GlogHandler struct { level atomic.Int32 // Current log level, atomically accessible override atomic.Bool // Flag whether overrides are used, atomically accessible - patterns []pattern // Current list of patterns to override with - siteCache map[uintptr]slog.Level // Cache of callsite pattern evaluations - location string // file:line location where to do a stackdump at - lock sync.RWMutex // Lock protecting the override pattern list + patterns []pattern // Current list of patterns to override with + siteCache sync.Map // Cache of callsite pattern evaluations, maps uintptr -> slog.Level + location string // file:line location where to do a stackdump at + lock sync.RWMutex // Lock protecting the override pattern list } // NewGlogHandler creates a new log handler with filtering functionality similar // to Google's glog logger. The returned handler implements Handler. func NewGlogHandler(h slog.Handler) *GlogHandler { return &GlogHandler{ - origin: h, - siteCache: make(map[uintptr]slog.Level), + origin: h, } } @@ -69,7 +67,7 @@ type pattern struct { func (h *GlogHandler) Verbosity(level slog.Level) { h.level.Store(int32(level)) // clear the cache to make sure the verbosity is applied correctly. - h.siteCache = make(map[uintptr]slog.Level) + h.siteCache.Clear() } // Vmodule sets the glog verbosity pattern. @@ -133,10 +131,9 @@ func (h *GlogHandler) Vmodule(ruleset string) error { } // Swap out the vmodule pattern for the new filter system h.lock.Lock() - defer h.lock.Unlock() - h.patterns = filter - h.siteCache = make(map[uintptr]slog.Level) + h.lock.Unlock() + h.siteCache.Clear() h.override.Store(len(filter) != 0) return nil @@ -152,18 +149,15 @@ func (h *GlogHandler) Enabled(ctx context.Context, lvl slog.Level) bool { // WithAttrs implements slog.Handler, returning a new Handler whose attributes // consist of both the receiver's attributes and the arguments. func (h *GlogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + patterns := []pattern{} h.lock.RLock() - siteCache := maps.Clone(h.siteCache) + patterns = append(patterns, h.patterns...) h.lock.RUnlock() - patterns := []pattern{} - patterns = append(patterns, h.patterns...) - res := GlogHandler{ - origin: h.origin.WithAttrs(attrs), - patterns: patterns, - siteCache: siteCache, - location: h.location, + origin: h.origin.WithAttrs(attrs), + patterns: patterns, + location: h.location, } res.level.Store(h.level.Load()) @@ -183,30 +177,28 @@ func (h *GlogHandler) WithGroup(name string) slog.Handler { // local and backtrace filters, finally emitting it if either allow it through. func (h *GlogHandler) Handle(_ context.Context, r slog.Record) error { // Check callsite cache for previously calculated log levels - h.lock.RLock() - lvl, ok := h.siteCache[r.PC] - h.lock.RUnlock() + lvl, ok := h.siteCache.Load(r.PC) // If we didn't cache the callsite yet, calculate it if !ok { - h.lock.Lock() - fs := runtime.CallersFrames([]uintptr{r.PC}) frame, _ := fs.Next() + h.lock.RLock() for _, rule := range h.patterns { if rule.pattern.MatchString(fmt.Sprintf("+%s", frame.File)) { - h.siteCache[r.PC], lvl, ok = rule.level, rule.level, true + h.siteCache.Store(r.PC, rule.level) + lvl, ok = rule.level, true } } + h.lock.RUnlock() // If no rule matched, use the default log lvl if !ok { lvl = slog.Level(h.level.Load()) - h.siteCache[r.PC] = lvl + h.siteCache.Store(r.PC, lvl) } - h.lock.Unlock() } - if lvl <= r.Level { + if lvl.(slog.Level) <= r.Level { return h.origin.Handle(context.Background(), r) } return nil From 1423367b4f4ea4484ff65b6b7e1083bd0b94a8a5 Mon Sep 17 00:00:00 2001 From: jonny rhea Date: Wed, 5 Nov 2025 21:00:16 -0600 Subject: [PATCH 5/7] log/glog: replace siteCache with atomic pointer --- log/handler_glog.go | 90 ++++++++++++++++++++++++++++----------------- 1 file changed, 56 insertions(+), 34 deletions(-) diff --git a/log/handler_glog.go b/log/handler_glog.go index 4694d04a50..de0456b5a3 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -19,7 +19,6 @@ package log import ( "context" "errors" - "fmt" "log/slog" "regexp" "runtime" @@ -41,18 +40,19 @@ type GlogHandler struct { level atomic.Int32 // Current log level, atomically accessible override atomic.Bool // Flag whether overrides are used, atomically accessible - patterns []pattern // Current list of patterns to override with - siteCache sync.Map // Cache of callsite pattern evaluations, maps uintptr -> slog.Level - location string // file:line location where to do a stackdump at - lock sync.RWMutex // Lock protecting the override pattern list + patterns []pattern // Current list of patterns to override with + cachePtr atomic.Pointer[sync.Map] // Pointer to cache of callsite pattern evaluations, maps uintptr -> slog.Level + location string // file:line location where to do a stackdump at + lock sync.Mutex // Lock protecting the override pattern list } // NewGlogHandler creates a new log handler with filtering functionality similar // to Google's glog logger. The returned handler implements Handler. func NewGlogHandler(h slog.Handler) *GlogHandler { - return &GlogHandler{ - origin: h, - } + g := &GlogHandler{origin: h} + m := new(sync.Map) + g.cachePtr.Store(m) + return g } // pattern contains a filter for the Vmodule option, holding a verbosity level @@ -66,8 +66,7 @@ type pattern struct { // and source files can be raised using Vmodule. func (h *GlogHandler) Verbosity(level slog.Level) { h.level.Store(int32(level)) - // clear the cache to make sure the verbosity is applied correctly. - h.siteCache.Clear() + h.cachePtr.Store(new(sync.Map)) // atomic swap of cache instead of Clear } // Vmodule sets the glog verbosity pattern. @@ -133,7 +132,7 @@ func (h *GlogHandler) Vmodule(ruleset string) error { h.lock.Lock() h.patterns = filter h.lock.Unlock() - h.siteCache.Clear() + h.cachePtr.Store(new(sync.Map)) // atomic swap of cache instead of Clear h.override.Store(len(filter) != 0) return nil @@ -150,9 +149,9 @@ func (h *GlogHandler) Enabled(ctx context.Context, lvl slog.Level) bool { // consist of both the receiver's attributes and the arguments. func (h *GlogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { patterns := []pattern{} - h.lock.RLock() + h.lock.Lock() patterns = append(patterns, h.patterns...) - h.lock.RUnlock() + h.lock.Unlock() res := GlogHandler{ origin: h.origin.WithAttrs(attrs), @@ -162,6 +161,7 @@ func (h *GlogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { res.level.Store(h.level.Load()) res.override.Store(h.override.Load()) + res.cachePtr.Store(h.cachePtr.Load()) return &res } @@ -175,31 +175,53 @@ func (h *GlogHandler) WithGroup(name string) slog.Handler { // Handle implements slog.Handler, filtering a log record through the global, // local and backtrace filters, finally emitting it if either allow it through. -func (h *GlogHandler) Handle(_ context.Context, r slog.Record) error { - // Check callsite cache for previously calculated log levels - lvl, ok := h.siteCache.Load(r.PC) +func (h *GlogHandler) Handle(ctx context.Context, r slog.Record) error { + // Get current cache + cache := h.cachePtr.Load() - // If we didn't cache the callsite yet, calculate it - if !ok { - fs := runtime.CallersFrames([]uintptr{r.PC}) - frame, _ := fs.Next() - - h.lock.RLock() - for _, rule := range h.patterns { - if rule.pattern.MatchString(fmt.Sprintf("+%s", frame.File)) { - h.siteCache.Store(r.PC, rule.level) - lvl, ok = rule.level, true - } + // Fast path: cache hit + if lvl, ok := cache.Load(r.PC); ok { + if lvl.(slog.Level) <= r.Level { + return h.origin.Handle(ctx, r) } - h.lock.RUnlock() - // If no rule matched, use the default log lvl - if !ok { - lvl = slog.Level(h.level.Load()) - h.siteCache.Store(r.PC, lvl) + return nil + } + + // Resolve the callsite file once. + fs := runtime.CallersFrames([]uintptr{r.PC}) + frame, _ := fs.Next() + file := frame.File + + // Snapshot the current pattern slice under lock. + h.lock.Lock() + curPatterns := h.patterns + h.lock.Unlock() + + // Match without holding the lock. + var ( + lvl slog.Level + ok bool + ) + for _, rule := range curPatterns { + if rule.pattern.MatchString("+" + file) { + lvl, ok = rule.level, true + // TODO: Not breaking allows the last match to win. Is this what we want? } } - if lvl.(slog.Level) <= r.Level { - return h.origin.Handle(context.Background(), r) + if !ok { + // No rule matched: use the current global/default level. + lvl = slog.Level(h.level.Load()) + } + + // Store only if patterns are still the same slice (avoid caching stale results). + h.lock.Lock() + if len(h.patterns) > 0 && len(curPatterns) > 0 && &h.patterns[0] == &curPatterns[0] { + cache.Store(r.PC, lvl) + } + h.lock.Unlock() + + if lvl <= r.Level { + return h.origin.Handle(ctx, r) } return nil } From 9baf82c8c5590ed94b65656e36b29d3bffeed1eb Mon Sep 17 00:00:00 2001 From: jonny rhea Date: Thu, 15 Jan 2026 11:24:25 -0600 Subject: [PATCH 6/7] log: cache default level when no vmodule patterns configured and add downgrade test --- log/handler_glog.go | 15 +++++++++++++-- log/logger_test.go | 29 +++++++++++++++++++++++++++++ 2 files changed, 42 insertions(+), 2 deletions(-) diff --git a/log/handler_glog.go b/log/handler_glog.go index de0456b5a3..1d85b9dfe5 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -213,9 +213,20 @@ func (h *GlogHandler) Handle(ctx context.Context, r slog.Record) error { lvl = slog.Level(h.level.Load()) } - // Store only if patterns are still the same slice (avoid caching stale results). + // Check if we should cache this result h.lock.Lock() - if len(h.patterns) > 0 && len(curPatterns) > 0 && &h.patterns[0] == &curPatterns[0] { + shouldCache := false + switch { + case len(curPatterns) == 0 && len(h.patterns) == 0: + // Cache the default/global level to avoid re-evaluating the callsite each time. + shouldCache = true + case len(h.patterns) > 0 && len(curPatterns) > 0: + // Only cache the result if the vmodule patterns have not changed since we + // snapshotted them. This avoids inserting stale entries if Vmodule() updates + // the pattern list concurrently with Handle(). + shouldCache = (&h.patterns[0] == &curPatterns[0]) + } + if shouldCache { cache.Store(r.PC, lvl) } h.lock.Unlock() diff --git a/log/logger_test.go b/log/logger_test.go index dae8497204..c951d7f9f0 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -33,6 +33,35 @@ func TestLoggingWithVmodule(t *testing.T) { } } +func TestLoggingWithVmoduleDowngrade(t *testing.T) { + out := new(bytes.Buffer) + glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false)) + glog.Verbosity(LevelTrace) // Allow all logs globally + logger := NewLogger(glog) + + // This should appear (global level allows it) + logger.Info("before vmodule downgrade, this should be logged") + if !bytes.Contains(out.Bytes(), []byte("before vmodule downgrade")) { + t.Fatal("expected 'before vmodule downgrade' to be logged") + } + out.Reset() + + // Downgrade this file to only allow Warn and above + glog.Vmodule("logger_test.go=2") + + // Info should now be filtered out + logger.Info("after vmodule downgrade, this should be filtered") + if bytes.Contains(out.Bytes(), []byte("after vmodule downgrade, this should be filtered")) { + t.Fatal("expected 'after vmodule downgrade, this should be filtered' to NOT be logged after vmodule downgrade") + } + + // Warn should still appear + logger.Warn("after vmodule downgrade, this should be logged") + if !bytes.Contains(out.Bytes(), []byte("after vmodule downgrade, this should be logged")) { + t.Fatal("expected 'should appear' to be logged") + } +} + func TestTerminalHandlerWithAttrs(t *testing.T) { out := new(bytes.Buffer) glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false).WithAttrs([]slog.Attr{slog.String("baz", "bat")})) From 7ce122b805a33a941a40ace1b05d5257482ac738 Mon Sep 17 00:00:00 2001 From: Jonny Rhea <5555162+jrhea@users.noreply.github.com> Date: Mon, 19 Jan 2026 07:53:04 -0600 Subject: [PATCH 7/7] Remove Todo --- log/handler_glog.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log/handler_glog.go b/log/handler_glog.go index 1d85b9dfe5..30300bb2a1 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -205,7 +205,7 @@ func (h *GlogHandler) Handle(ctx context.Context, r slog.Record) error { for _, rule := range curPatterns { if rule.pattern.MatchString("+" + file) { lvl, ok = rule.level, true - // TODO: Not breaking allows the last match to win. Is this what we want? + // Not breaking allows the last match to win. } } if !ok {