Codebase list golang-go.uber-zap / 0fdd86f
Skip zap stack frames in stacktrace output (#491) Currently, zap only filters out runtime stackframes, which leaves a lot of noise from zap (Error, log, check, etc). This modifies the stacktrace to filter out all zap frames at the beginning of the stack. It will not filter out zap stacks in between non-zap frames. Fixes #488. Prashant Varanasi authored 6 years ago GitHub committed 6 years ago
6 changed file(s) with 239 addition(s) and 24 deletion(s). Raw diff Collapse all Expand all
+1
-1
config_test.go less more
4949 expectRe: "DEBUG\tzap/config_test.go:" + `\d+` + "\tdebug\t" + `{"k": "v", "z": "zz"}` + "\n" +
5050 "INFO\tzap/config_test.go:" + `\d+` + "\tinfo\t" + `{"k": "v", "z": "zz"}` + "\n" +
5151 "WARN\tzap/config_test.go:" + `\d+` + "\twarn\t" + `{"k": "v", "z": "zz"}` + "\n" +
52 `go.uber.org/zap.Stack`,
52 `testing.\w+`,
5353 },
5454 }
5555
+1
-1
field_test.go less more
153153 f := Stack("stacktrace")
154154 assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.")
155155 assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.")
156 assert.Contains(t, f.String, "zap.TestStackField", "Expected stacktrace to contain caller.")
156 assert.Equal(t, takeStacktrace(), f.String, "Unexpected stack trace")
157157 assertCanBeReused(t, f)
158158 }
+0
-20
logger_test.go less more
379379 })
380380 }
381381
382 func TestLoggerAddStacktrace(t *testing.T) {
383 assertHasStack := func(t testing.TB, obs observer.LoggedEntry) {
384 assert.Contains(t, obs.Entry.Stack, "zap.TestLoggerAddStacktrace", "Expected to find test function in stacktrace.")
385 }
386 withLogger(t, DebugLevel, opts(AddStacktrace(InfoLevel)), func(logger *Logger, logs *observer.ObservedLogs) {
387 logger.Debug("")
388 assert.Empty(
389 t,
390 logs.AllUntimed()[0].Entry.Stack,
391 "Unexpected stacktrack at DebugLevel.",
392 )
393
394 logger.Info("")
395 assertHasStack(t, logs.AllUntimed()[1])
396
397 logger.Warn("")
398 assertHasStack(t, logs.AllUntimed()[2])
399 })
400 }
401
402382 func TestLoggerReplaceCore(t *testing.T) {
403383 replace := WrapCore(func(zapcore.Core) zapcore.Core {
404384 return zapcore.NewNopCore()
+40
-0
stacktrace.go less more
2727 "go.uber.org/zap/internal/bufferpool"
2828 )
2929
30 const _zapPackage = "go.uber.org/zap"
31
3032 var (
3133 _stacktraceIgnorePrefixes = []string{
3234 "runtime.goexit",
3739 return newProgramCounters(64)
3840 },
3941 }
42
43 // We add "." and "/" suffixes to the package name to ensure we only match
44 // the exact package and not any package with the same prefix.
45 _zapStacktracePrefixes = addPrefix(_zapPackage, ".", "/")
46 _zapStacktraceVendorContains = addPrefix("/vendor/", _zapStacktracePrefixes...)
4047 )
4148
4249 func takeStacktrace() string {
5966 }
6067
6168 i := 0
69 skipZapFrames := true // skip all consecutive zap frames at the beginning.
6270 frames := runtime.CallersFrames(programCounters.pcs[:numFrames])
6371 for frame, more := frames.Next(); more; frame, more = frames.Next() {
6472 if shouldIgnoreStacktraceFunction(frame.Function) {
6573 continue
6674 }
75 if skipZapFrames && isZapFrame(frame.Function) {
76 continue
77 } else {
78 skipZapFrames = false
79 }
80
6781 if i != 0 {
6882 buffer.AppendByte('\n')
6983 }
7791 }
7892
7993 return buffer.String()
94 }
95
96 func isZapFrame(function string) bool {
97 for _, prefix := range _zapStacktracePrefixes {
98 if strings.HasPrefix(function, prefix) {
99 return true
100 }
101 }
102
103 // We can't use a prefix match here since the location of the vendor
104 // directory affects the prefix. Instead we do a contains match.
105 for _, contains := range _zapStacktraceVendorContains {
106 if strings.Contains(function, contains) {
107 return true
108 }
109 }
110
111 return false
80112 }
81113
82114 func shouldIgnoreStacktraceFunction(function string) bool {
95127 func newProgramCounters(size int) *programCounters {
96128 return &programCounters{make([]uintptr, size)}
97129 }
130
131 func addPrefix(prefix string, ss ...string) []string {
132 withPrefix := make([]string, len(ss))
133 for i, s := range ss {
134 withPrefix[i] = prefix + s
135 }
136 return withPrefix
137 }
+161
-0
stacktrace_ext_test.go less more
0 // Copyright (c) 2016, 2017 Uber Technologies, Inc.
1 //
2 // Permission is hereby granted, free of charge, to any person obtaining a copy
3 // of this software and associated documentation files (the "Software"), to deal
4 // in the Software without restriction, including without limitation the rights
5 // to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
6 // copies of the Software, and to permit persons to whom the Software is
7 // furnished to do so, subject to the following conditions:
8 //
9 // The above copyright notice and this permission notice shall be included in
10 // all copies or substantial portions of the Software.
11 //
12 // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
13 // IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
14 // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
15 // AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
16 // LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
17 // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
18 // THE SOFTWARE.
19
20 package zap_test
21
22 import (
23 "bytes"
24 "io/ioutil"
25 "os"
26 "os/exec"
27 "path/filepath"
28 "runtime"
29 "strings"
30 "testing"
31
32 "go.uber.org/zap"
33 "go.uber.org/zap/zapcore"
34
35 "github.com/stretchr/testify/assert"
36 "github.com/stretchr/testify/require"
37 )
38
39 // _zapPackages are packages that we search for in the logging output to match a
40 // zap stack frame. It is different from _zapStacktracePrefixes which is only
41 // intended to match on the function name, while this is on the full output
42 // which includes filenames.
43 var _zapPackages = []string{
44 "go.uber.org/zap.",
45 "go.uber.org/zap/zapcore.",
46 }
47
48 func TestStacktraceFiltersZapLog(t *testing.T) {
49 withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) {
50 logger.Error("test log")
51 logger.Sugar().Error("sugar test log")
52
53 require.Contains(t, out.String(), "TestStacktraceFiltersZapLog", "Should not strip out non-zap import")
54 verifyNoZap(t, out.String())
55 })
56 }
57
58 func TestStacktraceFiltersZapMarshal(t *testing.T) {
59 withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) {
60 marshal := func(enc zapcore.ObjectEncoder) error {
61 logger.Warn("marshal caused warn")
62 enc.AddString("f", "v")
63 return nil
64 }
65 logger.Error("test log", zap.Object("obj", zapcore.ObjectMarshalerFunc(marshal)))
66
67 logs := out.String()
68
69 // The marshal function (which will be under the test function) should not be stripped.
70 const marshalFnPrefix = "TestStacktraceFiltersZapMarshal."
71 require.Contains(t, logs, marshalFnPrefix, "Should not strip out marshal call")
72
73 // There should be no zap stack traces before that point.
74 marshalIndex := strings.Index(logs, marshalFnPrefix)
75 verifyNoZap(t, logs[:marshalIndex])
76
77 // After that point, there should be zap stack traces - we don't want to strip out
78 // the Marshal caller information.
79 for _, fnPrefix := range _zapPackages {
80 require.Contains(t, logs[marshalIndex:], fnPrefix, "Missing zap caller stack for Marshal")
81 }
82 })
83 }
84
85 func TestStacktraceFiltersVendorZap(t *testing.T) {
86 // We need to simulate a zap as a vendor library, so we're going to create a fake GOPATH
87 // and run the above test which will contain zap in the vendor directory.
88 withGoPath(t, func(goPath string) {
89 curDir, err := os.Getwd()
90 require.NoError(t, err, "Failed to get current directory")
91
92 testDir := filepath.Join(goPath, "src/go.uber.org/zap_test/")
93 vendorDir := filepath.Join(testDir, "vendor")
94 require.NoError(t, os.MkdirAll(testDir, 0777), "Failed to create source director")
95
96 curFile := getSelfFilename(t)
97 //copyFile(t, curFile, filepath.Join(testDir, curFile))
98 setupSymlink(t, curFile, filepath.Join(testDir, curFile))
99
100 // Set up symlinks for zap, and for any test dependencies.
101 setupSymlink(t, curDir, filepath.Join(vendorDir, "go.uber.org/zap"))
102 for _, testDep := range []string{"github.com/stretchr/testify"} {
103 setupSymlink(t, filepath.Join(curDir, "vendor", testDep), filepath.Join(vendorDir, testDep))
104 }
105
106 // Now run the above test which ensures we filter out zap stacktraces, but this time
107 // zap is in a vendor
108 cmd := exec.Command("go", "test", "-v", "-run", "TestStacktraceFiltersZap")
109 cmd.Dir = testDir
110 out, err := cmd.CombinedOutput()
111 require.NoError(t, err, "Failed to run test in vendor directory, output: %s", out)
112 assert.Contains(t, string(out), "PASS")
113 })
114 }
115
116 // withLogger sets up a logger with a real encoder set up, so that any marshal functions are called.
117 // The inbuilt observer does not call Marshal for objects/arrays, which we need for some tests.
118 func withLogger(t *testing.T, fn func(logger *zap.Logger, out *bytes.Buffer)) {
119 buf := &bytes.Buffer{}
120 encoder := zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig())
121 core := zapcore.NewCore(encoder, zapcore.AddSync(buf), zapcore.DebugLevel)
122 logger := zap.New(core, zap.AddStacktrace(zap.DebugLevel))
123 fn(logger, buf)
124 }
125
126 func verifyNoZap(t *testing.T, logs string) {
127 for _, fnPrefix := range _zapPackages {
128 require.NotContains(t, logs, fnPrefix, "Should not strip out marshal call")
129 }
130 }
131
132 func withGoPath(t *testing.T, f func(goPath string)) {
133 goPath, err := ioutil.TempDir("", "gopath")
134 require.NoError(t, err, "Failed to create temporary directory for GOPATH")
135 //defer os.RemoveAll(goPath)
136
137 os.Setenv("GOPATH", goPath)
138 defer os.Setenv("GOPATH", os.Getenv("GOPATH"))
139
140 f(goPath)
141 }
142
143 func getSelfFilename(t *testing.T) string {
144 _, file, _, ok := runtime.Caller(0)
145 require.True(t, ok, "Failed to get caller information to identify local file")
146
147 return filepath.Base(file)
148 }
149
150 func setupSymlink(t *testing.T, src, dst string) {
151 // Make sure the destination directory exists.
152 os.MkdirAll(filepath.Dir(dst), 0777)
153
154 // Get absolute path of the source for the symlink, otherwise we can create a symlink
155 // that uses relative paths.
156 srcAbs, err := filepath.Abs(src)
157 require.NoError(t, err, "Failed to get absolute path")
158
159 require.NoError(t, os.Symlink(srcAbs, dst), "Failed to set up symlink")
160 }
+36
-2
stacktrace_test.go less more
3434 assert.Contains(
3535 t,
3636 lines[0],
37 "TestTakeStacktrace",
38 "Expected stacktrace to start with this test function, but top frame is %s.", lines[0],
37 "testing.",
38 "Expected stacktrace to start with the test runner (zap frames are filtered out) %s.", lines[0],
3939 )
4040 }
41
42 func TestIsZapFrame(t *testing.T) {
43 zapFrames := []string{
44 "go.uber.org/zap.Stack",
45 "go.uber.org/zap.(*SugaredLogger).log",
46 "go.uber.org/zap/zapcore.(ArrayMarshalerFunc).MarshalLogArray",
47 "github.com/uber/tchannel-go/vendor/go.uber.org/zap.Stack",
48 "github.com/uber/tchannel-go/vendor/go.uber.org/zap.(*SugaredLogger).log",
49 "github.com/uber/tchannel-go/vendor/go.uber.org/zap/zapcore.(ArrayMarshalerFunc).MarshalLogArray",
50 }
51 nonZapFrames := []string{
52 "github.com/uber/tchannel-go.NewChannel",
53 "go.uber.org/not-zap.New",
54 "go.uber.org/zapext.ctx",
55 "go.uber.org/zap_ext/ctx.New",
56 }
57
58 t.Run("zap frames", func(t *testing.T) {
59 for _, f := range zapFrames {
60 require.True(t, isZapFrame(f), f)
61 }
62 })
63 t.Run("non-zap frames", func(t *testing.T) {
64 for _, f := range nonZapFrames {
65 require.False(t, isZapFrame(f), f)
66 }
67 })
68 }
69
70 func BenchmarkTakeStacktrace(b *testing.B) {
71 for i := 0; i < b.N; i++ {
72 takeStacktrace()
73 }
74 }