diff --git a/log/handler_glog.go b/log/handler_glog.go index 739f8c5b42..13afb62ca4 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -19,9 +19,7 @@ package log import ( "context" "errors" - "fmt" "log/slog" - "maps" "regexp" "runtime" "strconv" @@ -38,22 +36,22 @@ var errVmoduleSyntax = errors.New("expect comma-separated list of filename=N") // matches; and requesting backtraces at certain positions. type GlogHandler struct { origin slog.Handler // The origin handler this wraps + lock sync.Mutex // synchronizes writes to config + config atomic.Pointer[glogConfig] +} - 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 +type glogConfig struct { + patterns []pattern + cache sync.Map + level slog.Level } // 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, - } +func NewGlogHandler(origin slog.Handler) *GlogHandler { + h := &GlogHandler{origin: origin} + h.config.Store(new(glogConfig)) + return h } // pattern contains a filter for the Vmodule option, holding a verbosity level @@ -66,7 +64,12 @@ type pattern struct { // Verbosity sets the glog verbosity ceiling. The verbosity of individual packages // and source files can be raised using Vmodule. func (h *GlogHandler) Verbosity(level slog.Level) { - h.level.Store(int32(level)) + h.lock.Lock() + defer h.lock.Unlock() + + cfg := h.config.Load() + newcfg := &glogConfig{level: level, patterns: cfg.patterns} + h.config.Store(newcfg) } // Vmodule sets the glog verbosity pattern. @@ -128,13 +131,13 @@ func (h *GlogHandler) Vmodule(ruleset string) error { re, _ := regexp.Compile(matcher) filter = append(filter, pattern{re, level}) } + // 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.override.Store(len(filter) != 0) + cfg := h.config.Load() + newcfg := &glogConfig{level: cfg.level, patterns: filter} + h.config.Store(newcfg) + h.lock.Unlock() return nil } @@ -142,30 +145,9 @@ func (h *GlogHandler) Vmodule(ruleset string) error { // Enabled implements slog.Handler, reporting whether the handler handles records // at the given level. func (h *GlogHandler) Enabled(ctx context.Context, lvl slog.Level) bool { - // fast-track skipping logging if override not enabled and the provided verbosity is above configured - return h.override.Load() || slog.Level(h.level.Load()) <= lvl -} - -// 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 { - h.lock.RLock() - siteCache := maps.Clone(h.siteCache) - h.lock.RUnlock() - - patterns := []pattern{} - patterns = append(patterns, h.patterns...) - - res := GlogHandler{ - origin: h.origin.WithAttrs(attrs), - patterns: patterns, - siteCache: siteCache, - location: h.location, - } - - res.level.Store(h.level.Load()) - res.override.Store(h.override.Load()) - return &res + // fast-track skipping logging if vmodule is not enabled or level too low + cfg := h.config.Load() + return len(cfg.patterns) > 0 || cfg.level <= lvl } // WithGroup implements slog.Handler, returning a new Handler with the given @@ -178,37 +160,70 @@ 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) - } +func (h *GlogHandler) Handle(ctx context.Context, r slog.Record) error { + return h.handle(ctx, r, h.origin) +} - // Check callsite cache for previously calculated log levels - h.lock.RLock() - lvl, ok := h.siteCache[r.PC] - h.lock.RUnlock() - - // If we didn't cache the callsite yet, calculate it - if !ok { - h.lock.Lock() +func (h *GlogHandler) handle(ctx context.Context, r slog.Record, origin slog.Handler) error { + cfg := h.config.Load() + var lvl slog.Level + cachedLvl, ok := cfg.cache.Load(r.PC) + if ok { + // Fast path: cache hit + lvl = cachedLvl.(slog.Level) + } else { + // Resolve the callsite file. fs := runtime.CallersFrames([]uintptr{r.PC}) frame, _ := fs.Next() - - 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 + file := frame.File + // Match against patterns and cache the level applied at this callsite. + lvl = cfg.level // default: use global level + for _, rule := range cfg.patterns { + if rule.pattern.MatchString("+" + file) { + lvl = rule.level } } - // If no rule matched, remember to drop log the next time - if !ok { - h.siteCache[r.PC] = 0 - } - h.lock.Unlock() + cfg.cache.Store(r.PC, lvl) } + + // Handle the message. if lvl <= r.Level { - return h.origin.Handle(context.Background(), r) + return origin.Handle(ctx, r) } return nil } + +// WithAttrs implements slog.Handler, returning a new Handler whose attributes +// consist of both the receiver's attributes and the arguments. +// +// Note the handler created here will still listen to Verbosity and Vmodule settings +// done on the original handler. +func (h *GlogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &glogWithAttrs{base: h, origin: h.origin.WithAttrs(attrs)} +} + +type glogWithAttrs struct { + base *GlogHandler + origin slog.Handler +} + +func (wh *glogWithAttrs) Enabled(ctx context.Context, lvl slog.Level) bool { + return wh.base.Enabled(ctx, lvl) +} + +func (wh *glogWithAttrs) Handle(ctx context.Context, r slog.Record) error { + return wh.base.handle(ctx, r, wh.origin) +} + +func (wh *glogWithAttrs) WithAttrs(attrs []slog.Attr) slog.Handler { + return &glogWithAttrs{base: wh.base, origin: wh.origin.WithAttrs(attrs)} +} + +// WithGroup implements slog.Handler, returning a new Handler with the given +// group appended to the receiver's existing groups. +// +// Note, this function is not implemented. +func (wh *glogWithAttrs) WithGroup(name string) slog.Handler { + panic("not implemented") +} diff --git a/log/logger_test.go b/log/logger_test.go index dae8497204..c585ddab66 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -33,6 +33,64 @@ func TestLoggingWithVmodule(t *testing.T) { } } +// TestLoggingWithVmoduleDowngrade checks that vmodule can be downgraded. +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") + } +} + +// TestWithAttrsVerbosityChange checks that verbosity changes affect child loggers. +func TestWithAttrsVerbosityChange(t *testing.T) { + out := new(bytes.Buffer) + glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false)) + glog.Verbosity(LevelInfo) + + // Create a child logger with an extra attribute. + child := slog.New(glog.WithAttrs([]slog.Attr{slog.String("peer", "foo")})) + + // Debug should be filtered at Info level. + child.Debug("this should be filtered") + if bytes.Contains(out.Bytes(), []byte("this should be filtered")) { + t.Fatal("expected debug message to be filtered at Info level") + } + + // Change verbosity on the parent to allow Debug. + glog.Verbosity(LevelDebug) + + // Child should pick up the new level and include its attributes. + child.Debug("this should be logged") + if !bytes.Contains(out.Bytes(), []byte("this should be logged")) { + t.Fatal("expected child logger to pick up verbosity change") + } + if !bytes.Contains(out.Bytes(), []byte("peer=foo")) { + t.Fatal("expected child logger to include WithAttrs attributes") + } +} + func TestTerminalHandlerWithAttrs(t *testing.T) { out := new(bytes.Buffer) glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false).WithAttrs([]slog.Attr{slog.String("baz", "bat")}))