fix: Fix ReportCaller file/line-number (#86)

ReportCaller was reporting the file/line-number that the logger-entry was created on, not the file/line-number that actually logged the message (e.g. the `.Info`-call)

caller.go

@@ -14,6 +14,9 @@ var (
 	// Positions in the call stack when tracing to report the calling method
 	minimumCallerDepth int
 
+	// Used for reporting the line-number inside the go-logger package, used for testing.
+	reportCallerInGoLoggerPackage bool
+
 	// Used for caller information initialisation
 	callerInitOnce sync.Once
 )
@@ -47,13 +50,18 @@ func getCaller() *runtime.Frame {
 	depth := runtime.Callers(minimumCallerDepth, pcs)
 	frames := runtime.CallersFrames(pcs[:depth])
 
+	var prev runtime.Frame
 	for f, again := frames.Next(); again; f, again = frames.Next() {
 		pkg := getPackageName(f.Function)
 
 		// If the caller isn't part of this package, we're done
 		if pkg != goLoggerPackage {
+			if reportCallerInGoLoggerPackage {
+				return &prev
+			}
 			return &f //nolint:scopelint
 		}
+		prev = f
 	}
 
 	// if we got here, we failed to find the caller's context

entry.go

@@ -2,6 +2,7 @@ package logger
 
 import (
 	"context"
+	"fmt"
 
 	"github.com/sirupsen/logrus"
 )
@@ -44,62 +45,80 @@ func (e *Entry) WithContext(ctx context.Context) *Entry {
 	return &Entry{logger: e.logger, fields: e.fields, context: ctx}
 }
 
+func addCallerFields(logrusFields logrus.Fields, reportCaller bool) {
+	if reportCaller {
+		frame := getCaller()
+		logrusFields["file"] = fmt.Sprintf("%s:%v", frame.File, frame.Line)
+		logrusFields["function"] = frame.Function
+	}
+}
+
 // Info forwards a logging call in the (format, args) format
 func (e *Entry) Info(args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Info(args...)
 }
 
 // Infof forwards a logging call in the (format, args) format
 func (e *Entry) Infof(format string, args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Infof(format, args...)
 }
 
 // Error forwards an error logging call
 func (e *Entry) Error(args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Error(args...)
 }
 
 // Errorf forwards an error logging call
 func (e *Entry) Errorf(format string, args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Errorf(format, args...)
 }
 
 // Debug forwards a debugging logging call
 func (e *Entry) Debug(args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Debug(args...)
 }
 
 // Debugf forwards a debugging logging call
 func (e *Entry) Debugf(format string, args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Debugf(format, args...)
 }
 
 // Warn forwards a warning logging call
 func (e *Entry) Warn(args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Warn(args...)
 }
 
 // Warnf forwards a warning logging call
 func (e *Entry) Warnf(format string, args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Warnf(format, args...)
 }
 
 // Fatal forwards a fatal logging call
 func (e *Entry) Fatal(args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Fatal(args...)
 }
 
 // Fatalf forwards a fatal logging call
 func (e *Entry) Fatalf(format string, args ...interface{}) {
 	logrusFields := logrus.Fields(e.fields)
+	addCallerFields(logrusFields, e.logger.reportCaller)
 	e.logger.logrusLogger.WithContext(e.context).WithTime(e.logger.now()).WithFields(logrusFields).Fatalf(format, args...)
 }

logger.go

@@ -2,7 +2,6 @@ package logger
 
 import (
 	"context"
-	"fmt"
 	"io"
 	"os"
 	"time"
@@ -49,14 +48,7 @@ func New(opts ...LoggerOption) *Logger {
 }
 
 func (logger *Logger) entry() *Entry {
-	fields := Fields{}
-	if logger.reportCaller {
-		frame := getCaller()
-		fields["file"] = fmt.Sprintf("%s:%v", frame.File, frame.Line)
-		fields["function"] = frame.Function
-	}
-
-	return &Entry{logger: logger, fields: fields}
+	return &Entry{logger: logger, fields: Fields{}}
 }
 
 const errorKey = "error"

logger_test.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"io"
 	"regexp"
+	"strconv"
 	"strings"
 	"testing"
 )
@@ -38,6 +39,35 @@ func assertLogEntryContains(t *testing.T, logReader io.Reader, key string, expec
 	}
 }
 
+func getLineNumber(t *testing.T, logReader io.Reader) int {
+	const key = "file"
+	t.Helper()
+	log := make(map[string]any)
+	err := json.NewDecoder(logReader).Decode(&log)
+	if err != nil {
+		t.Fatalf("cannot decode log entry: %v", err)
+	}
+	vAny, ok := log[key]
+	if !ok {
+		t.Fatalf("no value found for key %v", key)
+	}
+	v, ok := vAny.(string)
+	if !ok {
+		t.Fatalf("value in key %v was not string: %v", key, vAny)
+	}
+	r := regexp.MustCompile(`.*\.go:(\d+)$`)
+	matches := r.FindStringSubmatch(v)
+	if len(matches) != 2 {
+		// matches will first match the full string, and the second match is the line-number
+		t.Fatalf("log[%v]=%v does not match regexp", key, v)
+	}
+	i, err := strconv.Atoi(matches[1])
+	if err != nil {
+		t.Fatalf("log[%v]=%v failed to parse to int", key, v)
+	}
+	return i
+}
+
 func assertLogEntryHasKey(t *testing.T, logReader io.Reader, key string) {
 	t.Helper()
 	log := make(map[string]interface{})
@@ -289,13 +319,67 @@ func TestBadLevelName(t *testing.T) {
 	}
 }
 
-func TestReporingCaller(t *testing.T) {
-	buf := &bytes.Buffer{}
-	tee := io.TeeReader(buf, buf)
-	logger := New(WithOutput(buf))
+func TestReportingCaller(t *testing.T) {
+	builder := &strings.Builder{}
+	logger := New(WithOutput(builder), WithLevel(LevelInfo))
+	reportCallerInGoLoggerPackage = true
+
+	// Simple log
 	logger.Error("foobar")
-	assertLogEntryContains(t, tee, "file", regexp.MustCompile(`.*\.go:\d+$`))
-	assertLogEntryHasKey(t, tee, "function")
+
+	// 2 logs from same entry
+	entry := logger.WithField("foo", "bar")
+	entry.Info("first")
+	entry.Error("second")
+
+	result := strings.TrimSpace(builder.String()) // Trim trailing newline
+	lines := strings.Split(result, "\n")
+
+	if len(lines) != 3 {
+		t.Fatalf("expected %d lines, got %d", 3, len(lines))
+	}
+
+	lineNumbers := make([]int, 0, 3)
+
+	{
+		line := lines[0]
+		assertLogEntryContains(t, strings.NewReader(line), "file", regexp.MustCompile(`.*\.go:\d+$`))
+		assertLogEntryHasKey(t, strings.NewReader(line), "function")
+		lineNumbers = append(lineNumbers, getLineNumber(t, strings.NewReader(line)))
+	}
+
+	{
+		line := lines[1]
+		assertLogEntryContains(t, strings.NewReader(line), "file", regexp.MustCompile(`.*\.go:\d+$`))
+		assertLogEntryHasKey(t, strings.NewReader(line), "function")
+		lineNumbers = append(lineNumbers, getLineNumber(t, strings.NewReader(line)))
+	}
+	{
+		line := lines[2]
+		assertLogEntryContains(t, strings.NewReader(line), "file", regexp.MustCompile(`.*\.go:\d+$`))
+		assertLogEntryHasKey(t, strings.NewReader(line), "function")
+		lineNumbers = append(lineNumbers, getLineNumber(t, strings.NewReader(line)))
+	}
+
+	uniqueLineNumber := unique(lineNumbers)
+	if len(lineNumbers) != len(uniqueLineNumber) {
+		t.Fatalf("expected %d unique line-numbers, got %d. All line-numbers: %#v", len(lineNumbers), len(uniqueLineNumber), lineNumbers)
+	}
+}
+
+// Get unique items in slice
+func unique[T comparable](slice []T) []T {
+	m := make(map[T]struct{}, len(slice))
+
+	for _, v := range slice {
+		m[v] = struct{}{}
+	}
+
+	u := make([]T, 0, len(m))
+	for k := range m {
+		u = append(u, k)
+	}
+	return u
 }
 
 func TestDisableReportingCaller(t *testing.T) {