From 5eca05b1e4cf63df5d007ec6b13ce7394a0fffe3 Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Mon, 29 Jul 2024 10:27:04 +1000 Subject: [PATCH] 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 | 1 + ring/replication_set_test.go | 2 +- spanlogger/spanlogger.go | 50 +++++++++ spanlogger/spanlogger_test.go | 193 +++++++++++++++++++++++++++++++++- 4 files changed, 240 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f21aaf6fa..d9a590418 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/ring/replication_set_test.go b/ring/replication_set_test.go index 4868e752f..4b8ac021d 100644 --- a/ring/replication_set_test.go +++ b/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 } diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go index 70c86d16d..8daad995c 100644 --- a/spanlogger/spanlogger.go +++ b/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 "" +} diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index fd45a282d..0e9f7e1d1 100644 --- a/spanlogger/spanlogger_test.go +++ b/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) +}