From 916ed6b8eeaec96f112a63e33e2d0b1c39356eef Mon Sep 17 00:00:00 2001 From: Arsen Date: Wed, 22 Sep 2021 11:01:03 +0300 Subject: [PATCH] logger: caller's skip correction (#2280) --- logger/helper.go | 66 +++++++++++++++++-------------- logger/logger_test.go | 6 ++- plugins/logger/zap/options.go | 6 --- plugins/logger/zap/zap.go | 16 +++----- plugins/logger/zap/zap_test.go | 6 ++- plugins/logger/zerolog/zerolog.go | 8 +++- 6 files changed, 57 insertions(+), 51 deletions(-) diff --git a/logger/helper.go b/logger/helper.go index 41466066..b182b073 100644 --- a/logger/helper.go +++ b/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)} } diff --git a/logger/logger_test.go b/logger/logger_test.go index 3efcb7b9..19fe59bf 100644 --- a/logger/logger_test.go +++ b/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) diff --git a/plugins/logger/zap/options.go b/plugins/logger/zap/options.go index 8444d3d2..44ebd27a 100644 --- a/plugins/logger/zap/options.go +++ b/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 diff --git a/plugins/logger/zap/zap.go b/plugins/logger/zap/zap.go index bfaa0ecf..b9623216 100644 --- a/plugins/logger/zap/zap.go +++ b/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} diff --git a/plugins/logger/zap/zap_test.go b/plugins/logger/zap/zap_test.go index 9caae91c..a6e084a6 100644 --- a/plugins/logger/zap/zap_test.go +++ b/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) } diff --git a/plugins/logger/zerolog/zerolog.go b/plugins/logger/zerolog/zerolog.go index 33fd35aa..4bef803d 100644 --- a/plugins/logger/zerolog/zerolog.go +++ b/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)