Add compoment min level logging

logger/logger.go

@@ -227,21 +227,85 @@ type ZapComponentLeveler interface {
 	ComponentLevel(component string) zapcore.LevelEnabler
 }
 
+type ZapComponentMinLeveler interface {
+	ComponentMinLevel(component string) zapcore.LevelEnabler
+}
+
 type ZapLogger interface {
 	Logger
 	ToZap() *zap.SugaredLogger
 	ComponentLeveler() ZapComponentLeveler
 	WithMinLevel(lvl zapcore.LevelEnabler) Logger
+	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
+	enablers            *enablerCache
+}
+
+// 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)
+}
+
+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) {
@@ -298,13 +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
-	if l.minLevel == nil {
+	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)}
-		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)
@@ -331,6 +397,12 @@ func (l zapLoggerComponentLeveler[T]) ComponentLevel(component string) zapcore.L
 		component = l.zl.component + "." + component
 	}
 
+	if override := l.zl.componentMinLevel(component); override != nil {
+		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) {
 		return &zaputil.OrLevelEnabler{l.zl.sc.ComponentLevel(component), l.zl.tap}, false
 	})
@@ -345,9 +417,18 @@ 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.enablers = newEnablerCache(ml)
+	dup.zap = dup.makeZap()
+	return &dup
+}
+
 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
 }

logger/pionlogger/minlevel_test.go

@@ -0,0 +1,206 @@
+// 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: {<id>: 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")
+	})
+
+	// 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")
+	})
+}

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
 }