From d635f3c46f87b6b5e75acd5c690e8f84605ba9dc Mon Sep 17 00:00:00 2001 From: cnderrauber Date: Wed, 9 Sep 2026 10:56:35 +0800 Subject: [PATCH 1/2] Add compoment min level logging To Support per project component logging level --- logger/logger.go | 52 +++++++++-- logger/pionlogger/minlevel_test.go | 145 +++++++++++++++++++++++++++++ logger/zaputil/orlevelenabler.go | 27 +++++- 3 files changed, 215 insertions(+), 9 deletions(-) create mode 100644 logger/pionlogger/minlevel_test.go diff --git a/logger/logger.go b/logger/logger.go index c60d030a3..582102484 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -227,21 +227,42 @@ type ZapComponentLeveler interface { ComponentLevel(component string) zapcore.LevelEnabler } +// ZapComponentMinLeveler resolves a per-component minimum level for a logger, +// on top of the levels configured globally. It returns nil for components it +// has no opinion on. +type ZapComponentMinLeveler interface { + ComponentMinLevel(component string) zapcore.LevelEnabler +} + type ZapLogger interface { Logger ToZap() *zap.SugaredLogger ComponentLeveler() ZapComponentLeveler WithMinLevel(lvl zapcore.LevelEnabler) Logger + // WithComponentMinLeveler lowers the level per component, for this logger + // and its descendants. Unlike WithMinLevel it is reported by + // ComponentLeveler, so it also opens up subsystems that do their own level + // gating. + WithComponentMinLeveler(ml ZapComponentMinLeveler) Logger } type zapLogger[T zaputil.Encoder[T]] struct { zap *zap.SugaredLogger *zapConfig - enc T - component string - deferred []*zaputil.Deferrer - sampler *zaputil.Sampler - minLevel zapcore.LevelEnabler + enc T + component string + deferred []*zaputil.Deferrer + sampler *zaputil.Sampler + minLevel zapcore.LevelEnabler + componentMinLeveler ZapComponentMinLeveler +} + +// componentMinLevel returns the min leveler's opinion on component, or nil. +func (l *zapLogger[T]) componentMinLevel(component string) zapcore.LevelEnabler { + if l.componentMinLeveler == nil { + return nil + } + return l.componentMinLeveler.ComponentMinLevel(component) } func FromZapLogger(log *zap.Logger, conf *Config, opts ...ZapLoggerOption) (ZapLogger, error) { @@ -298,12 +319,14 @@ func newZapLogger[T zaputil.Encoder[T]](zap *zap.SugaredLogger, zc *zapConfig, e func (l *zapLogger[T]) makeZap() *zap.SugaredLogger { var console *zaputil.WriteEnabler - if l.minLevel == nil { + // writeEnablers is shared by every logger built from this config, so it can + // only cache enablers that depend on nothing but the component. + if componentMinLevel := l.componentMinLevel(l.component); componentMinLevel == nil && l.minLevel == nil { console, _ = l.writeEnablers.LoadOrCompute(l.component, func() (*zaputil.WriteEnabler, bool) { return zaputil.NewWriteEnabler(os.Stderr, l.sc.ComponentLevel(l.component)), false }) } else { - enab := zaputil.OrLevelEnabler{l.minLevel, l.sc.ComponentLevel(l.component)} + enab := zaputil.NewOrLevelEnabler(l.minLevel, l.sc.ComponentLevel(l.component), componentMinLevel) console = zaputil.NewWriteEnabler(os.Stderr, enab) } @@ -331,6 +354,14 @@ func (l zapLoggerComponentLeveler[T]) ComponentLevel(component string) zapcore.L component = l.zl.component + "." + component } + // Note this reports the logger's component min leveler but not its min + // level: see ZapLogger.WithMinLevel. levelEnablers is shared by every + // logger built from this config, so a min leveler's opinion, which is + // particular to one logger, must not be cached in it. + if override := l.zl.componentMinLevel(component); override != nil { + return zaputil.OrLevelEnabler{l.zl.sc.ComponentLevel(component), l.zl.tap, override} + } + enab, _ := l.zl.levelEnablers.LoadOrCompute(component, func() (*zaputil.OrLevelEnabler, bool) { return &zaputil.OrLevelEnabler{l.zl.sc.ComponentLevel(component), l.zl.tap}, false }) @@ -345,6 +376,13 @@ func (l *zapLogger[T]) Debugw(msg string, keysAndValues ...any) { l.zap.Debugw(msg, keysAndValues...) } +func (l *zapLogger[T]) WithComponentMinLeveler(ml ZapComponentMinLeveler) Logger { + dup := *l + dup.componentMinLeveler = ml + dup.zap = dup.makeZap() + return &dup +} + func (l *zapLogger[T]) WithMinLevel(lvl zapcore.LevelEnabler) Logger { dup := *l dup.minLevel = lvl diff --git a/logger/pionlogger/minlevel_test.go b/logger/pionlogger/minlevel_test.go new file mode 100644 index 000000000..9560b0106 --- /dev/null +++ b/logger/pionlogger/minlevel_test.go @@ -0,0 +1,145 @@ +// Copyright 2023 LiveKit, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package pionlogger + +import ( + "io" + "os" + "testing" + + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + "github.com/livekit/protocol/logger" +) + +// componentMinLeveler resolves exact component paths. Real implementations +// search up the component hierarchy; that search is the caller's concern. +type componentMinLeveler map[string]zapcore.LevelEnabler + +func (m componentMinLeveler) ComponentMinLevel(component string) zapcore.LevelEnabler { + return m[component] +} + +func debugLevel() zapcore.LevelEnabler { return zap.NewAtomicLevelAt(zapcore.DebugLevel) } + +// capture swaps os.Stderr for the duration of f. Loggers must be built inside +// f: makeZap binds os.Stderr when the logger is created, not when it emits. +func capture(t *testing.T, f func(base logger.ZapLogger)) string { + t.Helper() + + r, w, err := os.Pipe() + require.NoError(t, err) + + orig := os.Stderr + os.Stderr = w + + func() { + defer func() { os.Stderr = orig }() + + // staging/production shape: everything at info, pion quieted to warn + base, err := logger.NewZapLogger(&logger.Config{ + Level: "info", + ComponentLevels: map[string]string{"transport.pion": "warn"}, + }) + require.NoError(t, err) + f(base) + }() + + require.NoError(t, w.Close()) + out, err := io.ReadAll(r) + require.NoError(t, err) + return string(out) +} + +// pionDebug logs a debug line from pion scope through the same path +// pkg/rtc/transport.go uses: a participant logger, WithComponent("transport"), +// handed to the factory. +func pionDebug(l logger.Logger, scope, msg string) { + NewLoggerFactory(l.WithComponent("transport")).NewLogger(scope).Debug(msg) +} + +func TestMinLevelReachesPionComponents(t *testing.T) { + t.Run("no override leaves pion at its configured level", func(t *testing.T) { + out := capture(t, func(base logger.ZapLogger) { + pionDebug(base, "ice", "ice-debug") + }) + require.NotContains(t, out, "ice-debug") + }) + + // The behavior existing `project_levels: {: debug}` config relies on. + // A logger-wide floor must not drag pion along with it. + t.Run("min level alone does not open pion", func(t *testing.T) { + out := capture(t, func(base logger.ZapLogger) { + proj := base.WithMinLevel(debugLevel()) + proj.WithComponent("transport").Debugw("transport-debug") + pionDebug(proj, "ice", "ice-debug") + }) + require.Contains(t, out, "transport-debug", "min level should still apply to non-gated components") + require.NotContains(t, out, "ice-debug") + }) + + t.Run("component min leveler opens only the listed component", func(t *testing.T) { + out := capture(t, func(base logger.ZapLogger) { + proj := base.WithComponentMinLeveler(componentMinLeveler{"transport.pion.ice": debugLevel()}) + pionDebug(proj, "ice", "ice-debug") + pionDebug(proj, "sctp", "sctp-debug") + }) + require.Contains(t, out, "ice-debug") + require.NotContains(t, out, "sctp-debug", "an unlisted pion component must stay at its configured level") + }) + + // A project at `level: debug` that also lists one pion component gets that + // component and no other: the logger-wide floor still must not leak into + // the gated ones. + t.Run("min level and component min leveler together", func(t *testing.T) { + out := capture(t, func(base logger.ZapLogger) { + proj := base.WithMinLevel(debugLevel()).(logger.ZapLogger). + WithComponentMinLeveler(componentMinLeveler{"transport.pion.ice": debugLevel()}) + pionDebug(proj, "ice", "ice-debug") + pionDebug(proj, "sctp", "sctp-debug") + }) + require.Contains(t, out, "ice-debug") + require.NotContains(t, out, "sctp-debug") + }) + + // Enablers are memoized on state shared by every logger built from one + // config, so an override must never be cached under a bare component key. + t.Run("override does not leak to sibling loggers", func(t *testing.T) { + out := capture(t, func(base logger.ZapLogger) { + withOverride := base.WithComponentMinLeveler(componentMinLeveler{"transport.pion.ice": debugLevel()}) + pionDebug(withOverride, "ice", "overridden-ice-debug") + + // same component path, different logger, no override + pionDebug(base, "ice", "other-ice-debug") + }) + require.Contains(t, out, "overridden-ice-debug") + require.NotContains(t, out, "other-ice-debug") + }) + + t.Run("override does not leak to loggers built before it", func(t *testing.T) { + out := capture(t, func(base logger.ZapLogger) { + pionDebug(base, "ice", "first-ice-debug") + + withOverride := base.WithComponentMinLeveler(componentMinLeveler{"transport.pion.ice": debugLevel()}) + pionDebug(withOverride, "ice", "overridden-ice-debug") + pionDebug(base, "ice", "last-ice-debug") + }) + require.NotContains(t, out, "first-ice-debug") + require.Contains(t, out, "overridden-ice-debug") + require.NotContains(t, out, "last-ice-debug") + }) +} diff --git a/logger/zaputil/orlevelenabler.go b/logger/zaputil/orlevelenabler.go index a71ca12de..0f1c36cd5 100644 --- a/logger/zaputil/orlevelenabler.go +++ b/logger/zaputil/orlevelenabler.go @@ -16,8 +16,31 @@ package zaputil import "go.uber.org/zap/zapcore" -type OrLevelEnabler [2]zapcore.LevelEnabler +// OrLevelEnabler is enabled at a level if any of its members is. Members must +// be non-nil; build one with NewOrLevelEnabler from sources that may not be. +type OrLevelEnabler []zapcore.LevelEnabler func (e OrLevelEnabler) Enabled(lvl zapcore.Level) bool { - return e[0].Enabled(lvl) || e[1].Enabled(lvl) + for _, enab := range e { + if enab.Enabled(lvl) { + return true + } + } + return false +} + +// NewOrLevelEnabler combines enabs, ignoring any that are nil. It returns nil +// when every one of them is nil, so callers can tell "nothing to combine" apart +// from an enabler that is never enabled. +func NewOrLevelEnabler(enabs ...zapcore.LevelEnabler) zapcore.LevelEnabler { + e := make(OrLevelEnabler, 0, len(enabs)) + for _, enab := range enabs { + if enab != nil { + e = append(e, enab) + } + } + if len(e) == 0 { + return nil + } + return e } From fdfcb4092fe02ef0c7f5e4e30501e5d0a0499343 Mon Sep 17 00:00:00 2001 From: cnderrauber Date: Wed, 9 Sep 2026 21:04:57 +0800 Subject: [PATCH 2/2] cache min & component min levelers --- logger/logger.go | 75 +++++++++++++++++++++++------- logger/pionlogger/minlevel_test.go | 61 ++++++++++++++++++++++++ 2 files changed, 120 insertions(+), 16 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 582102484..9e22e3ac7 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -227,9 +227,6 @@ type ZapComponentLeveler interface { ComponentLevel(component string) zapcore.LevelEnabler } -// ZapComponentMinLeveler resolves a per-component minimum level for a logger, -// on top of the levels configured globally. It returns nil for components it -// has no opinion on. type ZapComponentMinLeveler interface { ComponentMinLevel(component string) zapcore.LevelEnabler } @@ -239,10 +236,6 @@ type ZapLogger interface { ToZap() *zap.SugaredLogger ComponentLeveler() ZapComponentLeveler WithMinLevel(lvl zapcore.LevelEnabler) Logger - // WithComponentMinLeveler lowers the level per component, for this logger - // and its descendants. Unlike WithMinLevel it is reported by - // ComponentLeveler, so it also opens up subsystems that do their own level - // gating. WithComponentMinLeveler(ml ZapComponentMinLeveler) Logger } @@ -255,6 +248,7 @@ type zapLogger[T zaputil.Encoder[T]] struct { sampler *zaputil.Sampler minLevel zapcore.LevelEnabler componentMinLeveler ZapComponentMinLeveler + enablers *enablerCache } // componentMinLevel returns the min leveler's opinion on component, or nil. @@ -265,6 +259,55 @@ func (l *zapLogger[T]) componentMinLevel(component string) zapcore.LevelEnabler return l.componentMinLeveler.ComponentMinLevel(component) } +type enablerCache struct { + mu sync.Mutex + writes map[string]*zaputil.WriteEnabler + levels map[string]zapcore.LevelEnabler +} + +func newEnablerCache(ml ZapComponentMinLeveler) *enablerCache { + if ml == nil { + return nil + } + return &enablerCache{} +} + +func (c *enablerCache) write(component string, build func() *zaputil.WriteEnabler) *zaputil.WriteEnabler { + if c == nil { + return build() + } + + c.mu.Lock() + defer c.mu.Unlock() + if enab, ok := c.writes[component]; ok { + return enab + } + enab := build() + if c.writes == nil { + c.writes = map[string]*zaputil.WriteEnabler{} + } + c.writes[component] = enab + return enab +} + +func (c *enablerCache) level(component string, build func() zapcore.LevelEnabler) zapcore.LevelEnabler { + if c == nil { + return build() + } + + c.mu.Lock() + defer c.mu.Unlock() + if enab, ok := c.levels[component]; ok { + return enab + } + enab := build() + if c.levels == nil { + c.levels = map[string]zapcore.LevelEnabler{} + } + c.levels[component] = enab + return enab +} + func FromZapLogger(log *zap.Logger, conf *Config, opts ...ZapLoggerOption) (ZapLogger, error) { if log == nil { log = zap.New(nil).WithOptions(zap.AddCaller(), zap.AddStacktrace(zap.ErrorLevel)) @@ -319,15 +362,15 @@ func newZapLogger[T zaputil.Encoder[T]](zap *zap.SugaredLogger, zc *zapConfig, e func (l *zapLogger[T]) makeZap() *zap.SugaredLogger { var console *zaputil.WriteEnabler - // writeEnablers is shared by every logger built from this config, so it can - // only cache enablers that depend on nothing but the component. if componentMinLevel := l.componentMinLevel(l.component); componentMinLevel == nil && l.minLevel == nil { console, _ = l.writeEnablers.LoadOrCompute(l.component, func() (*zaputil.WriteEnabler, bool) { return zaputil.NewWriteEnabler(os.Stderr, l.sc.ComponentLevel(l.component)), false }) } else { - enab := zaputil.NewOrLevelEnabler(l.minLevel, l.sc.ComponentLevel(l.component), componentMinLevel) - console = zaputil.NewWriteEnabler(os.Stderr, enab) + console = l.enablers.write(l.component, func() *zaputil.WriteEnabler { + enab := zaputil.NewOrLevelEnabler(l.minLevel, l.sc.ComponentLevel(l.component), componentMinLevel) + return zaputil.NewWriteEnabler(os.Stderr, enab) + }) } c := l.enc.Core(console, l.tap) @@ -354,12 +397,10 @@ func (l zapLoggerComponentLeveler[T]) ComponentLevel(component string) zapcore.L component = l.zl.component + "." + component } - // Note this reports the logger's component min leveler but not its min - // level: see ZapLogger.WithMinLevel. levelEnablers is shared by every - // logger built from this config, so a min leveler's opinion, which is - // particular to one logger, must not be cached in it. if override := l.zl.componentMinLevel(component); override != nil { - return zaputil.OrLevelEnabler{l.zl.sc.ComponentLevel(component), l.zl.tap, override} + return l.zl.enablers.level(component, func() zapcore.LevelEnabler { + return zaputil.NewOrLevelEnabler(l.zl.sc.ComponentLevel(component), l.zl.tap, override) + }) } enab, _ := l.zl.levelEnablers.LoadOrCompute(component, func() (*zaputil.OrLevelEnabler, bool) { @@ -379,6 +420,7 @@ func (l *zapLogger[T]) Debugw(msg string, keysAndValues ...any) { func (l *zapLogger[T]) WithComponentMinLeveler(ml ZapComponentMinLeveler) Logger { dup := *l dup.componentMinLeveler = ml + dup.enablers = newEnablerCache(ml) dup.zap = dup.makeZap() return &dup } @@ -386,6 +428,7 @@ func (l *zapLogger[T]) WithComponentMinLeveler(ml ZapComponentMinLeveler) Logger func (l *zapLogger[T]) WithMinLevel(lvl zapcore.LevelEnabler) Logger { dup := *l dup.minLevel = lvl + dup.enablers = newEnablerCache(dup.componentMinLeveler) dup.zap = dup.makeZap() return &dup } diff --git a/logger/pionlogger/minlevel_test.go b/logger/pionlogger/minlevel_test.go index 9560b0106..3d8bf4d23 100644 --- a/logger/pionlogger/minlevel_test.go +++ b/logger/pionlogger/minlevel_test.go @@ -142,4 +142,65 @@ func TestMinLevelReachesPionComponents(t *testing.T) { require.Contains(t, out, "overridden-ice-debug") require.NotContains(t, out, "last-ice-debug") }) + + // pion asks the factory for a logger per object, not per peer connection - + // once per RTPReceiver, per data channel, per stream - so the same + // component is resolved over and over for one participant. + t.Run("resolving a component repeatedly does not allocate", func(t *testing.T) { + base, err := logger.NewZapLogger(&logger.Config{ + Level: "info", + ComponentLevels: map[string]string{"transport.pion": "warn"}, + }) + require.NoError(t, err) + + proj := base.WithComponentMinLeveler(componentMinLeveler{"transport.pion.ice": debugLevel()}) + leveler := proj.WithComponent("transport").(logger.ZapLogger).ComponentLeveler() + require.True(t, leveler.ComponentLevel("pion.ice").Enabled(zapcore.DebugLevel)) + require.False(t, leveler.ComponentLevel("pion.sctp").Enabled(zapcore.DebugLevel)) + + // sctp has no override and so takes the levels cached for every logger + // at once; ice must cost the same, both of them only the component path + // this builds to look itself up by + overridden := testing.AllocsPerRun(100, func() { _ = leveler.ComponentLevel("pion.ice") }) + plain := testing.AllocsPerRun(100, func() { _ = leveler.ComponentLevel("pion.sctp") }) + require.Equal(t, plain, overridden) + }) + + // A memoized enabler holds the atomic levels themselves, so it keeps + // tracking config after it is cached. + t.Run("cached enablers follow a config reload", func(t *testing.T) { + conf := &logger.Config{ + Level: "info", + ComponentLevels: map[string]string{"transport.pion": "warn"}, + } + + r, w, err := os.Pipe() + require.NoError(t, err) + + orig := os.Stderr + os.Stderr = w + + func() { + defer func() { os.Stderr = orig }() + + base, err := logger.NewZapLogger(conf) + require.NoError(t, err) + + level := zap.NewAtomicLevelAt(zapcore.WarnLevel) + proj := base.WithComponentMinLeveler(componentMinLeveler{"transport.pion.ice": level}) + + // caches the enabler at warn + pionDebug(proj, "ice", "before-reload-debug") + + level.SetLevel(zapcore.DebugLevel) + pionDebug(proj, "ice", "after-reload-debug") + }() + + require.NoError(t, w.Close()) + out, err := io.ReadAll(r) + require.NoError(t, err) + + require.NotContains(t, string(out), "before-reload-debug") + require.Contains(t, string(out), "after-reload-debug", "a cached enabler must hold the level, not its value") + }) }