logger: caller's skip correction (#2280)

logger/helper.go

@@ -6,11 +6,11 @@ import (
 )
 
 type Helper struct {
-	Logger
+	logger Logger
 }
 
-func NewHelper(log Logger) *Helper {
-	return &Helper{Logger: log}
+func NewHelper(logger Logger) *Helper {
+	return &Helper{logger: logger}
 }
 
 // Extract always returns valid Helper with logger from context or with DefaultLogger as fallback.
@@ -24,96 +24,104 @@ func Extract(ctx context.Context) *Helper {
 	return NewHelper(DefaultLogger)
 }
 
+func (h *Helper) Log(level Level, args ...interface{}) {
+	h.logger.Log(level, args...)
+}
+
+func (h *Helper) Logf(level Level, template string, args ...interface{}) {
+	h.logger.Logf(level, template, args...)
+}
+
 func (h *Helper) Info(args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(InfoLevel) {
+	if !h.logger.Options().Level.Enabled(InfoLevel) {
 		return
 	}
-	h.Log(InfoLevel, args...)
+	h.logger.Log(InfoLevel, args...)
 }
 
 func (h *Helper) Infof(template string, args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(InfoLevel) {
+	if !h.logger.Options().Level.Enabled(InfoLevel) {
 		return
 	}
-	h.Logf(InfoLevel, template, args...)
+	h.logger.Logf(InfoLevel, template, args...)
 }
 
 func (h *Helper) Trace(args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(TraceLevel) {
+	if !h.logger.Options().Level.Enabled(TraceLevel) {
 		return
 	}
-	h.Log(TraceLevel, args...)
+	h.logger.Log(TraceLevel, args...)
 }
 
 func (h *Helper) Tracef(template string, args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(TraceLevel) {
+	if !h.logger.Options().Level.Enabled(TraceLevel) {
 		return
 	}
-	h.Logf(TraceLevel, template, args...)
+	h.logger.Logf(TraceLevel, template, args...)
 }
 
 func (h *Helper) Debug(args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(DebugLevel) {
+	if !h.logger.Options().Level.Enabled(DebugLevel) {
 		return
 	}
-	h.Log(DebugLevel, args...)
+	h.logger.Log(DebugLevel, args...)
 }
 
 func (h *Helper) Debugf(template string, args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(DebugLevel) {
+	if !h.logger.Options().Level.Enabled(DebugLevel) {
 		return
 	}
-	h.Logf(DebugLevel, template, args...)
+	h.logger.Logf(DebugLevel, template, args...)
 }
 
 func (h *Helper) Warn(args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(WarnLevel) {
+	if !h.logger.Options().Level.Enabled(WarnLevel) {
 		return
 	}
-	h.Log(WarnLevel, args...)
+	h.logger.Log(WarnLevel, args...)
 }
 
 func (h *Helper) Warnf(template string, args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(WarnLevel) {
+	if !h.logger.Options().Level.Enabled(WarnLevel) {
 		return
 	}
-	h.Logf(WarnLevel, template, args...)
+	h.logger.Logf(WarnLevel, template, args...)
 }
 
 func (h *Helper) Error(args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(ErrorLevel) {
+	if !h.logger.Options().Level.Enabled(ErrorLevel) {
 		return
 	}
-	h.Log(ErrorLevel, args...)
+	h.logger.Log(ErrorLevel, args...)
 }
 
 func (h *Helper) Errorf(template string, args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(ErrorLevel) {
+	if !h.logger.Options().Level.Enabled(ErrorLevel) {
 		return
 	}
-	h.Logf(ErrorLevel, template, args...)
+	h.logger.Logf(ErrorLevel, template, args...)
 }
 
 func (h *Helper) Fatal(args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(FatalLevel) {
+	if !h.logger.Options().Level.Enabled(FatalLevel) {
 		return
 	}
-	h.Log(FatalLevel, args...)
+	h.logger.Log(FatalLevel, args...)
 	os.Exit(1)
 }
 
 func (h *Helper) Fatalf(template string, args ...interface{}) {
-	if !h.Logger.Options().Level.Enabled(FatalLevel) {
+	if !h.logger.Options().Level.Enabled(FatalLevel) {
 		return
 	}
-	h.Logf(FatalLevel, template, args...)
+	h.logger.Logf(FatalLevel, template, args...)
 	os.Exit(1)
 }
 
 func (h *Helper) WithError(err error) *Helper {
-	return &Helper{Logger: h.Logger.Fields(map[string]interface{}{"error": err})}
+	return &Helper{logger: h.logger.Fields(map[string]interface{}{"error": err})}
 }
 
 func (h *Helper) WithFields(fields map[string]interface{}) *Helper {
-	return &Helper{Logger: h.Logger.Fields(fields)}
+	return &Helper{logger: h.logger.Fields(fields)}
 }

logger/logger_test.go

@@ -6,7 +6,8 @@ import (
 )
 
 func TestLogger(t *testing.T) {
-	l := NewLogger(WithLevel(TraceLevel))
+	l := NewLogger(WithLevel(TraceLevel), WithCallerSkipCount(2))
+
 	h1 := NewHelper(l).WithFields(map[string]interface{}{"key1": "val1"})
 	h1.Log(TraceLevel, "simple log before trace_msg1")
 	h1.Trace("trace_msg1")
@@ -19,11 +20,12 @@ func TestLogger(t *testing.T) {
 	h2.Logf(TraceLevel, "formatted log after trace_msg%s", "2")
 	h2.Warn("warn_msg2")
 
+	l = NewLogger(WithLevel(TraceLevel), WithCallerSkipCount(1))
 	l.Fields(map[string]interface{}{"key3": "val4"}).Log(InfoLevel, "test_msg")
 }
 
 func TestExtract(t *testing.T) {
-	l := NewLogger(WithLevel(TraceLevel)).Fields(map[string]interface{}{"requestID": "req-1"})
+	l := NewLogger(WithLevel(TraceLevel), WithCallerSkipCount(2)).Fields(map[string]interface{}{"requestID": "req-1"})
 
 	ctx := NewContext(context.Background(), l)
 

plugins/logger/zap/options.go

@@ -11,12 +11,6 @@ type Options struct {
 	logger.Options
 }
 
-type callerSkipKey struct{}
-
-func WithCallerSkip(i int) logger.Option {
-	return logger.SetOption(callerSkipKey{}, i)
-}
-
 type configKey struct{}
 
 // WithConfig pass zap.Config to logger

plugins/logger/zap/zap.go

@@ -37,18 +37,13 @@ func (l *zaplog) Init(opts ...logger.Option) error {
 
 	}
 
-	skip, ok := l.opts.Context.Value(callerSkipKey{}).(int)
-	if !ok || skip < 1 {
-		skip = 1
-	}
-
 	// Set log Level if not default
 	zapConfig.Level = zap.NewAtomicLevel()
 	if l.opts.Level != logger.InfoLevel {
 		zapConfig.Level.SetLevel(loggerToZapLevel(l.opts.Level))
 	}
 
-	log, err := zapConfig.Build(zap.AddCallerSkip(skip))
+	log, err := zapConfig.Build(zap.AddCallerSkip(l.opts.CallerSkipCount))
 	if err != nil {
 		return err
 	}
@@ -166,10 +161,11 @@ func (l *zaplog) Options() logger.Options {
 func NewLogger(opts ...logger.Option) (logger.Logger, error) {
 	// Default options
 	options := logger.Options{
-		Level:   logger.InfoLevel,
-		Fields:  make(map[string]interface{}),
-		Out:     os.Stderr,
-		Context: context.Background(),
+		Level:           logger.InfoLevel,
+		Fields:          make(map[string]interface{}),
+		Out:             os.Stderr,
+		Context:         context.Background(),
+		CallerSkipCount: 2,
 	}
 
 	l := &zaplog{opts: options}

plugins/logger/zap/zap_test.go

@@ -20,7 +20,8 @@ func TestName(t *testing.T) {
 }
 
 func TestLogf(t *testing.T) {
-	l, err := NewLogger()
+	// skip is 2, because we call logger through logger package
+	l, err := NewLogger(logger.WithCallerSkipCount(2))
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -30,7 +31,8 @@ func TestLogf(t *testing.T) {
 }
 
 func TestSetLevel(t *testing.T) {
-	l, err := NewLogger()
+	// skip is 1, because we call logger directly
+	l, err := NewLogger(logger.WithCallerSkipCount(1))
 	if err != nil {
 		t.Fatal(err)
 	}

plugins/logger/zerolog/zerolog.go

@@ -53,10 +53,14 @@ func (l *zeroLogger) Init(opts ...logger.Option) error {
 		l.opts.Mode = Production
 	}
 
+	skip := 4
+	if l.opts.CallerSkipCount > 0 {
+		skip = l.opts.CallerSkipCount
+	}
 	// RESET
 	zerolog.TimeFieldFormat = time.RFC3339
 	zerolog.ErrorStackMarshaler = nil
-	zerolog.CallerSkipFrameCount = 4
+	zerolog.CallerSkipFrameCount = skip
 
 	switch l.opts.Mode {
 	case Development:
@@ -94,7 +98,7 @@ func (l *zeroLogger) Init(opts ...logger.Option) error {
 	if l.opts.ReportCaller {
 		l.zLog = l.zLog.With().Caller().Logger()
 	}
-	
+
 	// Adding hooks if exist
 	for _, hook := range l.opts.Hooks {
 		l.zLog = l.zLog.Hook(hook)