From 2a13cd810b9fb10fc69787077b83f0ccdd779d52 Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Tue, 16 Jul 2024 17:19:58 +1000 Subject: [PATCH] Log correct caller information when `SpanLogger` is used --- spanlogger/spanlogger.go | 50 +++++++++++++ spanlogger/spanlogger_test.go | 127 ++++++++++++++++++++++++++++++++-- 2 files changed, 172 insertions(+), 5 deletions(-) diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go index 70c86d16d..fe3640a96 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 this method, and another to skip the stack frame for the SpanLogger method. + 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..641c583b6 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -1,18 +1,25 @@ package spanlogger import ( + "bytes" "context" + "fmt" + "io" + "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 +43,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 +57,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 +87,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 +109,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", @@ -183,3 +200,103 @@ type noDebugNoopLogger struct{} func (noDebugNoopLogger) Log(...interface{}) error { return nil } func (noDebugNoopLogger) DebugEnabled() bool { return false } + +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 := path[strings.LastIndex(path, "/")+1:] + + return fmt.Sprintf("%s:%v", fileName, lineNumber) +}