Skip to content

Commit

Permalink
stacktrace: honor StackSkip
Browse files Browse the repository at this point in the history
 * Honor StackSkip option when including stacktrace.
 * Replace package-based stack pruning - the same behavior is achieved by
   skipping frames appropriately.

 fixes uber-go#512
  • Loading branch information
boz committed Nov 10, 2017
1 parent f85c78b commit ecfe00a
Show file tree
Hide file tree
Showing 7 changed files with 131 additions and 181 deletions.
2 changes: 1 addition & 1 deletion config_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,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+`,
},
}

Expand Down
9 changes: 8 additions & 1 deletion field.go
Original file line number Diff line number Diff line change
Expand Up @@ -188,7 +188,14 @@ func Stack(key string) zapcore.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 stackField(key, 1)
}

// stackField returns a stacktrace field with the first skip frames ignored.
//
// stackField("foo",0) is equivalent to Stack("foo").
func stackField(key string, skip int) zapcore.Field {
return String(key, takeStacktrace(skip+1))
}

// Duration constructs a field with the given key and value. The encoder
Expand Down
22 changes: 21 additions & 1 deletion field_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ package zap

import (
"net"
"strings"
"sync"
"testing"
"time"
Expand Down Expand Up @@ -151,9 +152,28 @@ func TestFieldConstructors(t *testing.T) {
}

func TestStackField(t *testing.T) {
fn := func(st string) string {
return strings.Split(st, "\n")[0]
}

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, fn(takeStacktrace(0)), fn(f.String), "Unexpected stack trace")
assert.Equal(t, fn(stackField("", 0).String), fn(f.String), "Expected equivelance to StackSkip")

assertCanBeReused(t, f)
}

func TestStackSkipField(t *testing.T) {
fn := func(f zapcore.Field) string {
return strings.Split(f.String, "\n")[0]
}

stack := Stack("")
assert.Equal(t, fn(stack), fn(stackField("", 0)))

func() {
assert.Equal(t, fn(stack), fn(stackField("", 1)))
}()
}
6 changes: 3 additions & 3 deletions logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -256,7 +256,7 @@ func (log *Logger) clone() *Logger {
func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
// check must always be called directly by a method in the Logger interface
// (e.g., Check, Info, Fatal).
const callerSkipOffset = 2
callerSkipOffset := 2 + log.callerSkip

// Create basic checked entry thru the core; this will be non-nil if the
// log message will actually be written somewhere.
Expand Down Expand Up @@ -291,14 +291,14 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
// Thread the error output through to the CheckedEntry.
ce.ErrorOutput = log.errorOutput
if log.addCaller {
ce.Entry.Caller = zapcore.NewEntryCaller(runtime.Caller(log.callerSkip + callerSkipOffset))
ce.Entry.Caller = zapcore.NewEntryCaller(runtime.Caller(callerSkipOffset))
if !ce.Entry.Caller.Defined {
fmt.Fprintf(log.errorOutput, "%v Logger.check error: failed to get caller\n", time.Now().UTC())
log.errorOutput.Sync()
}
}
if log.addStack.Enabled(ce.Entry.Level) {
ce.Entry.Stack = Stack("").String
ce.Entry.Stack = stackField("", callerSkipOffset).String
}

return ce
Expand Down
52 changes: 7 additions & 45 deletions stacktrace.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,38 +22,33 @@ 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() string {
func takeStacktrace(skip int) string {
buffer := bufferpool.Get()
defer buffer.Free()
programCounters := _stacktracePool.Get().(*programCounters)
defer _stacktracePool.Put(programCounters)

var numFrames int

// Skip the call to runtime.Counters and takeStacktrace so that the
// program counters start at the caller of takeStacktrace.
skip += 2

for {
// Skip the call to runtime.Counters and takeStacktrace so that the
// program counters start at the caller of takeStacktrace.
numFrames = runtime.Callers(2, programCounters.pcs)
numFrames = runtime.Callers(skip, programCounters.pcs)
if numFrames < len(programCounters.pcs) {
break
}
Expand All @@ -63,19 +58,12 @@ func takeStacktrace() string {
}

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
// 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 i != 0 {
buffer.AppendByte('\n')
}
Expand All @@ -91,36 +79,10 @@ func takeStacktrace() 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
}

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
}
Loading

0 comments on commit ecfe00a

Please sign in to comment.