From 017057e49c8eb714095c940f3465bef7b06fb663 Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Tue, 23 Jun 2020 22:44:42 +0300 Subject: [PATCH 1/8] Introduce UseCallerSkipForStacktrace & StackSkip * UseCallerSkipForStacktrace configures the Logger to honor CallerSkip when taking stacktraces. * StackSkip is similar to Stack but allows skipping frames from the top of the stack Fixes #512, fixes #727 --- field.go | 15 ++++++++++++++- field_test.go | 2 +- logger.go | 9 +++++++-- options.go | 8 ++++++++ stacktrace.go | 11 ++++++++++- stacktrace_test.go | 4 ++-- 6 files changed, 42 insertions(+), 7 deletions(-) diff --git a/field.go b/field.go index dd558fc23..be04f66c0 100644 --- a/field.go +++ b/field.go @@ -368,7 +368,20 @@ func Stack(key string) Field { // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation // is okay. - return String(key, takeStacktrace()) + return String(key, takeStacktrace(nil)) +} + +// StackSkip constructs a field that stores a stacktrace of the current +// goroutine under provided key, skipping the given number of frames from the +// top of the stacktrace. Keep in mind that taking a stacktrace is eager and +// expensive (relatively speaking); this function both makes an allocation and +// takes about two microseconds. +func StackSkip(key string, skip int) Field { + // Returning the stacktrace as a string costs an allocation, but saves us + // from expanding the zapcore.Field union struct to include a byte slice. Since + // taking a stacktrace is already so expensive (~10us), the extra allocation + // is okay. + return String(key, takeStacktrace(&skip)) } // Duration constructs a field with the given key and value. The encoder diff --git a/field_test.go b/field_test.go index cc7f2e564..e45a1a95d 100644 --- a/field_test.go +++ b/field_test.go @@ -259,6 +259,6 @@ func TestStackField(t *testing.T) { f := Stack("stacktrace") assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") - assert.Equal(t, takeStacktrace(), f.String, "Unexpected stack trace") + assert.Equal(t, takeStacktrace(nil), f.String, "Unexpected stack trace") assertCanBeReused(t, f) } diff --git a/logger.go b/logger.go index cd6e19551..afb057ad9 100644 --- a/logger.go +++ b/logger.go @@ -48,7 +48,8 @@ type Logger struct { addCaller bool addStack zapcore.LevelEnabler - callerSkip int + callerSkip int + useCallerSkipForStack bool } // New constructs a new Logger from the provided zapcore.Core and Options. If @@ -304,7 +305,11 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry { } } if log.addStack.Enabled(ce.Entry.Level) { - ce.Entry.Stack = Stack("").String + if log.useCallerSkipForStack { + ce.Entry.Stack = StackSkip("", log.callerSkip).String + } else { + ce.Entry.Stack = Stack("").String + } } return ce diff --git a/options.go b/options.go index c05b38117..074566a3d 100644 --- a/options.go +++ b/options.go @@ -119,6 +119,14 @@ func AddStacktrace(lvl zapcore.LevelEnabler) Option { }) } +// UseCallerSkipForStacktrace configures the logger to use the number of frames +// that should be skipped for caller (CallerSkip) annotation when taking stacktraces. +func UseCallerSkipForStacktrace(enabled bool) Option { + return optionFunc(func(log *Logger) { + log.useCallerSkipForStack = enabled + }) +} + // IncreaseLevel increase the level of the logger. It has no effect if // the passed in level tries to decrease the level of the logger. func IncreaseLevel(lvl zapcore.LevelEnabler) Option { diff --git a/stacktrace.go b/stacktrace.go index 100fac216..801f9519b 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -43,7 +43,7 @@ var ( _zapStacktraceVendorContains = addPrefix("/vendor/", _zapStacktracePrefixes...) ) -func takeStacktrace() string { +func takeStacktrace(skip *int) string { buffer := bufferpool.Get() defer buffer.Free() programCounters := _stacktracePool.Get().(*programCounters) @@ -69,6 +69,10 @@ func takeStacktrace() string { // Note: On the last iteration, frames.Next() returns false, with a valid // frame, but we ignore this frame. The last frame is a a runtime frame which // adds noise, since it's only either runtime.main or runtime.goexit. + toSkip := 0 + if skip != nil { + toSkip = *skip + } for frame, more := frames.Next(); more; frame, more = frames.Next() { if skipZapFrames && isZapFrame(frame.Function) { continue @@ -76,6 +80,11 @@ func takeStacktrace() string { skipZapFrames = false } + if toSkip > 0 { + toSkip-- + continue + } + if i != 0 { buffer.AppendByte('\n') } diff --git a/stacktrace_test.go b/stacktrace_test.go index 3c9a41cfd..7050bdc53 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -29,7 +29,7 @@ import ( ) func TestTakeStacktrace(t *testing.T) { - trace := takeStacktrace() + trace := takeStacktrace(nil) lines := strings.Split(trace, "\n") require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") assert.Contains( @@ -70,6 +70,6 @@ func TestIsZapFrame(t *testing.T) { func BenchmarkTakeStacktrace(b *testing.B) { for i := 0; i < b.N; i++ { - takeStacktrace() + takeStacktrace(nil) } } From 8e2550755fe30762a8a2a92979aa429c58c44d66 Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Thu, 23 Jul 2020 01:14:49 +0300 Subject: [PATCH 2/8] Change takeStacktrace skip parameter to a value --- field.go | 4 ++-- field_test.go | 2 +- stacktrace.go | 10 +++------- stacktrace_test.go | 4 ++-- 4 files changed, 8 insertions(+), 12 deletions(-) diff --git a/field.go b/field.go index be04f66c0..f6bb8a498 100644 --- a/field.go +++ b/field.go @@ -368,7 +368,7 @@ func Stack(key string) Field { // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation // is okay. - return String(key, takeStacktrace(nil)) + return String(key, takeStacktrace(0)) } // StackSkip constructs a field that stores a stacktrace of the current @@ -381,7 +381,7 @@ func StackSkip(key string, skip int) Field { // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation // is okay. - return String(key, takeStacktrace(&skip)) + return String(key, takeStacktrace(skip)) } // Duration constructs a field with the given key and value. The encoder diff --git a/field_test.go b/field_test.go index e45a1a95d..67a03a90d 100644 --- a/field_test.go +++ b/field_test.go @@ -259,6 +259,6 @@ func TestStackField(t *testing.T) { f := Stack("stacktrace") assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") - assert.Equal(t, takeStacktrace(nil), f.String, "Unexpected stack trace") + assert.Equal(t, takeStacktrace(0), f.String, "Unexpected stack trace") assertCanBeReused(t, f) } diff --git a/stacktrace.go b/stacktrace.go index 801f9519b..a578e046c 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -43,7 +43,7 @@ var ( _zapStacktraceVendorContains = addPrefix("/vendor/", _zapStacktracePrefixes...) ) -func takeStacktrace(skip *int) string { +func takeStacktrace(skip int) string { buffer := bufferpool.Get() defer buffer.Free() programCounters := _stacktracePool.Get().(*programCounters) @@ -69,10 +69,6 @@ func takeStacktrace(skip *int) string { // Note: On the last iteration, frames.Next() returns false, with a valid // frame, but we ignore this frame. The last frame is a a runtime frame which // adds noise, since it's only either runtime.main or runtime.goexit. - toSkip := 0 - if skip != nil { - toSkip = *skip - } for frame, more := frames.Next(); more; frame, more = frames.Next() { if skipZapFrames && isZapFrame(frame.Function) { continue @@ -80,8 +76,8 @@ func takeStacktrace(skip *int) string { skipZapFrames = false } - if toSkip > 0 { - toSkip-- + if skip > 0 { + skip-- continue } diff --git a/stacktrace_test.go b/stacktrace_test.go index 7050bdc53..396e1edfd 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -29,7 +29,7 @@ import ( ) func TestTakeStacktrace(t *testing.T) { - trace := takeStacktrace(nil) + trace := takeStacktrace(0) lines := strings.Split(trace, "\n") require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") assert.Contains( @@ -70,6 +70,6 @@ func TestIsZapFrame(t *testing.T) { func BenchmarkTakeStacktrace(b *testing.B) { for i := 0; i < b.N; i++ { - takeStacktrace(nil) + takeStacktrace(0) } } From c27b7e49e5561e932f77f5fbc33df133e1439aa6 Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Thu, 23 Jul 2020 01:16:07 +0300 Subject: [PATCH 3/8] Modify StackSkip doc --- field.go | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/field.go b/field.go index f6bb8a498..a5cee85c7 100644 --- a/field.go +++ b/field.go @@ -371,11 +371,8 @@ func Stack(key string) Field { return String(key, takeStacktrace(0)) } -// StackSkip constructs a field that stores a stacktrace of the current -// goroutine under provided key, skipping the given number of frames from the -// top of the stacktrace. Keep in mind that taking a stacktrace is eager and -// expensive (relatively speaking); this function both makes an allocation and -// takes about two microseconds. +// StackSkip constructs a field similarly to Stack, but also skips the given +// number of frames from the top of the stacktrace. func StackSkip(key string, skip int) Field { // Returning the stacktrace as a string costs an allocation, but saves us // from expanding the zapcore.Field union struct to include a byte slice. Since From 3410fce72582a14bbbc0903d45bda999c4c46f13 Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Sun, 26 Jul 2020 02:03:35 +0300 Subject: [PATCH 4/8] Added tests and fixed bugs --- field.go | 5 +++++ field_test.go | 16 ++++++++++++++++ logger.go | 2 +- stacktrace.go | 5 +++-- stacktrace_ext_test.go | 26 ++++++++++++++++++++++++++ stacktrace_test.go | 27 +++++++++++++++++++++++++++ 6 files changed, 78 insertions(+), 3 deletions(-) diff --git a/field.go b/field.go index a5cee85c7..d1672db7a 100644 --- a/field.go +++ b/field.go @@ -374,6 +374,11 @@ func Stack(key string) Field { // StackSkip constructs a field similarly to Stack, but also skips the given // number of frames from the top of the stacktrace. func StackSkip(key string, skip int) Field { + // Skip the call to StackSkip + if skip != 0 { + skip++ + } + // Returning the stacktrace as a string costs an allocation, but saves us // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation diff --git a/field_test.go b/field_test.go index 67a03a90d..71d485ad9 100644 --- a/field_test.go +++ b/field_test.go @@ -262,3 +262,19 @@ func TestStackField(t *testing.T) { assert.Equal(t, takeStacktrace(0), f.String, "Unexpected stack trace") assertCanBeReused(t, f) } + +func TestStackSkipField(t *testing.T) { + f := StackSkip("stacktrace", 0) + assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") + assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") + assert.Equal(t, takeStacktrace(0), f.String, "Unexpected stack trace") + assertCanBeReused(t, f) +} + +func TestStackSkipFieldWithSkip(t *testing.T) { + f := StackSkip("stacktrace", 1) + assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") + assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") + assert.Equal(t, takeStacktrace(1), f.String, "Unexpected stack trace") + assertCanBeReused(t, f) +} diff --git a/logger.go b/logger.go index afb057ad9..0c8ac05e3 100644 --- a/logger.go +++ b/logger.go @@ -306,7 +306,7 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry { } if log.addStack.Enabled(ce.Entry.Level) { if log.useCallerSkipForStack { - ce.Entry.Stack = StackSkip("", log.callerSkip).String + ce.Entry.Stack = StackSkip("", log.callerSkip+callerSkipOffset).String } else { ce.Entry.Stack = Stack("").String } diff --git a/stacktrace.go b/stacktrace.go index a578e046c..c3f4f55a3 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -51,7 +51,7 @@ func takeStacktrace(skip int) string { var numFrames int for { - // Skip the call to runtime.Counters and takeStacktrace so that the + // Skip the call to runtime.Callers and takeStacktrace so that the // program counters start at the caller of takeStacktrace. numFrames = runtime.Callers(2, programCounters.pcs) if numFrames < len(programCounters.pcs) { @@ -62,8 +62,9 @@ func takeStacktrace(skip int) string { programCounters = newProgramCounters(len(programCounters.pcs) * 2) } + // Skip all consecutive zap frames at the beginning if no skip is set. + skipZapFrames := skip == 0 i := 0 - skipZapFrames := true // skip all consecutive zap frames at the beginning. frames := runtime.CallersFrames(programCounters.pcs[:numFrames]) // Note: On the last iteration, frames.Next() returns false, with a valid diff --git a/stacktrace_ext_test.go b/stacktrace_ext_test.go index f780b33ee..97c8a81b7 100644 --- a/stacktrace_ext_test.go +++ b/stacktrace_ext_test.go @@ -120,6 +120,32 @@ func TestStacktraceFiltersVendorZap(t *testing.T) { }) } +func TestStacktraceUseCallerSkipForStacktraceWithoutCallerSkip(t *testing.T) { + withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) { + logger = logger.WithOptions(zap.UseCallerSkipForStacktrace(true)) + func() { + logger.Error("test log") + }() + + require.Contains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithoutCallerSkip.", "Should not skip too much") + require.Contains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithoutCallerSkip", "Should not skip too much") + verifyNoZap(t, out.String()) + }) +} + +func TestStacktraceUseCallerSkipForStacktraceWithCallerSkip(t *testing.T) { + withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) { + logger = logger.WithOptions(zap.UseCallerSkipForStacktrace(true), zap.AddCallerSkip(2)) + func() { + logger.Error("test log") + }() + + require.NotContains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithCallerSkip.", "Should skip as requested by caller skip") + require.Contains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithCallerSkip", "Should not skip too much") + verifyNoZap(t, out.String()) + }) +} + // withLogger sets up a logger with a real encoder set up, so that any marshal functions are called. // The inbuilt observer does not call Marshal for objects/arrays, which we need for some tests. func withLogger(t *testing.T, fn func(logger *zap.Logger, out *bytes.Buffer)) { diff --git a/stacktrace_test.go b/stacktrace_test.go index 396e1edfd..21caf3db2 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -68,6 +68,33 @@ func TestIsZapFrame(t *testing.T) { }) } +func TestTakeStacktraceWithSkip(t *testing.T) { + trace := takeStacktrace(1) + lines := strings.Split(trace, "\n") + require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") + assert.Contains( + t, + lines[0], + "testing.", + "Expected stacktrace to start with the test runner (skipping our own frame) %s.", lines[0], + ) +} + +func TestTakeStacktraceWithSkipInnerFunc(t *testing.T) { + var trace string + func() { + trace = takeStacktrace(1) + }() + lines := strings.Split(trace, "\n") + require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") + assert.Contains( + t, + lines[0], + "testing.", + "Expected stacktrace to start with the test function (skipping the inner func) %s.", lines[0], + ) +} + func BenchmarkTakeStacktrace(b *testing.B) { for i := 0; i < b.N; i++ { takeStacktrace(0) From 33c1b16de185ffbd6f52de250c2a19c66f2193e0 Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Sun, 26 Jul 2020 02:11:05 +0300 Subject: [PATCH 5/8] Fix failing test --- stacktrace_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/stacktrace_test.go b/stacktrace_test.go index 21caf3db2..c67426119 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -83,7 +83,7 @@ func TestTakeStacktraceWithSkip(t *testing.T) { func TestTakeStacktraceWithSkipInnerFunc(t *testing.T) { var trace string func() { - trace = takeStacktrace(1) + trace = takeStacktrace(2) }() lines := strings.Split(trace, "\n") require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") @@ -91,7 +91,7 @@ func TestTakeStacktraceWithSkipInnerFunc(t *testing.T) { t, lines[0], "testing.", - "Expected stacktrace to start with the test function (skipping the inner func) %s.", lines[0], + "Expected stacktrace to start with the test function (skipping the test function) %s.", lines[0], ) } From 80d2017e49fae312c05783663d03055562e48764 Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Wed, 5 Aug 2020 17:50:39 +0300 Subject: [PATCH 6/8] Make UseCallerSkipForStacktrace the default, removing the option Also remove the zap frame skipping logic in favour of zap setting the skip correctly when taking the stack trace. --- config_test.go | 2 +- field.go | 13 ++----------- field_test.go | 8 +++++--- logger.go | 9 ++------- options.go | 8 -------- stacktrace.go | 42 ------------------------------------------ stacktrace_ext_test.go | 15 +++++++-------- stacktrace_test.go | 32 ++------------------------------ 8 files changed, 19 insertions(+), 110 deletions(-) diff --git a/config_test.go b/config_test.go index 19af60795..ac098aafe 100644 --- a/config_test.go +++ b/config_test.go @@ -52,7 +52,7 @@ func TestConfig(t *testing.T) { expectRe: "DEBUG\tzap/config_test.go:" + `\d+` + "\tdebug\t" + `{"k": "v", "z": "zz"}` + "\n" + "INFO\tzap/config_test.go:" + `\d+` + "\tinfo\t" + `{"k": "v", "z": "zz"}` + "\n" + "WARN\tzap/config_test.go:" + `\d+` + "\twarn\t" + `{"k": "v", "z": "zz"}` + "\n" + - `testing.\w+`, + `go.uber.org/zap.TestConfig.\w+`, }, } diff --git a/field.go b/field.go index d1672db7a..3c0d7d957 100644 --- a/field.go +++ b/field.go @@ -364,26 +364,17 @@ func Timep(key string, val *time.Time) Field { // expensive (relatively speaking); this function both makes an allocation and // takes about two microseconds. func Stack(key string) Field { - // Returning the stacktrace as a string costs an allocation, but saves us - // from expanding the zapcore.Field union struct to include a byte slice. Since - // taking a stacktrace is already so expensive (~10us), the extra allocation - // is okay. - return String(key, takeStacktrace(0)) + return StackSkip(key, 1) // skip Stack } // StackSkip constructs a field similarly to Stack, but also skips the given // number of frames from the top of the stacktrace. func StackSkip(key string, skip int) Field { - // Skip the call to StackSkip - if skip != 0 { - skip++ - } - // Returning the stacktrace as a string costs an allocation, but saves us // from expanding the zapcore.Field union struct to include a byte slice. Since // taking a stacktrace is already so expensive (~10us), the extra allocation // is okay. - return String(key, takeStacktrace(skip)) + return String(key, takeStacktrace(skip+1)) // skip StackSkip } // Duration constructs a field with the given key and value. The encoder diff --git a/field_test.go b/field_test.go index 71d485ad9..08c1bf45b 100644 --- a/field_test.go +++ b/field_test.go @@ -23,6 +23,7 @@ package zap import ( "math" "net" + "regexp" "sync" "testing" "time" @@ -259,15 +260,16 @@ func TestStackField(t *testing.T) { f := Stack("stacktrace") assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") - assert.Equal(t, takeStacktrace(0), f.String, "Unexpected stack trace") + r := regexp.MustCompile(`field_test.go:(\d+)`) + assert.Equal(t, r.ReplaceAllString(takeStacktrace(0), "field_test.go"), r.ReplaceAllString(f.String, "field_test.go"), "Unexpected stack trace") assertCanBeReused(t, f) } func TestStackSkipField(t *testing.T) { - f := StackSkip("stacktrace", 0) + f := StackSkip("stacktrace", 1) assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") - assert.Equal(t, takeStacktrace(0), f.String, "Unexpected stack trace") + assert.Equal(t, takeStacktrace(1), f.String, "Unexpected stack trace") assertCanBeReused(t, f) } diff --git a/logger.go b/logger.go index 0c8ac05e3..532968d22 100644 --- a/logger.go +++ b/logger.go @@ -48,8 +48,7 @@ type Logger struct { addCaller bool addStack zapcore.LevelEnabler - callerSkip int - useCallerSkipForStack bool + callerSkip int } // New constructs a new Logger from the provided zapcore.Core and Options. If @@ -305,11 +304,7 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry { } } if log.addStack.Enabled(ce.Entry.Level) { - if log.useCallerSkipForStack { - ce.Entry.Stack = StackSkip("", log.callerSkip+callerSkipOffset).String - } else { - ce.Entry.Stack = Stack("").String - } + ce.Entry.Stack = StackSkip("", log.callerSkip+callerSkipOffset).String } return ce diff --git a/options.go b/options.go index 074566a3d..c05b38117 100644 --- a/options.go +++ b/options.go @@ -119,14 +119,6 @@ func AddStacktrace(lvl zapcore.LevelEnabler) Option { }) } -// UseCallerSkipForStacktrace configures the logger to use the number of frames -// that should be skipped for caller (CallerSkip) annotation when taking stacktraces. -func UseCallerSkipForStacktrace(enabled bool) Option { - return optionFunc(func(log *Logger) { - log.useCallerSkipForStack = enabled - }) -} - // IncreaseLevel increase the level of the logger. It has no effect if // the passed in level tries to decrease the level of the logger. func IncreaseLevel(lvl zapcore.LevelEnabler) Option { diff --git a/stacktrace.go b/stacktrace.go index c3f4f55a3..35819231f 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -22,25 +22,17 @@ package zap import ( "runtime" - "strings" "sync" "go.uber.org/zap/internal/bufferpool" ) -const _zapPackage = "go.uber.org/zap" - var ( _stacktracePool = sync.Pool{ New: func() interface{} { return newProgramCounters(64) }, } - - // We add "." and "/" suffixes to the package name to ensure we only match - // the exact package and not any package with the same prefix. - _zapStacktracePrefixes = addPrefix(_zapPackage, ".", "/") - _zapStacktraceVendorContains = addPrefix("/vendor/", _zapStacktracePrefixes...) ) func takeStacktrace(skip int) string { @@ -62,8 +54,6 @@ func takeStacktrace(skip int) string { programCounters = newProgramCounters(len(programCounters.pcs) * 2) } - // Skip all consecutive zap frames at the beginning if no skip is set. - skipZapFrames := skip == 0 i := 0 frames := runtime.CallersFrames(programCounters.pcs[:numFrames]) @@ -71,12 +61,6 @@ func takeStacktrace(skip int) string { // frame, but we ignore this frame. The last frame is a a runtime frame which // adds noise, since it's only either runtime.main or runtime.goexit. for frame, more := frames.Next(); more; frame, more = frames.Next() { - if skipZapFrames && isZapFrame(frame.Function) { - continue - } else { - skipZapFrames = false - } - if skip > 0 { skip-- continue @@ -97,24 +81,6 @@ func takeStacktrace(skip int) string { return buffer.String() } -func isZapFrame(function string) bool { - for _, prefix := range _zapStacktracePrefixes { - if strings.HasPrefix(function, prefix) { - return true - } - } - - // We can't use a prefix match here since the location of the vendor - // directory affects the prefix. Instead we do a contains match. - for _, contains := range _zapStacktraceVendorContains { - if strings.Contains(function, contains) { - return true - } - } - - return false -} - type programCounters struct { pcs []uintptr } @@ -122,11 +88,3 @@ type programCounters struct { func newProgramCounters(size int) *programCounters { return &programCounters{make([]uintptr, size)} } - -func addPrefix(prefix string, ss ...string) []string { - withPrefix := make([]string, len(ss)) - for i, s := range ss { - withPrefix[i] = prefix + s - } - return withPrefix -} diff --git a/stacktrace_ext_test.go b/stacktrace_ext_test.go index 97c8a81b7..c37e2d65a 100644 --- a/stacktrace_ext_test.go +++ b/stacktrace_ext_test.go @@ -120,28 +120,27 @@ func TestStacktraceFiltersVendorZap(t *testing.T) { }) } -func TestStacktraceUseCallerSkipForStacktraceWithoutCallerSkip(t *testing.T) { +func TestStacktraceWithoutCallerSkip(t *testing.T) { withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) { - logger = logger.WithOptions(zap.UseCallerSkipForStacktrace(true)) func() { logger.Error("test log") }() - require.Contains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithoutCallerSkip.", "Should not skip too much") - require.Contains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithoutCallerSkip", "Should not skip too much") + require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip.", "Should not skip too much") + require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip", "Should not skip too much") verifyNoZap(t, out.String()) }) } -func TestStacktraceUseCallerSkipForStacktraceWithCallerSkip(t *testing.T) { +func TestStacktraceWithCallerSkip(t *testing.T) { withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) { - logger = logger.WithOptions(zap.UseCallerSkipForStacktrace(true), zap.AddCallerSkip(2)) + logger = logger.WithOptions(zap.AddCallerSkip(2)) func() { logger.Error("test log") }() - require.NotContains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithCallerSkip.", "Should skip as requested by caller skip") - require.Contains(t, out.String(), "TestStacktraceUseCallerSkipForStacktraceWithCallerSkip", "Should not skip too much") + require.NotContains(t, out.String(), "TestStacktraceWithCallerSkip.", "Should skip as requested by caller skip") + require.Contains(t, out.String(), "TestStacktraceWithCallerSkip", "Should not skip too much") verifyNoZap(t, out.String()) }) } diff --git a/stacktrace_test.go b/stacktrace_test.go index c67426119..6482082be 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -35,39 +35,11 @@ func TestTakeStacktrace(t *testing.T) { assert.Contains( t, lines[0], - "testing.", - "Expected stacktrace to start with the test runner (zap frames are filtered out) %s.", lines[0], + "go.uber.org/zap.TestTakeStacktrace", + "Expected stacktrace to start with the test %s.", lines[0], ) } -func TestIsZapFrame(t *testing.T) { - zapFrames := []string{ - "go.uber.org/zap.Stack", - "go.uber.org/zap.(*SugaredLogger).log", - "go.uber.org/zap/zapcore.(ArrayMarshalerFunc).MarshalLogArray", - "github.com/uber/tchannel-go/vendor/go.uber.org/zap.Stack", - "github.com/uber/tchannel-go/vendor/go.uber.org/zap.(*SugaredLogger).log", - "github.com/uber/tchannel-go/vendor/go.uber.org/zap/zapcore.(ArrayMarshalerFunc).MarshalLogArray", - } - nonZapFrames := []string{ - "github.com/uber/tchannel-go.NewChannel", - "go.uber.org/not-zap.New", - "go.uber.org/zapext.ctx", - "go.uber.org/zap_ext/ctx.New", - } - - t.Run("zap frames", func(t *testing.T) { - for _, f := range zapFrames { - require.True(t, isZapFrame(f), f) - } - }) - t.Run("non-zap frames", func(t *testing.T) { - for _, f := range nonZapFrames { - require.False(t, isZapFrame(f), f) - } - }) -} - func TestTakeStacktraceWithSkip(t *testing.T) { trace := takeStacktrace(1) lines := strings.Split(trace, "\n") From 066ee2d901df82c135f024e11ffb011b95788166 Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Wed, 12 Aug 2020 11:01:06 +0300 Subject: [PATCH 7/8] Code review fix --- stacktrace.go | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/stacktrace.go b/stacktrace.go index 35819231f..0cf8c1ddf 100644 --- a/stacktrace.go +++ b/stacktrace.go @@ -45,7 +45,7 @@ func takeStacktrace(skip int) string { for { // Skip the call to runtime.Callers and takeStacktrace so that the // program counters start at the caller of takeStacktrace. - numFrames = runtime.Callers(2, programCounters.pcs) + numFrames = runtime.Callers(skip+2, programCounters.pcs) if numFrames < len(programCounters.pcs) { break } @@ -61,11 +61,6 @@ func takeStacktrace(skip int) string { // frame, but we ignore this frame. The last frame is a a runtime frame which // adds noise, since it's only either runtime.main or runtime.goexit. for frame, more := frames.Next(); more; frame, more = frames.Next() { - if skip > 0 { - skip-- - continue - } - if i != 0 { buffer.AppendByte('\n') } From fc5ed1db033e371805e7a2d005c48c0bed18ad8d Mon Sep 17 00:00:00 2001 From: Segev Finer Date: Sat, 15 Aug 2020 14:17:22 +0300 Subject: [PATCH 8/8] Code review fixes for tests --- field_test.go | 5 +++-- stacktrace_ext_test.go | 1 - stacktrace_test.go | 12 ++++++------ 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/field_test.go b/field_test.go index 08c1bf45b..fbfc635d5 100644 --- a/field_test.go +++ b/field_test.go @@ -266,10 +266,11 @@ func TestStackField(t *testing.T) { } func TestStackSkipField(t *testing.T) { - f := StackSkip("stacktrace", 1) + f := StackSkip("stacktrace", 0) assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.") assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.") - assert.Equal(t, takeStacktrace(1), f.String, "Unexpected stack trace") + r := regexp.MustCompile(`field_test.go:(\d+)`) + assert.Equal(t, r.ReplaceAllString(takeStacktrace(0), "field_test.go"), r.ReplaceAllString(f.String, "field_test.go"), f.String, "Unexpected stack trace") assertCanBeReused(t, f) } diff --git a/stacktrace_ext_test.go b/stacktrace_ext_test.go index c37e2d65a..3b56070a9 100644 --- a/stacktrace_ext_test.go +++ b/stacktrace_ext_test.go @@ -127,7 +127,6 @@ func TestStacktraceWithoutCallerSkip(t *testing.T) { }() require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip.", "Should not skip too much") - require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip", "Should not skip too much") verifyNoZap(t, out.String()) }) } diff --git a/stacktrace_test.go b/stacktrace_test.go index 6482082be..d473029ee 100644 --- a/stacktrace_test.go +++ b/stacktrace_test.go @@ -31,24 +31,24 @@ import ( func TestTakeStacktrace(t *testing.T) { trace := takeStacktrace(0) lines := strings.Split(trace, "\n") - require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") + require.NotEmpty(t, lines, "Expected stacktrace to have at least one frame.") assert.Contains( t, lines[0], "go.uber.org/zap.TestTakeStacktrace", - "Expected stacktrace to start with the test %s.", lines[0], + "Expected stacktrace to start with the test.", ) } func TestTakeStacktraceWithSkip(t *testing.T) { trace := takeStacktrace(1) lines := strings.Split(trace, "\n") - require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") + require.NotEmpty(t, lines, "Expected stacktrace to have at least one frame.") assert.Contains( t, lines[0], "testing.", - "Expected stacktrace to start with the test runner (skipping our own frame) %s.", lines[0], + "Expected stacktrace to start with the test runner (skipping our own frame).", ) } @@ -58,12 +58,12 @@ func TestTakeStacktraceWithSkipInnerFunc(t *testing.T) { trace = takeStacktrace(2) }() lines := strings.Split(trace, "\n") - require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.") + require.NotEmpty(t, lines, "Expected stacktrace to have at least one frame.") assert.Contains( t, lines[0], "testing.", - "Expected stacktrace to start with the test function (skipping the test function) %s.", lines[0], + "Expected stacktrace to start with the test function (skipping the test function).", ) }