From b06285be6af24a8531871287cda7a68331c58d7d Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Thu, 6 May 2021 15:44:12 -0700 Subject: [PATCH 1/8] Add event.CallerSkipFrame(skip int) This indicates that, for this event, we should skip an additional specified number of frames. This is cumulative, calling it twice for the same event will add both numbers together, and this is in addition to any skip frame settings set through the context, or globally. The indended purpose is for wrappers to Msg or Msgf, so that the actual caller is always printed correctly. --- event.go | 23 ++++++++++++++++------- 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/event.go b/event.go index f1829bea..51990792 100644 --- a/event.go +++ b/event.go @@ -20,12 +20,13 @@ var eventPool = &sync.Pool{ // Event represents a log event. It is instanced by one of the level method of // Logger and finalized by the Msg or Msgf method. type Event struct { - buf []byte - w LevelWriter - level Level - done func(msg string) - stack bool // enable error stack trace - ch []Hook // hooks from context + buf []byte + w LevelWriter + level Level + done func(msg string) + stack bool // enable error stack trace + ch []Hook // hooks from context + callerSkipFrameCount int // The number of additional frames to skip when printing the caller. } func putEvent(e *Event) { @@ -62,6 +63,7 @@ func newEvent(w LevelWriter, level Level) *Event { e.w = w e.level = level e.stack = false + e.callerSkipFrameCount = 0 return e } @@ -685,6 +687,13 @@ func (e *Event) Interface(key string, i interface{}) *Event { return e } +// CallerSkipFrame instructs any future Caller calls to skip the specified number of frames. +// This includes those added via hooks from the context. +func (e *Event) CallerSkipFrame(skip int) *Event { + e.callerSkipFrameCount++ + return e +} + // Caller adds the file:line of the caller with the zerolog.CallerFieldName key. // The argument skip is the number of stack frames to ascend // Skip If not passed, use the global variable CallerSkipFrameCount @@ -700,7 +709,7 @@ func (e *Event) caller(skip int) *Event { if e == nil { return e } - _, file, line, ok := runtime.Caller(skip) + _, file, line, ok := runtime.Caller(skip + e.callerSkipFrameCount) if !ok { return e } From 5d7ae343d7df7d1051863e8e0abe5bbadf06187e Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Thu, 6 May 2021 15:47:04 -0700 Subject: [PATCH 2/8] Use CallerSkipFrame for Print, Printf, and Write. This allows us to use the correct caller when using these 3 functions. --- log.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/log.go b/log.go index 4779e8cc..9451da09 100644 --- a/log.go +++ b/log.go @@ -392,6 +392,7 @@ func (l *Logger) Log() *Event { // Arguments are handled in the manner of fmt.Print. func (l *Logger) Print(v ...interface{}) { if e := l.Debug(); e.Enabled() { + e.CallerSkipFrame(1) e.Msg(fmt.Sprint(v...)) } } @@ -400,6 +401,7 @@ func (l *Logger) Print(v ...interface{}) { // Arguments are handled in the manner of fmt.Printf. func (l *Logger) Printf(format string, v ...interface{}) { if e := l.Debug(); e.Enabled() { + e.CallerSkipFrame(1) e.Msg(fmt.Sprintf(format, v...)) } } @@ -412,6 +414,7 @@ func (l Logger) Write(p []byte) (n int, err error) { // Trim CR added by stdlog. p = p[0 : n-1] } + e.CallerSkipFrame(1) l.Log().Msg(string(p)) return } From 1f7c3da8d83915119b992b9938348f14e355e3d4 Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Thu, 6 May 2021 15:47:41 -0700 Subject: [PATCH 3/8] Rework Print and Printf. These now use CallerSkipFrame, this means that they can no longer pass down to the Logger.Print/Printf functions. As such, we now use Logger.Debug() to get an event, call CallerSkipFrame, and then use either .Msg or .Msgf to print the message. But we get correct caller logs, and this is essentially the same thing that Logger.Print and Logger.Printf are doing. --- log/log.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/log/log.go b/log/log.go index b96f1c14..a96ec506 100644 --- a/log/log.go +++ b/log/log.go @@ -3,6 +3,7 @@ package log import ( "context" + "fmt" "io" "os" @@ -114,13 +115,13 @@ func Log() *zerolog.Event { // Print sends a log event using debug level and no extra field. // Arguments are handled in the manner of fmt.Print. func Print(v ...interface{}) { - Logger.Print(v...) + Logger.Debug().CallerSkipFrame(1).Msg(fmt.Sprint(v...)) } // Printf sends a log event using debug level and no extra field. // Arguments are handled in the manner of fmt.Printf. func Printf(format string, v ...interface{}) { - Logger.Printf(format, v...) + Logger.Debug().CallerSkipFrame(1).Msgf(format, v...) } // Ctx returns the Logger associated with the ctx. If no logger From 3d15cd96b297c50fb0e980abbf94883c597572d7 Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Thu, 6 May 2021 23:32:40 -0700 Subject: [PATCH 4/8] Rename callerSkipFrameCount to skipFrame. Code review request. --- event.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/event.go b/event.go index 51990792..561450c8 100644 --- a/event.go +++ b/event.go @@ -20,13 +20,13 @@ var eventPool = &sync.Pool{ // Event represents a log event. It is instanced by one of the level method of // Logger and finalized by the Msg or Msgf method. type Event struct { - buf []byte - w LevelWriter - level Level - done func(msg string) - stack bool // enable error stack trace - ch []Hook // hooks from context - callerSkipFrameCount int // The number of additional frames to skip when printing the caller. + buf []byte + w LevelWriter + level Level + done func(msg string) + stack bool // enable error stack trace + ch []Hook // hooks from context + skipFrame int // The number of additional frames to skip when printing the caller. } func putEvent(e *Event) { @@ -63,7 +63,7 @@ func newEvent(w LevelWriter, level Level) *Event { e.w = w e.level = level e.stack = false - e.callerSkipFrameCount = 0 + e.skipFrame = 0 return e } @@ -690,7 +690,7 @@ func (e *Event) Interface(key string, i interface{}) *Event { // CallerSkipFrame instructs any future Caller calls to skip the specified number of frames. // This includes those added via hooks from the context. func (e *Event) CallerSkipFrame(skip int) *Event { - e.callerSkipFrameCount++ + e.skipFrame++ return e } @@ -709,7 +709,7 @@ func (e *Event) caller(skip int) *Event { if e == nil { return e } - _, file, line, ok := runtime.Caller(skip + e.callerSkipFrameCount) + _, file, line, ok := runtime.Caller(skip + e.skipFrame) if !ok { return e } From 3326547548fb5fe2a8e6d4db82a7f692a17d6073 Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Thu, 6 May 2021 23:33:31 -0700 Subject: [PATCH 5/8] Inline the CallerSkipFrame work. Code review request. --- log.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/log.go b/log.go index 9451da09..7c4ba7c5 100644 --- a/log.go +++ b/log.go @@ -392,7 +392,7 @@ func (l *Logger) Log() *Event { // Arguments are handled in the manner of fmt.Print. func (l *Logger) Print(v ...interface{}) { if e := l.Debug(); e.Enabled() { - e.CallerSkipFrame(1) + e.skipFrame++ e.Msg(fmt.Sprint(v...)) } } @@ -401,7 +401,7 @@ func (l *Logger) Print(v ...interface{}) { // Arguments are handled in the manner of fmt.Printf. func (l *Logger) Printf(format string, v ...interface{}) { if e := l.Debug(); e.Enabled() { - e.CallerSkipFrame(1) + e.skipFrame++ e.Msg(fmt.Sprintf(format, v...)) } } From 99c9830747e5fbe673073f2600e78ba9758cf0df Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Thu, 6 May 2021 23:33:48 -0700 Subject: [PATCH 6/8] Fix skip frame logic in Write. This didn't even compile. Another reminder that a quick change while tired is never a good idea. --- log.go | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/log.go b/log.go index 7c4ba7c5..0ac8d66b 100644 --- a/log.go +++ b/log.go @@ -414,8 +414,7 @@ func (l Logger) Write(p []byte) (n int, err error) { // Trim CR added by stdlog. p = p[0 : n-1] } - e.CallerSkipFrame(1) - l.Log().Msg(string(p)) + l.Log().CallerSkipFrame(1).Msg(string(p)) return } From bdfa5fe2015622e12817a668b461f15fddfa3f9a Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Mon, 10 May 2021 12:53:15 -0700 Subject: [PATCH 7/8] Fix the CallerSkipFrame increment. We were ignoring the argument, oops. --- event.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/event.go b/event.go index 561450c8..ff6ff24f 100644 --- a/event.go +++ b/event.go @@ -690,7 +690,7 @@ func (e *Event) Interface(key string, i interface{}) *Event { // CallerSkipFrame instructs any future Caller calls to skip the specified number of frames. // This includes those added via hooks from the context. func (e *Event) CallerSkipFrame(skip int) *Event { - e.skipFrame++ + e.skipFrame += skip return e } From c4fdee1083e685bdb49b29f6ec1abff72e9d96f1 Mon Sep 17 00:00:00 2001 From: "Zephaniah E. Loss-Cutler-Hull" Date: Mon, 10 May 2021 12:53:36 -0700 Subject: [PATCH 8/8] Fix our inline of the CallerSkipFrame. A ever so slight misunderstanding of the code review request. --- log.go | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/log.go b/log.go index 0ac8d66b..e6ed76b2 100644 --- a/log.go +++ b/log.go @@ -392,8 +392,7 @@ func (l *Logger) Log() *Event { // Arguments are handled in the manner of fmt.Print. func (l *Logger) Print(v ...interface{}) { if e := l.Debug(); e.Enabled() { - e.skipFrame++ - e.Msg(fmt.Sprint(v...)) + e.CallerSkipFrame(1).Msg(fmt.Sprint(v...)) } } @@ -401,8 +400,7 @@ func (l *Logger) Print(v ...interface{}) { // Arguments are handled in the manner of fmt.Printf. func (l *Logger) Printf(format string, v ...interface{}) { if e := l.Debug(); e.Enabled() { - e.skipFrame++ - e.Msg(fmt.Sprintf(format, v...)) + e.CallerSkipFrame(1).Msg(fmt.Sprintf(format, v...)) } }