Fix handling of printing caller with Write, Print, and Printf. (#315)

* 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.

* Use CallerSkipFrame for Print, Printf, and Write.

This allows us to use the correct caller when using these 3 functions.

Co-authored-by: Zephaniah E. Loss-Cutler-Hull <[email protected]>

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
+	skipFrame 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.skipFrame = 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.skipFrame += skip
+	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.skipFrame)
 	if !ok {
 		return e
 	}

log.go

@@ -392,15 +392,15 @@ 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.Msg(fmt.Sprint(v...))
+		e.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 (l *Logger) Printf(format string, v ...interface{}) {
 	if e := l.Debug(); e.Enabled() {
-		e.Msg(fmt.Sprintf(format, v...))
+		e.CallerSkipFrame(1).Msg(fmt.Sprintf(format, v...))
 	}
 }
 
@@ -412,7 +412,7 @@ func (l Logger) Write(p []byte) (n int, err error) {
 		// Trim CR added by stdlog.
 		p = p[0 : n-1]
 	}
-	l.Log().Msg(string(p))
+	l.Log().CallerSkipFrame(1).Msg(string(p))
 	return
 }
 

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