Skip to content

Commit

Permalink
fix logger callers (#850)
Browse files Browse the repository at this point in the history
  • Loading branch information
@paulwe
paulwe committed Oct 13, 2024
1 parent de5ac83 commit 8394d50
Show file tree
Hide file tree
Showing 2 changed files with 104 additions and 20 deletions.
28 changes: 16 additions & 12 deletions logger/logger.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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 {
Expand All @@ -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]
}
Expand All @@ -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
}

Expand All @@ -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
}

Expand All @@ -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
}

Expand All @@ -400,22 +404,22 @@ 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
}

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
}

Expand Down
96 changes: 88 additions & 8 deletions logger/logger_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,13 +3,17 @@ package logger
import (
"bytes"
"encoding/json"
"fmt"
"runtime"
"strings"
"testing"

"github.com/stretchr/testify/require"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"

"github.com/livekit/protocol/logger/zaputil"
"github.com/livekit/protocol/utils/must"
)

func zapLoggerCore(l Logger) zapcore.Core {
Expand Down Expand Up @@ -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)
Expand All @@ -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)
})
}

0 comments on commit 8394d50

Please sign in to comment.