stacktrace: skip frames

 * Skip frames as configured in stacktraces
 * Add `StackSkip()` to manually retrieved a pruned stacktrace
 * Remove "zip" package pruning in `takeStacktrace()`

 fixes uber-go#512

config_test.go

@@ -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+`,
 		},
 	}
 

field.go

@@ -184,11 +184,19 @@ func Time(key string, val time.Time) zapcore.Field {
 // expensive (relatively speaking); this function both makes an allocation and
 // takes about two microseconds.
 func Stack(key string) zapcore.Field {
+	return String(key, takeStacktrace(1))
+}
+
+// StackSkip returns a stacktrace field like Stack and also allows for skipping
+// stack frames via the skip argument.
+//
+// StackSkip("foo",0) is equivalent to Stack("foo").
+func StackSkip(key string, skip int) zapcore.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())
+	return String(key, takeStacktrace(skip+1))
 }
 
 // Duration constructs a field with the given key and value. The encoder

field_test.go

@@ -22,6 +22,7 @@ package zap
 
 import (
 	"net"
+	"strings"
 	"sync"
 	"testing"
 	"time"
@@ -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(StackSkip("", 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(StackSkip("", 0)))
+
+	func() {
+		assert.Equal(t, fn(stack), fn(StackSkip("", 1)))
+	}()
+}

logger.go

@@ -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.
@@ -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 = StackSkip("", callerSkipOffset).String
 	}
 
 	return ce

stacktrace.go

@@ -22,38 +22,31 @@ 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 += 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
 		}
@@ -63,19 +56,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')
 		}
@@ -91,36 +77,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
-}

stacktrace_ext_test.go

@@ -56,6 +56,19 @@ func TestStacktraceFiltersZapLog(t *testing.T) {
 	})
 }
 
+func TestStackSkip(t *testing.T) {
+	fn := func(f zapcore.Field) string {
+		return strings.Split(f.String, "\n")[0]
+	}
+
+	orig := fn(zap.Stack(""))
+	assert.Equal(t, orig, fn(zap.StackSkip("", 0)))
+
+	func() {
+		assert.Equal(t, orig, fn(zap.StackSkip("", 1)))
+	}()
+}
+
 func TestStacktraceFiltersZapMarshal(t *testing.T) {
 	withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) {
 		marshal := func(enc zapcore.ObjectEncoder) error {

stacktrace_test.go

@@ -29,47 +29,25 @@ import (
 )
 
 func TestTakeStacktrace(t *testing.T) {
-	trace := takeStacktrace()
+	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 (zap frames are filtered out) %s.", lines[0],
+		"Expected stacktrace to start with the test runner %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() {
+		skipped := strings.Split(takeStacktrace(2), "\n")
+		require.True(t, len(skipped) > 0, "Expected skipped stacktrace to have at least one frame.")
+		assert.Equal(t, lines[0], skipped[0])
+	}()
 }
 
 func BenchmarkTakeStacktrace(b *testing.B) {
 	for i := 0; i < b.N; i++ {
-		takeStacktrace()
+		takeStacktrace(0)
 	}
 }