From 2d8e06867ce275790c5457aca4734b2f9fd08333 Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Wed, 9 Oct 2024 15:08:14 +1100 Subject: [PATCH 1/9] Extend existing tests to catch issue --- spanlogger/spanlogger_test.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index 0e9f7e1d1..7aef01c45 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -326,6 +326,7 @@ func TestSpanLogger_CallerInfo(t *testing.T) { logged := logs.String() require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeFirstLogCall+2)) + require.Equalf(t, 1, strings.Count(logged, "caller="), "expected to only have one caller field, but got: %v", logged) logs.Reset() _, _, lineNumberTwoLinesBeforeSecondLogCall, ok := runtime.Caller(0) @@ -334,6 +335,7 @@ func TestSpanLogger_CallerInfo(t *testing.T) { logged = logs.String() require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeSecondLogCall+2)) + require.Equalf(t, 1, strings.Count(logged, "caller="), "expected to only have one caller field, but got: %v", logged) requireSpanHasTwoLogLinesWithoutCaller(t, span) }) @@ -346,6 +348,7 @@ func TestSpanLogger_CallerInfo(t *testing.T) { logged := logs.String() require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeLogCall+2)) + require.Equalf(t, 1, strings.Count(logged, "caller="), "expected to only have one caller field, but got: %v", logged) logs.Reset() _, _, lineNumberTwoLinesBeforeSecondLogCall, ok := runtime.Caller(0) @@ -354,6 +357,7 @@ func TestSpanLogger_CallerInfo(t *testing.T) { logged = logs.String() require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeSecondLogCall+2)) + require.Equalf(t, 1, strings.Count(logged, "caller="), "expected to only have one caller field, but got: %v", logged) requireSpanHasTwoLogLinesWithoutCaller(t, span) }) From d8ed57a2cff90c572e3b8dbed9e1a85941799e5d Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Wed, 9 Oct 2024 15:21:47 +1100 Subject: [PATCH 2/9] Add further test cases --- spanlogger/spanlogger_test.go | 40 ++++++++++++++++++++++++++++++++--- 1 file changed, 37 insertions(+), 3 deletions(-) diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index 7aef01c45..8463e5db1 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -285,6 +285,14 @@ func TestSpanLogger_CallerInfo(t *testing.T) { logger = level.NewFilter(logger, level.AllowAll()) return logger }, + + "default logger that has been wrapped with further information": 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()) + logger = log.With(logger, "user", "user-1") + return logger + }, } resolver := fakeResolver{} @@ -307,12 +315,15 @@ func TestSpanLogger_CallerInfo(t *testing.T) { return buf, spanLogger, span.(*jaeger.Span) } - requireSpanHasTwoLogLinesWithoutCaller := func(t *testing.T, span *jaeger.Span) { + requireSpanHasTwoLogLinesWithoutCaller := func(t *testing.T, span *jaeger.Span, extraFields ...otlog.Field) { 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) + expectedFields := append(slices.Clone(extraFields), otlog.String("msg", "this is a test")) + require.Equal(t, expectedFields, logs[0].Fields) + + expectedFields = append(slices.Clone(extraFields), otlog.String("msg", "this is another test")) + require.Equal(t, expectedFields, logs[1].Fields) } for name, loggerFactory := range testCases { @@ -361,6 +372,29 @@ func TestSpanLogger_CallerInfo(t *testing.T) { requireSpanHasTwoLogLinesWithoutCaller(t, span) }) + + t.Run("logging with SpanLogger wrapped in a level", func(t *testing.T) { + logs, spanLogger, span := setupTest(t, loggerFactory) + + _, thisFile, lineNumberTwoLinesBeforeFirstLogCall, ok := runtime.Caller(0) + require.True(t, ok) + _ = level.Info(spanLogger).Log("msg", "this is a test") + + logged := logs.String() + require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeFirstLogCall+2)) + require.Equalf(t, 1, strings.Count(logged, "caller="), "expected to only have one caller field, but got: %v", logged) + + logs.Reset() + _, _, lineNumberTwoLinesBeforeSecondLogCall, ok := runtime.Caller(0) + require.True(t, ok) + _ = level.Info(spanLogger).Log("msg", "this is another test") + + logged = logs.String() + require.Contains(t, logged, "caller="+toCallerInfo(thisFile, lineNumberTwoLinesBeforeSecondLogCall+2)) + require.Equalf(t, 1, strings.Count(logged, "caller="), "expected to only have one caller field, but got: %v", logged) + + requireSpanHasTwoLogLinesWithoutCaller(t, span, otlog.String("level", "info")) + }) }) } } From e6d31113d6618d90e107afa2b89148039906ea7a Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Wed, 9 Oct 2024 16:14:25 +1100 Subject: [PATCH 3/9] Fix issue where caller information is logged twice --- spanlogger/spanlogger.go | 59 ++++++++++++++++------------------- spanlogger/spanlogger_test.go | 11 ++++--- 2 files changed, 33 insertions(+), 37 deletions(-) diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go index 8daad995c..bc6d44aba 100644 --- a/spanlogger/spanlogger.go +++ b/spanlogger/spanlogger.go @@ -1,8 +1,13 @@ +// Provenance-includes-location: https://github.com/go-kit/log/blob/main/value.go +// Provenance-includes-license: MIT +// Provenance-includes-copyright: Go kit + package spanlogger import ( "context" "runtime" + "strconv" "strings" "go.uber.org/atomic" // Really just need sync/atomic but there is a lint rule preventing it. @@ -163,9 +168,6 @@ func (s *SpanLogger) getLogger() log.Logger { 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() @@ -188,46 +190,39 @@ func (s *SpanLogger) SetSpanAndLogTag(key string, value interface{}) { 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) - +// SpanLoggerAwareCaller is like log.Caller, but ensures that the caller information is +// that of the caller to SpanLogger (if SpanLogger is being used), not SpanLogger itself. +// +// defaultStackDepth should be the number of stack frames to skip by default, as would be +// passed to github.com/go-kit/log's Caller method. +func SpanLoggerAwareCaller(defaultStackDepth int) log.Valuer { 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. + stackDepth := defaultStackDepth for { - _, file, _, ok := runtime.Caller(stackDepth) + _, file, line, ok := runtime.Caller(stackDepth) if !ok { // We've run out of possible stack frames. Give up. - valuer.Store(&unknownCaller) - return unknownCaller() + return "" } - 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() + // If we're in this file, or log.go in the go-kit/log package, we need to continue searching in the stack. + // + // The path to log.go varies depending on how the package is imported: + // - if go-kit/log is vendored, the path is something like /vendor/github.com/go-kit/log/log.go + // - if it is not vendored, the path is something like /home/user/go/pkg/mod/github.com/go-kit/log@v0.2.1/log.go and varies based on the version imported + if strings.HasSuffix(file, "dskit/spanlogger/spanlogger.go") || (strings.HasSuffix(file, "/log.go") && strings.Contains(file, "github.com/go-kit/log")) { + stackDepth++ + continue } - stackDepth++ + return formatCallerInfoForLog(file, line) } } } -var unknownCaller log.Valuer = func() interface{} { - return "" +// This is based on github.com/go-kit/log's Caller, but modified for use by SpanLoggerAwareCaller above. +func formatCallerInfoForLog(file string, line int) string { + idx := strings.LastIndexByte(file, '/') + return file[idx+1:] + ":" + strconv.Itoa(line) } diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index 8463e5db1..e62125947 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -7,6 +7,7 @@ import ( "io" "path/filepath" "runtime" + "slices" "strings" "testing" @@ -206,7 +207,7 @@ func BenchmarkSpanLoggerWithRealLogger(b *testing.B) { 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)) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", SpanLoggerAwareCaller(5)) if debugEnabled { logger = level.NewFilter(logger, level.AllowAll()) @@ -267,12 +268,12 @@ type loggerWithDebugEnabled struct { func (l loggerWithDebugEnabled) DebugEnabled() bool { return l.debugEnabled } -func TestSpanLogger_CallerInfo(t *testing.T) { +func TestSpanLoggerAwareCaller(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 = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", SpanLoggerAwareCaller(5)) logger = level.NewFilter(logger, level.AllowAll()) return logger }, @@ -280,7 +281,7 @@ func TestSpanLogger_CallerInfo(t *testing.T) { // 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 = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", SpanLoggerAwareCaller(6)) logger = dskit_log.NewRateLimitedLogger(logger, 1000, 1000, nil) logger = level.NewFilter(logger, level.AllowAll()) return logger @@ -288,7 +289,7 @@ func TestSpanLogger_CallerInfo(t *testing.T) { "default logger that has been wrapped with further information": func(w io.Writer) log.Logger { logger := dskit_log.NewGoKitWithWriter("logfmt", w) - logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.Caller(5)) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", SpanLoggerAwareCaller(5)) logger = level.NewFilter(logger, level.AllowAll()) logger = log.With(logger, "user", "user-1") return logger From e93c3a0413b1a3ee22915a324d93caa10cbc6dec Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Wed, 9 Oct 2024 16:25:00 +1100 Subject: [PATCH 4/9] Add benchmark comparing the performance of `Caller` and `SpanLoggerAwareCaller` --- spanlogger/spanlogger_test.go | 30 +++++++++++++++++++++++++++--- 1 file changed, 27 insertions(+), 3 deletions(-) diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index e62125947..8338d0e74 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -223,7 +223,7 @@ func BenchmarkSpanLoggerWithRealLogger(b *testing.B) { resolver := fakeResolver{} sl, _ := New(context.Background(), logger, "test", resolver, "bar") - b.Run("log", func(b *testing.B) { + b.Run("Log", func(b *testing.B) { buf.Reset() b.ResetTimer() @@ -232,7 +232,7 @@ func BenchmarkSpanLoggerWithRealLogger(b *testing.B) { } }) - b.Run("level.debug", func(b *testing.B) { + b.Run("level.Debug", func(b *testing.B) { buf.Reset() b.ResetTimer() @@ -241,7 +241,7 @@ func BenchmarkSpanLoggerWithRealLogger(b *testing.B) { } }) - b.Run("debuglog", func(b *testing.B) { + b.Run("DebugLog", func(b *testing.B) { buf.Reset() b.ResetTimer() @@ -251,7 +251,31 @@ func BenchmarkSpanLoggerWithRealLogger(b *testing.B) { }) }) } +} + +func BenchmarkSpanLoggerAwareCaller(b *testing.B) { + runBenchmark := func(b *testing.B, caller log.Valuer) { + buf := bytes.NewBuffer(nil) + logger := dskit_log.NewGoKitWithWriter("logfmt", buf) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", caller) + + b.ResetTimer() + + for i := 0; i < b.N; i++ { + _ = logger.Log("msg", "foo", "more", "data") + } + } + + defaultStackDepth := 5 + + b.Run("with go-kit's Caller", func(b *testing.B) { + runBenchmark(b, log.Caller(defaultStackDepth)) + }) + + b.Run("with dskit's SpanLoggerAwareCaller", func(b *testing.B) { + runBenchmark(b, SpanLoggerAwareCaller(defaultStackDepth)) + }) } // Logger which does nothing and implements the DebugEnabled interface used by SpanLogger. From 2c3d91163d0a4931f727358b92f7fcc43dec4fd3 Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Wed, 9 Oct 2024 16:47:12 +1100 Subject: [PATCH 5/9] Change name to satisfy linter --- spanlogger/spanlogger.go | 6 +++--- spanlogger/spanlogger_test.go | 12 ++++++------ 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go index bc6d44aba..a87fff2d5 100644 --- a/spanlogger/spanlogger.go +++ b/spanlogger/spanlogger.go @@ -190,12 +190,12 @@ func (s *SpanLogger) SetSpanAndLogTag(key string, value interface{}) { s.logger.Store(&wrappedLogger) } -// SpanLoggerAwareCaller is like log.Caller, but ensures that the caller information is +// Caller is like github.com/go-kit/log's Caller, but ensures that the caller information is // that of the caller to SpanLogger (if SpanLogger is being used), not SpanLogger itself. // // defaultStackDepth should be the number of stack frames to skip by default, as would be // passed to github.com/go-kit/log's Caller method. -func SpanLoggerAwareCaller(defaultStackDepth int) log.Valuer { +func Caller(defaultStackDepth int) log.Valuer { return func() interface{} { stackDepth := defaultStackDepth @@ -221,7 +221,7 @@ func SpanLoggerAwareCaller(defaultStackDepth int) log.Valuer { } } -// This is based on github.com/go-kit/log's Caller, but modified for use by SpanLoggerAwareCaller above. +// This is based on github.com/go-kit/log's Caller, but modified for use by Caller above. func formatCallerInfoForLog(file string, line int) string { idx := strings.LastIndexByte(file, '/') return file[idx+1:] + ":" + strconv.Itoa(line) diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index 8338d0e74..c3ceccbd2 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -207,7 +207,7 @@ func BenchmarkSpanLoggerWithRealLogger(b *testing.B) { 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", SpanLoggerAwareCaller(5)) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", Caller(5)) if debugEnabled { logger = level.NewFilter(logger, level.AllowAll()) @@ -273,8 +273,8 @@ func BenchmarkSpanLoggerAwareCaller(b *testing.B) { runBenchmark(b, log.Caller(defaultStackDepth)) }) - b.Run("with dskit's SpanLoggerAwareCaller", func(b *testing.B) { - runBenchmark(b, SpanLoggerAwareCaller(defaultStackDepth)) + b.Run("with dskit's spanlogger.Caller", func(b *testing.B) { + runBenchmark(b, Caller(defaultStackDepth)) }) } @@ -297,7 +297,7 @@ func TestSpanLoggerAwareCaller(t *testing.T) { // 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", SpanLoggerAwareCaller(5)) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", Caller(5)) logger = level.NewFilter(logger, level.AllowAll()) return logger }, @@ -305,7 +305,7 @@ func TestSpanLoggerAwareCaller(t *testing.T) { // 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", SpanLoggerAwareCaller(6)) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", Caller(6)) logger = dskit_log.NewRateLimitedLogger(logger, 1000, 1000, nil) logger = level.NewFilter(logger, level.AllowAll()) return logger @@ -313,7 +313,7 @@ func TestSpanLoggerAwareCaller(t *testing.T) { "default logger that has been wrapped with further information": func(w io.Writer) log.Logger { logger := dskit_log.NewGoKitWithWriter("logfmt", w) - logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", SpanLoggerAwareCaller(5)) + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", Caller(5)) logger = level.NewFilter(logger, level.AllowAll()) logger = log.With(logger, "user", "user-1") return logger From 647f153a049e53e87469927e6e0ecd0a82764e4c Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Wed, 9 Oct 2024 17:15:29 +1100 Subject: [PATCH 6/9] Fix tests broken by removal of `caller` key/value pair from `SpanLogger` --- spanlogger/spanlogger_test.go | 15 +++------------ 1 file changed, 3 insertions(+), 12 deletions(-) diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index c3ceccbd2..5e281b3a9 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -46,9 +46,6 @@ func TestSpanLogger_CustomLogger(t *testing.T) { } 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") @@ -59,9 +56,9 @@ func TestSpanLogger_CustomLogger(t *testing.T) { _ = span.Log("msg", "fallback spanlogger") expect := [][]interface{}{ - {"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"}, + {"method", "test", "msg", "original spanlogger"}, + {"msg", "restored spanlogger"}, + {"msg", "fallback spanlogger"}, } require.Equal(t, expect, logged) } @@ -89,9 +86,6 @@ 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")) @@ -111,18 +105,15 @@ 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", From 9e662ca825b8e1ba86a947bb8fdf16176afcffc3 Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Thu, 10 Oct 2024 15:56:29 +1100 Subject: [PATCH 7/9] Don't bother with checking for go-kit/log stack frames until we've seen SpanLogger MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This makes the cost of spanlogger.Caller negligible for use outside of SpanLogger: │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │ │ sec/op │ sec/op vs base │ comparison-after-step-2.txt 927.5n ± 5% 932.1n ± 2% ~ (p=0.093 n=6) │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │ │ B/op │ B/op vs base │ comparison-after-step-2.txt 732.5 ± 0% 733.0 ± 0% ~ (p=0.636 n=6) │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │ │ allocs/op │ allocs/op vs base │ comparison-after-step-2.txt 9.000 ± 0% 9.000 ± 0% ~ (p=1.000 n=6) ¹ ¹ all samples are equal --- spanlogger/spanlogger.go | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-) diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go index a87fff2d5..358542f8b 100644 --- a/spanlogger/spanlogger.go +++ b/spanlogger/spanlogger.go @@ -198,6 +198,7 @@ func (s *SpanLogger) SetSpanAndLogTag(key string, value interface{}) { func Caller(defaultStackDepth int) log.Valuer { return func() interface{} { stackDepth := defaultStackDepth + seenSpanLogger := false for { _, file, line, ok := runtime.Caller(stackDepth) @@ -206,12 +207,22 @@ func Caller(defaultStackDepth int) log.Valuer { return "" } - // If we're in this file, or log.go in the go-kit/log package, we need to continue searching in the stack. - // + // If we're in this file, or log.go in the go-kit/log package after having seen this file, we need to continue searching in the stack. + if strings.HasSuffix(file, "dskit/spanlogger/spanlogger.go") { + seenSpanLogger = true + stackDepth++ + continue + } + // The path to log.go varies depending on how the package is imported: // - if go-kit/log is vendored, the path is something like /vendor/github.com/go-kit/log/log.go // - if it is not vendored, the path is something like /home/user/go/pkg/mod/github.com/go-kit/log@v0.2.1/log.go and varies based on the version imported - if strings.HasSuffix(file, "dskit/spanlogger/spanlogger.go") || (strings.HasSuffix(file, "/log.go") && strings.Contains(file, "github.com/go-kit/log")) { + // + // We need to check for go-kit/log stack frames because log.With, log.WithPrefix or log.WithSuffix (including the various level methods like level.Debug, + // level.Info etc.) to wrap a SpanLogger introduces an additional context.Log stack frame that calls into the SpanLogger. This is because the use of SpanLogger + // as the logger means the optimisation to avoid creating a new logger in https://github.com/go-kit/log/blob/c7bf81493e581feca11e11a7672b14be3591ca43/log.go#L141-L146 + // used by those methods can't be used, and so the SpanLogger is wrapped in a new logger. + if seenSpanLogger && (strings.HasSuffix(file, "/log.go") && strings.Contains(file, "github.com/go-kit/log")) { stackDepth++ continue } From 57c681b36739a8a0f7cf2af59e68023025c24af8 Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Thu, 10 Oct 2024 16:37:27 +1100 Subject: [PATCH 8/9] Reuse slice and use string equality check --- spanlogger/spanlogger.go | 40 +++++++++++++++++++++++++++------------- 1 file changed, 27 insertions(+), 13 deletions(-) diff --git a/spanlogger/spanlogger.go b/spanlogger/spanlogger.go index 358542f8b..f32bce6f6 100644 --- a/spanlogger/spanlogger.go +++ b/spanlogger/spanlogger.go @@ -197,32 +197,35 @@ func (s *SpanLogger) SetSpanAndLogTag(key string, value interface{}) { // passed to github.com/go-kit/log's Caller method. func Caller(defaultStackDepth int) log.Valuer { return func() interface{} { - stackDepth := defaultStackDepth + stackDepth := defaultStackDepth + 1 // +1 to account for this method. seenSpanLogger := false + pc := make([]uintptr, 1) for { - _, file, line, ok := runtime.Caller(stackDepth) + function, file, line, ok := caller(stackDepth, pc) if !ok { // We've run out of possible stack frames. Give up. return "" } - // If we're in this file, or log.go in the go-kit/log package after having seen this file, we need to continue searching in the stack. - if strings.HasSuffix(file, "dskit/spanlogger/spanlogger.go") { + // If we're in a SpanLogger method, we need to continue searching. + // + // Matching on the exact function name like this does mean this will break if we rename or refactor SpanLogger, but + // the tests should catch this. In the worst case scenario, we'll log incorrect caller information, which isn't the + // end of the world. + if function == "github.com/grafana/dskit/spanlogger.(*SpanLogger).Log" || function == "github.com/grafana/dskit/spanlogger.(*SpanLogger).DebugLog" { seenSpanLogger = true stackDepth++ continue } - // The path to log.go varies depending on how the package is imported: - // - if go-kit/log is vendored, the path is something like /vendor/github.com/go-kit/log/log.go - // - if it is not vendored, the path is something like /home/user/go/pkg/mod/github.com/go-kit/log@v0.2.1/log.go and varies based on the version imported - // - // We need to check for go-kit/log stack frames because log.With, log.WithPrefix or log.WithSuffix (including the various level methods like level.Debug, - // level.Info etc.) to wrap a SpanLogger introduces an additional context.Log stack frame that calls into the SpanLogger. This is because the use of SpanLogger - // as the logger means the optimisation to avoid creating a new logger in https://github.com/go-kit/log/blob/c7bf81493e581feca11e11a7672b14be3591ca43/log.go#L141-L146 - // used by those methods can't be used, and so the SpanLogger is wrapped in a new logger. - if seenSpanLogger && (strings.HasSuffix(file, "/log.go") && strings.Contains(file, "github.com/go-kit/log")) { + // We need to check for go-kit/log stack frames like this because using log.With, log.WithPrefix or log.WithSuffix + // (including the various level methods like level.Debug, level.Info etc.) to wrap a SpanLogger introduce an + // additional context.Log stack frame that calls into the SpanLogger. This is because the use of SpanLogger + // as the logger means the optimisation to avoid creating a new logger in + // https://github.com/go-kit/log/blob/c7bf81493e581feca11e11a7672b14be3591ca43/log.go#L141-L146 used by those methods + // can't be used, and so the SpanLogger is wrapped in a new logger. + if seenSpanLogger && function == "github.com/go-kit/log.(*context).Log" { stackDepth++ continue } @@ -232,6 +235,17 @@ func Caller(defaultStackDepth int) log.Valuer { } } +// caller is like runtime.Caller, but modified to allow reuse of the uintptr slice and return the function name. +func caller(stackDepth int, pc []uintptr) (function string, file string, line int, ok bool) { + n := runtime.Callers(stackDepth+1, pc) + if n < 1 { + return "", "", 0, false + } + + frame, _ := runtime.CallersFrames(pc).Next() + return frame.Function, frame.File, frame.Line, frame.PC != 0 +} + // This is based on github.com/go-kit/log's Caller, but modified for use by Caller above. func formatCallerInfoForLog(file string, line int) string { idx := strings.LastIndexByte(file, '/') From d2b63722af038e46f7f6d86b39264a6512016bac Mon Sep 17 00:00:00 2001 From: Charles Korn Date: Fri, 11 Oct 2024 09:54:34 +1100 Subject: [PATCH 9/9] Address PR feedback: use const in test Co-authored-by: Arve Knudsen --- spanlogger/spanlogger_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spanlogger/spanlogger_test.go b/spanlogger/spanlogger_test.go index 5e281b3a9..fa22a15c8 100644 --- a/spanlogger/spanlogger_test.go +++ b/spanlogger/spanlogger_test.go @@ -258,7 +258,7 @@ func BenchmarkSpanLoggerAwareCaller(b *testing.B) { } - defaultStackDepth := 5 + const defaultStackDepth = 5 b.Run("with go-kit's Caller", func(b *testing.B) { runBenchmark(b, log.Caller(defaultStackDepth))