Log correct caller information when SpanLogger is used (#547)

* Log correct caller information when `SpanLogger` is used

* Add changelog entry

* Ignore `caller` in `ring` tests

* Address PR feedback

* Add benchmark

CHANGELOG.md

@@ -253,3 +253,4 @@
 * [BUGFIX] httpgrpc: store headers in canonical form when converting from gRPC to HTTP. #518
 * [BUGFIX] Memcached: Don't truncate sub-second TTLs to 0 which results in them being cached forever. #530 
 * [BUGFIX] Cache: initialise the `operation_failures_total{reason="connect-timeout"}` metric to 0 for each cache operation type on startup. #545
+* [BUGFIX] spanlogger: include correct caller information in log messages logged through a `SpanLogger`. #547

ring/replication_set_test.go

@@ -2124,7 +2124,7 @@ func (l *testLogger) Log(keyvals ...interface{}) error {
 		key := keyvals[i]
 		value := keyvals[i+1]
 
-		if key == "user" || key == "method" {
+		if key == "user" || key == "method" || key == "caller" {
 			// These keys are added automatically by spanlogger, but they're not interesting for our tests.
 			continue
 		}

spanlogger/spanlogger.go

@@ -2,6 +2,8 @@ package spanlogger
 
 import (
 	"context"
+	"runtime"
+	"strings"
 
 	"go.uber.org/atomic" // Really just need sync/atomic but there is a lint rule preventing it.
 
@@ -160,6 +162,10 @@ func (s *SpanLogger) getLogger() log.Logger {
 	if ok {
 		logger = log.With(logger, "trace_id", traceID)
 	}
+
+	// Replace the default valuer for the 'caller' attribute with one that gets the caller of the methods in this file.
+	logger = log.With(logger, "caller", spanLoggerAwareCaller())
+
 	// If the value has been set by another goroutine, fetch that other value and discard the one we made.
 	if !s.logger.CompareAndSwap(nil, &logger) {
 		pLogger := s.logger.Load()
@@ -181,3 +187,47 @@ func (s *SpanLogger) SetSpanAndLogTag(key string, value interface{}) {
 	wrappedLogger := log.With(logger, key, value)
 	s.logger.Store(&wrappedLogger)
 }
+
+// spanLoggerAwareCaller is like log.Caller, but ensures that the caller information is
+// that of the caller to SpanLogger, not SpanLogger itself.
+func spanLoggerAwareCaller() log.Valuer {
+	valuer := atomic.NewPointer[log.Valuer](nil)
+
+	return func() interface{} {
+		// If we've already determined the correct stack depth, use it.
+		existingValuer := valuer.Load()
+		if existingValuer != nil {
+			return (*existingValuer)()
+		}
+
+		// We haven't been called before, determine the correct stack depth to
+		// skip the configured logger's internals and the SpanLogger's internals too.
+		//
+		// Note that we can't do this in spanLoggerAwareCaller() directly because we
+		// need to do this when invoked by the configured logger - otherwise we cannot
+		// measure the stack depth of the logger's internals.
+
+		stackDepth := 3 // log.DefaultCaller uses a stack depth of 3, so start searching for the correct stack depth there.
+
+		for {
+			_, file, _, ok := runtime.Caller(stackDepth)
+			if !ok {
+				// We've run out of possible stack frames. Give up.
+				valuer.Store(&unknownCaller)
+				return unknownCaller()
+			}
+
+			if strings.HasSuffix(file, "spanlogger/spanlogger.go") {
+				stackValuer := log.Caller(stackDepth + 2) // Add one to skip the stack frame for the SpanLogger method, and another to skip the stack frame for the valuer which we'll invoke below.
+				valuer.Store(&stackValuer)
+				return stackValuer()
+			}
+
+			stackDepth++
+		}
+	}
+}
+
+var unknownCaller log.Valuer = func() interface{} {
+	return "<unknown>"
+}

spanlogger/spanlogger_test.go

@@ -1,18 +1,26 @@
 package spanlogger
 
 import (
+	"bytes"
 	"context"
+	"fmt"
+	"io"
+	"path/filepath"
+	"runtime"
 	"strings"
 	"testing"
 
+	dskit_log "github.com/grafana/dskit/log"
+	"github.com/grafana/dskit/user"
+
 	"github.com/go-kit/log"
 	"github.com/go-kit/log/level"
 	"github.com/opentracing/opentracing-go"
+	otlog "github.com/opentracing/opentracing-go/log"
 	"github.com/opentracing/opentracing-go/mocktracer"
 	"github.com/pkg/errors"
 	"github.com/stretchr/testify/require"
-
-	"github.com/grafana/dskit/user"
+	"github.com/uber/jaeger-client-go"
 )
 
 func TestSpanLogger_Log(t *testing.T) {
@@ -36,6 +44,10 @@ func TestSpanLogger_CustomLogger(t *testing.T) {
 		return nil
 	}
 	resolver := fakeResolver{}
+
+	_, thisFile, thisLineNumber, ok := runtime.Caller(0)
+	require.True(t, ok)
+
 	span, ctx := New(context.Background(), logger, "test", resolver)
 	_ = span.Log("msg", "original spanlogger")
 
@@ -46,9 +58,9 @@ func TestSpanLogger_CustomLogger(t *testing.T) {
 	_ = span.Log("msg", "fallback spanlogger")
 
 	expect := [][]interface{}{
-		{"method", "test", "msg", "original spanlogger"},
-		{"msg", "restored spanlogger"},
-		{"msg", "fallback spanlogger"},
+		{"method", "test", "caller", toCallerInfo(thisFile, thisLineNumber+4), "msg", "original spanlogger"},
+		{"caller", toCallerInfo(thisFile, thisLineNumber+7), "msg", "restored spanlogger"},
+		{"caller", toCallerInfo(thisFile, thisLineNumber+10), "msg", "fallback spanlogger"},
 	}
 	require.Equal(t, expect, logged)
 }
@@ -76,6 +88,9 @@ func TestSpanLogger_SetSpanAndLogTag(t *testing.T) {
 		return nil
 	}
 
+	_, thisFile, thisLineNumber, ok := runtime.Caller(0)
+	require.True(t, ok)
+
 	spanLogger, _ := New(context.Background(), logger, "the_method", fakeResolver{})
 	require.NoError(t, spanLogger.Log("msg", "this is the first message"))
 
@@ -95,15 +110,18 @@ func TestSpanLogger_SetSpanAndLogTag(t *testing.T) {
 	expectedLogMessages := [][]interface{}{
 		{
 			"method", "the_method",
+			"caller", toCallerInfo(thisFile, thisLineNumber+4),
 			"msg", "this is the first message",
 		},
 		{
 			"method", "the_method",
+			"caller", toCallerInfo(thisFile, thisLineNumber+7),
 			"id", "123",
 			"msg", "this is the second message",
 		},
 		{
 			"method", "the_method",
+			"caller", toCallerInfo(thisFile, thisLineNumber+10),
 			"id", "123",
 			"more context", "abc",
 			"msg", "this is the third message",
@@ -178,8 +196,173 @@ func BenchmarkSpanLogger(b *testing.B) {
 	})
 }
 
+func BenchmarkSpanLoggerWithRealLogger(b *testing.B) {
+	testCases := map[string]bool{
+		"all levels allowed":     true,
+		"info and above allowed": false,
+	}
+
+	for name, debugEnabled := range testCases {
+		b.Run(name, func(b *testing.B) {
+			buf := bytes.NewBuffer(nil)
+			logger := dskit_log.NewGoKitWithWriter("logfmt", buf)
+			logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(5))
+
+			if debugEnabled {
+				logger = level.NewFilter(logger, level.AllowAll())
+			} else {
+				logger = level.NewFilter(logger, level.AllowInfo())
+			}
+
+			logger = loggerWithDebugEnabled{
+				Logger:       logger,
+				debugEnabled: debugEnabled,
+			}
+
+			resolver := fakeResolver{}
+			sl, _ := New(context.Background(), logger, "test", resolver, "bar")
+
+			b.Run("log", func(b *testing.B) {
+				buf.Reset()
+				b.ResetTimer()
+
+				for i := 0; i < b.N; i++ {
+					_ = sl.Log("msg", "foo", "more", "data")
+				}
+			})
+
+			b.Run("level.debug", func(b *testing.B) {
+				buf.Reset()
+				b.ResetTimer()
+
+				for i := 0; i < b.N; i++ {
+					_ = level.Debug(sl).Log("msg", "foo", "more", "data")
+				}
+			})
+
+			b.Run("debuglog", func(b *testing.B) {
+				buf.Reset()
+				b.ResetTimer()
+
+				for i := 0; i < b.N; i++ {
+					sl.DebugLog("msg", "foo", "more", "data")
+				}
+			})
+		})
+	}
+
+}
+
 // Logger which does nothing and implements the DebugEnabled interface used by SpanLogger.
 type noDebugNoopLogger struct{}
 
 func (noDebugNoopLogger) Log(...interface{}) error { return nil }
 func (noDebugNoopLogger) DebugEnabled() bool       { return false }
+
+// Logger which delegates to the inner log.Logger, and implements the DebugEnabled interface used by SpanLogger.
+type loggerWithDebugEnabled struct {
+	log.Logger
+	debugEnabled bool
+}
+
+func (l loggerWithDebugEnabled) DebugEnabled() bool { return l.debugEnabled }
+
+func TestSpanLogger_CallerInfo(t *testing.T) {
+	testCases := map[string]func(w io.Writer) log.Logger{
+		// This is based on Mimir's default logging configuration: https://github.com/grafana/mimir/blob/50d1c27b4ad82b265ff5a865345bec2d726f64ef/pkg/util/log/log.go#L45-L46
+		"default logger": func(w io.Writer) log.Logger {
+			logger := dskit_log.NewGoKitWithWriter("logfmt", w)
+			logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(5))
+			logger = level.NewFilter(logger, level.AllowAll())
+			return logger
+		},
+
+		// This is based on Mimir's logging configuration with rate-limiting enabled: https://github.com/grafana/mimir/blob/50d1c27b4ad82b265ff5a865345bec2d726f64ef/pkg/util/log/log.go#L42-L43
+		"rate-limited logger": func(w io.Writer) log.Logger {
+			logger := dskit_log.NewGoKitWithWriter("logfmt", w)
+			logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(6))
+			logger = dskit_log.NewRateLimitedLogger(logger, 1000, 1000, nil)
+			logger = level.NewFilter(logger, level.AllowAll())
+			return logger
+		},
+	}
+
+	resolver := fakeResolver{}
+
+	setupTest := func(t *testing.T, loggerFactory func(io.Writer) log.Logger) (*bytes.Buffer, *SpanLogger, *jaeger.Span) {
+		reporter := jaeger.NewInMemoryReporter()
+		tracer, closer := jaeger.NewTracer(
+			"test",
+			jaeger.NewConstSampler(true),
+			reporter,
+		)
+		t.Cleanup(func() { _ = closer.Close() })
+
+		span, ctx := opentracing.StartSpanFromContextWithTracer(context.Background(), tracer, "test")
+
+		buf := bytes.NewBuffer(nil)
+		logger := loggerFactory(buf)
+		spanLogger := FromContext(ctx, logger, resolver)
+
+		return buf, spanLogger, span.(*jaeger.Span)
+	}
+
+	requireSpanHasTwoLogLinesWithoutCaller := func(t *testing.T, span *jaeger.Span) {
+		logs := span.Logs()
+		require.Len(t, logs, 2)
+
+		require.Equal(t, []otlog.Field{otlog.String("msg", "this is a test")}, logs[0].Fields)
+		require.Equal(t, []otlog.Field{otlog.String("msg", "this is another test")}, logs[1].Fields)
+	}
+
+	for name, loggerFactory := range testCases {
+		t.Run(name, func(t *testing.T) {
+			t.Run("logging with Log()", func(t *testing.T) {
+				logs, spanLogger, span := setupTest(t, loggerFactory)
+
+				_, thisFile, lineNumberTwoLinesBeforeFirstLogCall, ok := runtime.Caller(0)
+				require.True(t, ok)
+				_ = spanLogger.Log("msg", "this is a test")
+
+				logged := logs.String()
+				require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeFirstLogCall+2))
+
+				logs.Reset()
+				_, _, lineNumberTwoLinesBeforeSecondLogCall, ok := runtime.Caller(0)
+				require.True(t, ok)
+				_ = spanLogger.Log("msg", "this is another test")
+
+				logged = logs.String()
+				require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeSecondLogCall+2))
+
+				requireSpanHasTwoLogLinesWithoutCaller(t, span)
+			})
+
+			t.Run("logging with DebugLog()", func(t *testing.T) {
+				logs, spanLogger, span := setupTest(t, loggerFactory)
+				_, thisFile, lineNumberTwoLinesBeforeLogCall, ok := runtime.Caller(0)
+				require.True(t, ok)
+				spanLogger.DebugLog("msg", "this is a test")
+
+				logged := logs.String()
+				require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeLogCall+2))
+
+				logs.Reset()
+				_, _, lineNumberTwoLinesBeforeSecondLogCall, ok := runtime.Caller(0)
+				require.True(t, ok)
+				spanLogger.DebugLog("msg", "this is another test")
+
+				logged = logs.String()
+				require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeSecondLogCall+2))
+
+				requireSpanHasTwoLogLinesWithoutCaller(t, span)
+			})
+		})
+	}
+}
+
+func toCallerInfo(path string, lineNumber int) string {
+	fileName := filepath.Base(path)
+
+	return fmt.Sprintf("%s:%v", fileName, lineNumber)
+}