From 8394d501fd50622c4288aacb1c8e77df7a90e20a Mon Sep 17 00:00:00 2001 From: Paul Wells Date: Sat, 12 Oct 2024 23:26:06 -0700 Subject: [PATCH] fix logger callers (#850) --- logger/logger.go | 28 +++++++------ logger/logger_test.go | 96 +++++++++++++++++++++++++++++++++++++++---- 2 files changed, 104 insertions(+), 20 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 0c1c73a8..fc1e8203 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -52,9 +52,9 @@ func GetLogger() Logger { // SetLogger lets you use a custom logger. Pass in a logr.Logger with default depth func SetLogger(l Logger, name string) { - defaultLogger = l.WithCallDepth(1).WithName(name) + defaultLogger = l.WithName(name) // pkg wrapper needs to drop two levels of depth - pkgLogger = l.WithCallDepth(2).WithName(name) + pkgLogger = l.WithCallDepth(1).WithName(name) } func Debugw(msg string, keysAndValues ...any) { @@ -106,7 +106,7 @@ type UnlikelyLogger struct { } func (l UnlikelyLogger) makeLogger() Logger { - return l.logger.WithCallDepth(2) + return l.logger.WithCallDepth(1) } func (l UnlikelyLogger) Debugw(msg string, keysAndValues ...any) { @@ -237,7 +237,7 @@ func FromZapLogger(log *zap.Logger, conf *Config, opts ...ZapLoggerOption) (ZapL if log == nil { log = zap.New(nil).WithOptions(zap.AddCaller(), zap.AddStacktrace(zap.ErrorLevel)) } - zap := log.Sugar() + zap := log.WithOptions(zap.AddCallerSkip(1)).Sugar() zc := &zapConfig{ conf: conf, @@ -281,11 +281,11 @@ func newZapLogger[T zaputil.Encoder[T]](zap *zap.SugaredLogger, zc *zapConfig, e enc: enc, sampler: sampler, } - l.zap = l.ToZap() + l.zap = l.makeZap() return l } -func (l *zapLogger[T]) ToZap() *zap.SugaredLogger { +func (l *zapLogger[T]) makeZap() *zap.SugaredLogger { var console *zaputil.WriteEnabler if l.minLevel == nil { console, _ = l.writeEnablers.LoadOrCompute(l.component, func() *zaputil.WriteEnabler { @@ -307,6 +307,10 @@ func (l *zapLogger[T]) ToZap() *zap.SugaredLogger { return l.zap.WithOptions(zap.WrapCore(func(zapcore.Core) zapcore.Core { return c })) } +func (l *zapLogger[T]) ToZap() *zap.SugaredLogger { + return l.zap.WithOptions(zap.AddCallerSkip(-1)) +} + type zapLoggerComponentLeveler[T zaputil.Encoder[T]] struct { zl *zapLogger[T] } @@ -333,7 +337,7 @@ func (l *zapLogger[T]) Debugw(msg string, keysAndValues ...any) { func (l *zapLogger[T]) WithMinLevel(lvl zapcore.LevelEnabler) Logger { dup := *l dup.minLevel = lvl - dup.zap = dup.ToZap() + dup.zap = dup.makeZap() return &dup } @@ -358,7 +362,7 @@ func (l *zapLogger[T]) Errorw(msg string, err error, keysAndValues ...any) { func (l *zapLogger[T]) WithValues(keysAndValues ...any) Logger { dup := *l dup.enc = dup.enc.WithValues(keysAndValues...) - dup.zap = dup.ToZap() + dup.zap = dup.makeZap() return &dup } @@ -380,7 +384,7 @@ func (l *zapLogger[T]) WithComponent(component string) Logger { } else { dup.component = dup.component + "." + component } - dup.zap = dup.ToZap() + dup.zap = dup.makeZap() return &dup } @@ -400,14 +404,14 @@ func (l *zapLogger[T]) WithItemSampler() Logger { l.conf.ItemSampleInitial, l.conf.ItemSampleInterval, ) - dup.zap = dup.ToZap() + dup.zap = dup.makeZap() return &dup } func (l *zapLogger[T]) WithoutSampler() Logger { dup := *l dup.sampler = nil - dup.zap = dup.ToZap() + dup.zap = dup.makeZap() return &dup } @@ -415,7 +419,7 @@ func (l *zapLogger[T]) WithDeferredValues() (Logger, DeferredFieldResolver) { dup := *l def, resolve := zaputil.NewDeferrer() dup.deferred = append(dup.deferred, def) - dup.zap = dup.ToZap() + dup.zap = dup.makeZap() return &dup, resolve } diff --git a/logger/logger_test.go b/logger/logger_test.go index e8dfb47e..4115445e 100644 --- a/logger/logger_test.go +++ b/logger/logger_test.go @@ -3,6 +3,9 @@ package logger import ( "bytes" "encoding/json" + "fmt" + "runtime" + "strings" "testing" "github.com/stretchr/testify/require" @@ -10,6 +13,7 @@ import ( "go.uber.org/zap/zapcore" "github.com/livekit/protocol/logger/zaputil" + "github.com/livekit/protocol/utils/must" ) func zapLoggerCore(l Logger) zapcore.Core { @@ -85,14 +89,8 @@ func TestLoggerComponent(t *testing.T) { require.NoError(t, err) l.Debugw("foo", "bar", "baz") - var log struct { - Level string - TS float64 - Caller string - Msg string - Bar string - } - require.NoError(t, json.Unmarshal(ws.Bytes(), &log)) + log, err := unmarshalTestLogOutput(ws.Bytes()) + require.NoError(t, err) require.Equal(t, "debug", log.Level) require.NotEqual(t, 0, log.TS) @@ -118,8 +116,90 @@ func TestLoggerComponent(t *testing.T) { }) } +type testLogOutput struct { + Level string + TS float64 + Caller string + Msg string + Bar string +} + +func unmarshalTestLogOutput(b []byte) (*testLogOutput, error) { + log := &testLogOutput{} + return log, json.Unmarshal(b, &log) +} + type testBufferedWriteSyncer struct { bytes.Buffer } func (t *testBufferedWriteSyncer) Sync() error { return nil } + +func testLogCaller(logFunc func(msg string, keysAndValues ...any)) { + logFunc("test") +} + +func getTestLogCallerCaller() string { + var caller string + testLogCaller(func(string, ...any) { + _, file, line, _ := runtime.Caller(1) + caller = fmt.Sprintf("%s:%d", file, line) + }) + return caller +} + +func TestLoggerCallDepth(t *testing.T) { + caller := getTestLogCallerCaller() + + t.Run("NewZapLogger", func(t *testing.T) { + ws := &testBufferedWriteSyncer{} + l := must.Get(NewZapLogger(&Config{}, WithTap(zaputil.NewWriteEnabler(ws, zapcore.DebugLevel)))) + + testLogCaller(l.Debugw) + log := must.Get(unmarshalTestLogOutput(ws.Bytes())) + + require.True(t, strings.HasSuffix(caller, log.Caller), `caller mismatch expected suffix match on "%s" got "%s"`, caller, log.Caller) + }) + + t.Run("package logger", func(t *testing.T) { + ws := &testBufferedWriteSyncer{} + l := must.Get(NewZapLogger(&Config{}, WithTap(zaputil.NewWriteEnabler(ws, zapcore.DebugLevel)))) + SetLogger(l, "TEST") + + testLogCaller(Debugw) + log := must.Get(unmarshalTestLogOutput(ws.Bytes())) + + require.True(t, strings.HasSuffix(caller, log.Caller), `caller mismatch expected suffix match on "%s" got "%s"`, caller, log.Caller) + }) + + t.Run("GetLogger", func(t *testing.T) { + ws := &testBufferedWriteSyncer{} + l := must.Get(NewZapLogger(&Config{}, WithTap(zaputil.NewWriteEnabler(ws, zapcore.DebugLevel)))) + SetLogger(l, "TEST") + + testLogCaller(GetLogger().Debugw) + log := must.Get(unmarshalTestLogOutput(ws.Bytes())) + + require.True(t, strings.HasSuffix(caller, log.Caller), `caller mismatch expected suffix match on "%s" got "%s"`, caller, log.Caller) + }) + + t.Run("ToZap", func(t *testing.T) { + ws := &testBufferedWriteSyncer{} + l := must.Get(NewZapLogger(&Config{}, WithTap(zaputil.NewWriteEnabler(ws, zapcore.DebugLevel)))) + + testLogCaller(l.ToZap().Debugw) + log := must.Get(unmarshalTestLogOutput(ws.Bytes())) + + require.True(t, strings.HasSuffix(caller, log.Caller), `caller mismatch expected suffix match on "%s" got "%s"`, caller, log.Caller) + }) + + t.Run("WithUnlikelyValues", func(t *testing.T) { + ws := &testBufferedWriteSyncer{} + l := must.Get(NewZapLogger(&Config{}, WithTap(zaputil.NewWriteEnabler(ws, zapcore.DebugLevel)))) + + testLogCaller(l.WithUnlikelyValues().Debugw) + log := must.Get(unmarshalTestLogOutput(ws.Bytes())) + + require.True(t, strings.HasSuffix(caller, log.Caller), `caller mismatch expected suffix match on "%s" got "%s"`, caller, log.Caller) + }) +}