Skip to content

Commit

Permalink
Make UseCallerSkipForStacktrace the default, removing the option
Browse files Browse the repository at this point in the history
Also remove the zap frame skipping logic in favour of zap setting the
skip correctly when taking the stack trace.
  • Loading branch information
segevfiner committed Aug 5, 2020
1 parent 33c1b16 commit 20dc3e4
Show file tree
Hide file tree
Showing 8 changed files with 19 additions and 100 deletions.
2 changes: 1 addition & 1 deletion config_test.go
Expand Up @@ -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+`,
},
}

Expand Down
13 changes: 2 additions & 11 deletions field.go
Expand Up @@ -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
Expand Down
8 changes: 5 additions & 3 deletions field_test.go
Expand Up @@ -23,6 +23,7 @@ package zap
import (
"math"
"net"
"regexp"
"sync"
"testing"
"time"
Expand Down Expand Up @@ -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)
}

Expand Down
9 changes: 2 additions & 7 deletions logger.go
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
8 changes: 0 additions & 8 deletions options.go
Expand Up @@ -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 {
Expand Down
32 changes: 0 additions & 32 deletions stacktrace.go
Expand Up @@ -22,7 +22,6 @@ package zap

import (
"runtime"
"strings"
"sync"

"go.uber.org/zap/internal/bufferpool"
Expand All @@ -36,11 +35,6 @@ var (
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 {
Expand All @@ -62,21 +56,13 @@ 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])

// 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 skip > 0 {
skip--
continue
Expand All @@ -97,24 +83,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
}
Expand Down
15 changes: 7 additions & 8 deletions stacktrace_ext_test.go
Expand Up @@ -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())
})
}
Expand Down
32 changes: 2 additions & 30 deletions stacktrace_test.go
Expand Up @@ -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")
Expand Down

0 comments on commit 20dc3e4

Please sign in to comment.