Use runtime.Frame for caller info

README.md

@@ -39,11 +39,19 @@ type Entry struct {
 	Message   string        // message as send to log call
 	Error     error         // error if .Error() was called
 	Fields    []interface{} // alternating key-value pairs
+
+	// Caller information
+	Caller      runtime.Frame // only available after .WithCaller(true)
+	CallerDepth int           // caller depth from callback
 }
 ```
 
 Use `e.FieldsMap()` to retrieve the Fields as a map.
 
+To enable caller information, use `genericr.New(...).WithCaller(true)`.
+
+To filter messages above a certain verbosity level, use `genericr.New(...).WithVerbosity(1)`.
+
 ### Usage in tests
 
 This shows how you can redirect logs to the testing.T logger and keep a reference

caller_test.go

@@ -0,0 +1,8 @@
+package genericr_test
+
+import "github.com/go-logr/logr"
+
+// This is indirectly tested by calling this function
+func logSomethingFromOtherFile(log logr.Logger) {
+	log.Info("test caller")
+}

genericr.go

@@ -23,7 +23,9 @@ import (
 	"bytes"
 	"encoding/json"
 	"fmt"
+	"path/filepath"
 	"regexp"
+	"runtime"
 	"sort"
 	"strconv"
 
@@ -38,7 +40,10 @@ type Entry struct {
 	Message   string        // message as send to log call
 	Error     error         // error if .Error() was called
 	Fields    []interface{} // alternating key-value pairs
-	// TODO: CallerDepth int
+
+	// Caller information
+	Caller      runtime.Frame // only available after .WithCaller(true)
+	CallerDepth int           // caller depth from callback
 }
 
 // String converts the entry to a string.
@@ -51,6 +56,10 @@ func (e Entry) String() string {
 	buf.WriteString(strconv.Itoa(e.Level))
 	buf.WriteByte(']')
 	buf.WriteByte(' ')
+	if e.Caller.File != "" || e.Caller.Line != 0 {
+		buf.WriteString(e.CallerShort())
+		buf.WriteByte(' ')
+	}
 	buf.WriteString(e.Name)
 	buf.WriteByte(' ')
 	buf.WriteString(pretty(e.Message))
@@ -71,6 +80,15 @@ func (e Entry) FieldsMap() map[string]interface{} {
 	return fieldsMap(e.Fields)
 }
 
+// CallerShort returns a short caller location string ("somefile.go:123")
+func (e Entry) CallerShort() string {
+	if e.Caller.File == "" && e.Caller.Line == 0 {
+		return ""
+	}
+	_, fname := filepath.Split(e.Caller.File)
+	return fmt.Sprintf("%s:%d", fname, e.Caller.Line)
+}
+
 // LogFunc is your custom log backend
 type LogFunc func(e Entry)
 
@@ -92,15 +110,36 @@ type Logger struct {
 	nameParts []string      // list of names
 	name      string        // nameParts joined by '.' for performance
 	values    []interface{} // key-value pairs
-	depth     int           // call stack depth to figure out caller info
+	caller    bool          // try to retrieve the caller from the stack
+	depth     int           // call stack depth offset to figure out caller info
 }
 
-// WithVerbosity returns a new instance with given max verbosity level
+// WithVerbosity returns a new instance with given max verbosity level.
+// This is not part of the logr interface, so you can only use this on the root object.
 func (l Logger) WithVerbosity(level int) Logger {
 	l.verbosity = level
 	return l
 }
 
+// WithCaller enables or disables caller lookup for Entry.Caller.
+// It is disabled by default.
+// Local benchmarks show close to 1µs and 2 allocs extra overhead from enabling this,
+// without actually using this extra information.
+// This is not part of the logr interface, so you can only use this on the root object.
+func (l Logger) WithCaller(enabled bool) Logger {
+	l.caller = enabled
+	return l
+}
+
+// WithCallerDepth adjusts the caller depth. This is useful is the caller uses
+// a custom wrapper to log messages with extra info.
+// To actually do caller lookups, those have to be enabled with .WithCaller(true).
+// This is not part of the logr interface, so you can only use this on the root object.
+func (l Logger) WithCallerDepth(depth int) Logger {
+	l.depth += depth
+	return l
+}
+
 func (l Logger) Info(msg string, kvList ...interface{}) {
 	l.logMessage(nil, msg, kvList)
 }
@@ -150,6 +189,7 @@ func (l Logger) WithValues(kvList ...interface{}) logr.Logger {
 	return l
 }
 
+// logMessage implements the actual logging for .Info() and .Error()
 func (l Logger) logMessage(err error, msg string, kvList []interface{}) {
 	if !l.Enabled() {
 		return
@@ -164,14 +204,25 @@ func (l Logger) logMessage(err error, msg string, kvList []interface{}) {
 		copy(out, l.values)
 		copy(out[len(l.values):], kvList)
 	}
+
+	calldepth := 2 + l.depth
+	var caller runtime.Frame
+	if l.caller {
+		pc := make([]uintptr, 1)
+		if n := runtime.Callers(calldepth+1, pc[:]); n >= 1 {
+			caller, _ = runtime.CallersFrames(pc).Next()
+		}
+	}
+
 	l.f(Entry{
-		Level:     l.level,
-		Name:      l.name,
-		NameParts: l.nameParts,
-		Message:   msg,
-		Error:     err,
-		Fields:    out,
-		//CallerDepth: l.depth,
+		Level:       l.level,
+		Name:        l.name,
+		NameParts:   l.nameParts,
+		Message:     msg,
+		Error:       err,
+		Fields:      out,
+		Caller:      caller,
+		CallerDepth: calldepth + 1, // +1 for callback
 	})
 }
 

genericr_test.go

@@ -3,6 +3,8 @@ package genericr_test
 import (
 	"errors"
 	"fmt"
+	"path/filepath"
+	"runtime"
 	"testing"
 
 	"github.com/wojas/genericr"
@@ -146,6 +148,26 @@ func TestLogger_Table(t *testing.T) {
 	}
 }
 
+func TestLogger_Caller(t *testing.T) {
+	var last genericr.Entry
+	var lf genericr.LogFunc = func(e genericr.Entry) {
+		last = e
+		t.Log(e.String())
+		t.Log(runtime.Caller(e.CallerDepth)) // should log caller_test
+	}
+	log := genericr.New(lf).WithCaller(true)
+	logSomethingFromOtherFile(log)
+
+	_, fname := filepath.Split(last.Caller.File)
+	if fname != "caller_test.go" {
+		t.Errorf("Caller: expected 'caller_test.go', got %q (full: %s:%d)",
+			fname, last.Caller.File, last.Caller.Line)
+	}
+	if last.CallerDepth != 3 {
+		t.Errorf("Caller depth: expected 3, got %d", last.CallerDepth)
+	}
+}
+
 func BenchmarkLogger_basic(b *testing.B) {
 	foo := 0
 	var lf genericr.LogFunc = func(e genericr.Entry) {
@@ -160,6 +182,20 @@ func BenchmarkLogger_basic(b *testing.B) {
 	}
 }
 
+func BenchmarkLogger_basic_with_caller(b *testing.B) {
+	foo := 0
+	var lf genericr.LogFunc = func(e genericr.Entry) {
+		foo += e.Level // just to prevent it from being optimized away
+	}
+	log := genericr.New(lf).WithCaller(true)
+
+	b.ReportAllocs()
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		log.Info("hello")
+	}
+}
+
 func BenchmarkLogger_2vars(b *testing.B) {
 	foo := 0
 	var lf genericr.LogFunc = func(e genericr.Entry) {