diff --git a/caller.go b/caller.go index 9179a94..46fad30 100644 --- a/caller.go +++ b/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 diff --git a/entry.go b/entry.go index d648b00..8b768e1 100644 --- a/entry.go +++ b/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...) } diff --git a/logger.go b/logger.go index f33258a..11a6fef 100644 --- a/logger.go +++ b/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" diff --git a/logger_test.go b/logger_test.go index d91be2a..315aea9 100644 --- a/logger_test.go +++ b/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) {