Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Honor CallerSkip when taking stack traces & add the StackSkip field #843

Merged
merged 8 commits into from Aug 18, 2020
Merged
Show file tree
Hide file tree
Changes from 5 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
17 changes: 16 additions & 1 deletion field.go
Expand Up @@ -368,7 +368,22 @@ 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(0))
segevfiner marked this conversation as resolved.
Show resolved Hide resolved
}

// 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++
segevfiner marked this conversation as resolved.
Show resolved Hide resolved
}

// 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
Expand Down
18 changes: 17 additions & 1 deletion field_test.go
Expand Up @@ -259,6 +259,22 @@ 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(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) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There doesn't appear to be any difference between this and TestStackSkipField. Did you mean to use zero for TestStackSkipField?

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)
}
9 changes: 7 additions & 2 deletions logger.go
Expand Up @@ -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
Expand Down Expand Up @@ -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+callerSkipOffset).String
} else {
ce.Entry.Stack = Stack("").String
}
}

return ce
Expand Down
8 changes: 8 additions & 0 deletions options.go
Expand Up @@ -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 {
Expand Down
12 changes: 9 additions & 3 deletions stacktrace.go
Expand Up @@ -43,15 +43,15 @@ var (
_zapStacktraceVendorContains = addPrefix("/vendor/", _zapStacktracePrefixes...)
)

func takeStacktrace() string {
func takeStacktrace(skip int) string {
buffer := bufferpool.Get()
defer buffer.Free()
programCounters := _stacktracePool.Get().(*programCounters)
defer _stacktracePool.Put(programCounters)

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)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why do we implement skip manually below, can't we just add it here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Leftover from still having skip zap frames.

if numFrames < len(programCounters.pcs) {
Expand All @@ -62,8 +62,9 @@ func takeStacktrace() 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.
prashantv marked this conversation as resolved.
Show resolved Hide resolved
frames := runtime.CallersFrames(programCounters.pcs[:numFrames])

// Note: On the last iteration, frames.Next() returns false, with a valid
Expand All @@ -76,6 +77,11 @@ func takeStacktrace() string {
skipZapFrames = false
}

if skip > 0 {
skip--
continue
}

if i != 0 {
buffer.AppendByte('\n')
}
Expand Down
26 changes: 26 additions & 0 deletions stacktrace_ext_test.go
Expand Up @@ -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)) {
Expand Down
31 changes: 29 additions & 2 deletions stacktrace_test.go
Expand Up @@ -29,7 +29,7 @@ import (
)

func TestTakeStacktrace(t *testing.T) {
trace := takeStacktrace()
trace := takeStacktrace(0)
lines := strings.Split(trace, "\n")
require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.")
assert.Contains(
Expand Down Expand Up @@ -68,8 +68,35 @@ 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.")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

minor: Can use NotEmpty.

Suggested change
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],
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

minor: Testify will include the lines[0] in the output so we don't need to.

Suggested change
"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).",

)
}

func TestTakeStacktraceWithSkipInnerFunc(t *testing.T) {
var trace string
func() {
trace = takeStacktrace(2)
}()
lines := strings.Split(trace, "\n")
require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
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],
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
"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.",

)
}

func BenchmarkTakeStacktrace(b *testing.B) {
for i := 0; i < b.N; i++ {
takeStacktrace()
takeStacktrace(0)
}
}