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

Skip runtime and some zap frames in stacktraces #311

Merged
merged 6 commits into from
Mar 7, 2017
Merged

Conversation

bufdev
Copy link
Contributor

@bufdev bufdev commented Feb 17, 2017

Remove runtime.goexit, runtime.main, and some zap frames from our stacktraces. Since we're now formatting our own traces, we also get a big performance win: nearly 5x faster and half the number of bytes allocated!

Current master:

BenchmarkStackField-4             200000              9587 ns/op             960 B/op          2 allocs/op

After this PR:

BenchmarkStackField-4             500000              2149 ns/op             448 B/op          2 allocs/op

Fixes #308.

@mention-bot
Copy link

@peter-edge, thanks for your PR! By analyzing the history of the files in this pull request, we identified @akshayjshah, @prashantv and @pravj to be potential reviewers.

Copy link
Contributor

@akshayjshah akshayjshah left a comment

Choose a reason for hiding this comment

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

Some line-level nits, but let's discuss the goal here (sorry to keep doing this to you).

I like that this change removes the runtime from our stacktraces; those frames certainly aren't very useful. I don't know if it was your intention, but rolling our own formatter instead of using runtime.Stack is also a massive performance win (especially since we're typically capturing stacktraces on every error-and-above log):

Before:

BenchmarkStackField-4   	  200000	     10541 ns/op	     961 B/op	       2 allocs/op

Now:

BenchmarkStackField-4   	 1000000	      1488 ns/op	     384 B/op	       3 allocs/op

Awesome. 💯

I'm less sold on using a static caller skip to remove zap's frames from the trace - it's just really brittle under refactoring. Tests can catch breakages, but it's a pain. I'd like to benchmark a more robust approach: we can use use strings.Contains on file to check whether we're in zap or not and skip frames until we exit the library (making sure that we keep frames from re-entry into zap further down). Thoughts?

Regarding external libraries for this:

All of Facebook's open-source Go is out, because it comes with a noxious patent clause that legal would have to review. I'd like to avoid that minefield.

go-stack seems nice, and Chris Hines is a smart dude. If it supports this use case, let's benchmark and see what the performance is like.

field_test.go Outdated
@@ -162,7 +162,7 @@ func TestFieldConstructors(t *testing.T) {
}

func TestStackField(t *testing.T) {
f := Stack("stacktrace")
f := stack("stacktrace", 0)
Copy link
Contributor

Choose a reason for hiding this comment

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

Let's continue to test the exported Stack function here, since it's verifying portions of the public contract.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Actually on second thought - I think we actually have to do the thing you said with strings.Contains, because Stack can be called in different ways, which is the problem here.

stacktrace.go Outdated
if len(buf) == 0 {
// We may have been passed a nil byte slice.
buf = make([]byte, 1024)
func takeStacktrace(buffer *buffer.Buffer, skip int) string {
Copy link
Contributor

Choose a reason for hiding this comment

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

Let's update the comment to reflect the altered function signature.

// The stacktrace should also capture its immediate caller.
traceZero := takeStacktrace(bufferpool.Get(), 0)
for _, trace := range []string{traceZero} {
// The stacktrace should also its immediate caller.
Copy link
Contributor

Choose a reason for hiding this comment

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

Missing a word here.

traceTiny := takeStacktrace(make([]byte, 1), false)
for _, trace := range []string{traceNil, traceTiny} {
// The top frame should be takeStacktrace.
assert.Contains(t, trace, "zap.takeStacktrace", "Stacktrace should contain the takeStacktrace function.")
Copy link
Contributor

Choose a reason for hiding this comment

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

We should invert this assertion in the new code, so we verify that takeStacktrace isn't included in the output.

assert.True(t, '\n' < utf8.RuneSelf, `You can't cast '\n' to a byte, stop being silly`)
assert.True(t, '\t' < utf8.RuneSelf, `You can't cast '\t' to a byte, stop being silly`)
assert.True(t, ':' < utf8.RuneSelf, `You can't cast ':' to a byte, stop being silly`)
}
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you elaborate a bit here? These are all part of the ASCII range, so they're a single byte in UTF-8 by definition.

I'd prefer not to ship this test in zap, since there's nothing we can do if it fails. If there's some zap behavior that you're worried about, let's test that directly.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ya as I said, it's kind of a silly test, but there is something we can do, we could AppendString instead of AppendByte if they weren't part of the ASCII range. Anyways ya I'll remove it

stacktrace.go Outdated
f := runtime.FuncForPC(programCounter)
name := f.Name()
// this strips everything below runtime.main
// TODO(pedge): we might want to do a better check than this
Copy link
Contributor

Choose a reason for hiding this comment

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

What's go-stack doing? Are there known cases where this check doesn't suffice?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

go-stack is doing something more intense, and I don't want to just directly copy his code for now. It also seems more expensive. https://github.com/go-stack/stack/blob/master/stack.go#L330

stacktrace.go Outdated
buf = make([]byte, 1024)
func takeStacktrace(buffer *buffer.Buffer, skip int) string {
size := 16
programCounters := make([]uintptr, size)
Copy link
Contributor

Choose a reason for hiding this comment

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

Let's pool these. They're scoped to this function, so it's an easy optimization - we'll just need a small wrapper type to avoid allocating on Put.

stacktrace.go Outdated
buffer.AppendByte('\n')
}
file, line := f.FileLine(programCounter - 1)
buffer.AppendString(f.Name())
Copy link
Contributor

Choose a reason for hiding this comment

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

We've already captured this as name. Let's re-use that instead of allocating again.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Whoops

@bufdev
Copy link
Contributor Author

bufdev commented Feb 17, 2017

On the strings.Contains, I actually disagree - I can write a test to cleanly verify the skip works properly. It just seems more proper in practice.

I looked over go-stack and it seems like with how it is implemented, it won't work for us due to performance/allocation reasons. I think we should roll our own for now, and get in touch with Chris Hines to see if we can make some changes to that library so it can work for us, because I rather use his code than maintain our own here.

@bufdev
Copy link
Contributor Author

bufdev commented Feb 17, 2017

Actually on second thought, you're right about strings.Contains - the reason the TestConfig failed was because we called Stack directly, instead of from a logging function. We should support both.

@akshayjshah
Copy link
Contributor

By all means - write a test that verifies that the behavior is correct when users call Stack directly, when a *zap.Logger auto-adds a stacktrace to an error log, and when a *zap.SugaredLogger auto-adds a stacktrace to an error log. In all cases, we want to remove zap's frames.

If we can't make this work consistently, I'd prefer to not do it.

@bufdev
Copy link
Contributor Author

bufdev commented Feb 17, 2017

I think I'm going to do strings.Contains, I think that's a safer way, you're right. Should I add a buffer.UintptrBuffer type, or am I being stupid? Really I wish we had a more generic buffer type, but alas, one of the times you miss generics...

@bufdev
Copy link
Contributor Author

bufdev commented Feb 17, 2017

Actually what the hell am I talking about, I can do []uintptr directly I think

@akshayjshah
Copy link
Contributor

akshayjshah commented Feb 17, 2017

I think you'll actually want something like

type stack struct {
  pcs []uintptr
}

and then you'll pool *stack. If you pool []uintptr directly, you'll have to allocate every time you call Pool.Put (because Put expects to take interface{} and slice headers are values). This is exactly why we have the buffers.Buffer type - we can't just pool []byte.

Russ Cox wrote a really good blog post on interfaces that dives into how all this is implemented. It explains why zap goes through all this Field nonsense - it's purely to keep values on the stack instead of casting them into interface{}.

stacktrace.go Outdated
name := f.Name()
// this strips everything below runtime.main
// TODO(pedge): we might want to do a better check than this
if name == "runtime.main" {
Copy link
Contributor

Choose a reason for hiding this comment

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

Can we find "runtime.main" program counter once, and check equality between program counters, but not between strings?
Also I assume that if "runtime.main" it is always on same index from end (just assumptions, should be verified), so it's could be better to do smth like

if len(programConters) >= mainPcIdx && programCounters[mainPcIdx] == mainPc {
    programCounters = programCounters[:mainPcIdx]
}

field.go Outdated
// 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.
field := String(key, takeStacktrace(bs[:cap(bs)], false))
field := String(key, takeStacktrace(buf, skip))
Copy link
Contributor

Choose a reason for hiding this comment

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

I think, string allocation for stack is large enough, and it could be fixed.
What about BufferType FieldType, with *bufferpool.Buffer in Field.Interface (don't allocate), that on AddTo calls ObjectEncoder.AddBinary(bufferBytes), and then returns buffer to pool?
But in that case we should document, on ObjectEccoder.AddBinary that after AddBinary bytes under slice can be modified, so ObjectEncoder should not retain reference for it. It's reasonable constraint, io.Writer have same. In zap only *MapObjectEncoder retains references for binary slices.

Copy link
Contributor

Choose a reason for hiding this comment

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

AddBinary won't work here - it's intended for opaque binary blobs (for example, you fail to unmarshal some proto3 blob and want to log it for later debugging). In JSON, binary is base64-encoded, so it won't be a readable stacktrace.

In general, I really don't want to let users push arbitrary bytes into the encoders. It's too difficult to make it encoding-agnostic.

Copy link
Contributor

Choose a reason for hiding this comment

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

Answer in #324.

field.go Outdated
@@ -187,14 +187,18 @@ func Error(err error) zapcore.Field {
// extremely expensive (relatively speaking); this function both makes an
// allocation and takes ~10 microseconds.
func Stack(key string) zapcore.Field {
return stack(key, 4)
Copy link
Contributor

@skipor skipor Feb 18, 2017

Choose a reason for hiding this comment

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

That is exported function and called outside of package too.
So skip should be 1 by default, but Logger should use its callerSkip to define caller stack frame.
Also consider add exportedStackSkip(key string, skip int) zapcore.Field, to allow caller skip some frames. It's useful in recover: skip allows set top stack frame to panic caller frame.

stacktrace.go Outdated
buffer.AppendString(f.Name())
buffer.AppendByte('\n')
buffer.AppendByte('\t')
buffer.AppendString(file)
Copy link
Contributor

Choose a reason for hiding this comment

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

What about to trim filename to $GOPATH? It makes stack more compact and readable.
Maybe not now, but in future.

Copy link
Contributor

Choose a reason for hiding this comment

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

Also possibly, it's better to make smth like StackEncoder and use wrapped and pooled []uintptr as stack representation until pass it to Encoder. That makes possible to choose stack format.
Also it's alternative to get rid of string allocation for stack: StackEncoder can directly call PrimitiveArrayEncoder.AddBinary, which is not present yet, but should, as for me.
Also, when zap.Stack called directly, but message is not logged, that allows to not encode stack at all.

@bufdev
Copy link
Contributor Author

bufdev commented Feb 20, 2017

I've uploaded a diff that addresses most of the comments, including using strings.HasPrefix instead of skipping callers. Note that tests are failing, and I want to go back to my original statement - I think we should skip callers like we were instead, and internally, use the lowercase stack(key string, skip int) function in the logging functions. I could do some hacks (ie adjusting the prefixes that are checked) for tests, but note that with how this currently operates, having tests like we have now are almost impossible to do because any test will have a prefix of go.uber.org/Zap. in the name of the functions in the stack.

Short: I'm re-advocating for skipping callers internally, and writing good tests for this. Let me know what you think.

@bufdev
Copy link
Contributor Author

bufdev commented Feb 20, 2017

Also I wish we could @ Chris Hines about this.

stacktrace.go Outdated

var (
defaultUintptrSliceSize = 128
uintptrPool = sync.Pool{
Copy link
Collaborator

Choose a reason for hiding this comment

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

use _ prefix 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.

I don't understand why we're doing this at uber - what is the value?

Copy link
Contributor

Choose a reason for hiding this comment

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

It makes it much, much clearer when you're using a global, which makes it less likely that you'll assign to it or shadow it by mistake. (Shadowing is fine, but it makes the code a bit more brittle - removing the local declaration won't break the later code, but will likely make it incorrect.)

stacktrace.go Outdated
)

var (
defaultUintptrSliceSize = 128
Copy link
Collaborator

Choose a reason for hiding this comment

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

Not a big issue since we're dealing with 4 byte values, but this is a huge call stack size. Maybe something like 32 would be more reasonable?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

That might be ok, but if we're re-using these, why not just make it larger? There might be some lower-level x86 thing I'm forgetting about but

stacktrace.go Outdated
buffer := bufferpool.Get()
programCounters := getUintptrSlice()
n := runtime.Callers(0, programCounters)
size := defaultUintptrSliceSize
Copy link
Collaborator

Choose a reason for hiding this comment

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

Don't use size here, use len(programCounters)

stacktrace.go Outdated
programCounters := getUintptrSlice()
n := runtime.Callers(0, programCounters)
size := defaultUintptrSliceSize
for n >= size {
Copy link
Collaborator

Choose a reason for hiding this comment

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

You can remove the size variable completely, and remove the runtime.Callers duplication

programCounters := getUintptrSlice()
for {
  n := runtime.Callers(0, programCounters)
  if n < len(programCounters) {
    programCounters = programCounters[:n]
    break
  }

  programCounters = make([]uintptr, len(programCounters)*2)
}

stacktrace.go Outdated
// We may have been passed a nil byte slice.
buf = make([]byte, 1024)
func takeStacktrace() string {
buffer := bufferpool.Get()
Copy link
Collaborator

Choose a reason for hiding this comment

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

the cost of defer is negligible compared to the cost of this method, so consider defer bufferpool.Put(buffer)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think it's fine like this though

Copy link
Contributor

Choose a reason for hiding this comment

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

+1 for deferring here, which you've done. Small nit: can we group the defers and the Gets, so that acquiring and releasing the resource are on adjacent lines?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done

stacktrace.go Outdated
n = runtime.Stack(buf, includeAllGoroutines)
programCounters = programCounters[:n]

i := 0
Copy link
Collaborator

Choose a reason for hiding this comment

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

instead of a separate variable i, can we check the buffer length instead?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

We can't, because of how we skip as of this PR - this variable is used for whether to add a newline or not

}
trace := takeStacktrace()
// The stacktrace should also its immediate caller.
assert.Contains(t, trace, "TestTakeStacktrace", "Stacktrace should contain the test function.")
Copy link
Collaborator

Choose a reason for hiding this comment

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

since the test is in the zap package, why does it appear in the output of takeStacktrace?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This is exactly the problem with this way of doing this, see the last comment, this is broken right now

@akshayjshah
Copy link
Contributor

I'm much more of a fan of this approach (not surprising, since I suggested it). After dealing with a frame-skipping approach to caller annotations (which have to be much faster), it's a royal pain. This will be even worse, since there are exported call sites.

One simple approach to testing this code is to make the skip prefix a global variable, and (a) assert that the preset value results in an empty stacktrace (since all frames are internal), and then (b) change the variable to match only one of the zap frames and assert that the others show up. This isn't perfect coverage, but it's enough to make me confident.

stacktrace.go Outdated
for _, programCounter := range programCounters {
f := runtime.FuncForPC(programCounter)
name := f.Name()
if strings.HasPrefix(name, "runtime.") || strings.HasPrefix(name, "go.uber.org/zap.") {
Copy link
Contributor

Choose a reason for hiding this comment

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

We should include zapcore here too; perhaps removing the trailing period?

@bufdev
Copy link
Contributor Author

bufdev commented Feb 22, 2017

Check it out now @akshayjshah

stacktrace.go Outdated
New: func() interface{} {
return make([]uintptr, 64)
},
}
Copy link
Contributor

Choose a reason for hiding this comment

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

We shouldn't directly pool []uintptr. Slices are actually values (see "Slices: The slice header" in this Go Blog post), so passing them as interface{} allocates. Since sync.Pool.Put takes an interface{}, putting a plain []uintptr back into the pool allocates, which is exactly what we're trying to avoid.

Instead, try this:

type programCounters struct {
  pcs []uintptr
}

and pool *programCounters.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done

stacktrace.go Outdated
// We may have been passed a nil byte slice.
buf = make([]byte, 1024)
func takeStacktrace() string {
buffer := bufferpool.Get()
Copy link
Contributor

Choose a reason for hiding this comment

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

+1 for deferring here, which you've done. Small nit: can we group the defers and the Gets, so that acquiring and releasing the resource are on adjacent lines?

stacktrace.go Outdated
defer _stacktraceUintptrPool.Put(programCounters)

for {
n := runtime.Callers(2, programCounters)
Copy link
Contributor

Choose a reason for hiding this comment

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

Mind leaving a comment explaining this constant to future us?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done

stacktrace.go Outdated
buffer := bufferpool.Get()
programCounters := _stacktraceUintptrPool.Get().([]uintptr)
defer bufferpool.Put(buffer)
defer _stacktraceUintptrPool.Put(programCounters)
Copy link
Contributor

Choose a reason for hiding this comment

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

Should we be resetting the length of this slice (programCounters = programCounters[:0]) before putting it back into the pool?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

There's no need to do this given how we use programCounters - we just overwrite the data in runtime.Callers and iterate up to the number of program counters put into the slice.

}

// What happens with require functions? If they completely break out of the
// function, will this lock never get unlocked?
Copy link
Contributor

Choose a reason for hiding this comment

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

Let's use defers here, which will let us continue to use require in tests.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done

logger_test.go Outdated
withStacktraceIgnorePrefixes([]string{}, func() {
assertHasStack := func(t testing.TB, obs observer.LoggedEntry) {
assert.Contains(t, obs.Entry.Stack, "zap.TestLoggerAddStacktrace", "Expected to find test function in stacktrace.")
}
Copy link
Contributor

Choose a reason for hiding this comment

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

Does this function need to be in the stacktrace-prefix-clobbering closure?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes :)

config_test.go Outdated
assert.NoError(t, err, "Couldn't read log contents from temp file.")
if err != nil {
return
}
Copy link
Contributor

Choose a reason for hiding this comment

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

I think we can use defer in the decorator and keep the require 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.

Done

field := String(key, takeStacktrace(bs[:cap(bs)], false))
bufferpool.Put(buf)
return field
return String(key, takeStacktrace())
Copy link
Contributor

Choose a reason for hiding this comment

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

Nice, much cleaner.

stacktrace.go Outdated
if len(buf) == 0 {
// We may have been passed a nil byte slice.
buf = make([]byte, 1024)
func takeStacktrace() string {
Copy link
Contributor

Choose a reason for hiding this comment

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

Consider add skip int argument here, and pass callerSkip for taking stack trace in Logger. Skip for making Stack Field from outside of package is constant.
Skipping "go.uber.org/zap" prefixed frames, by passing correct 'skip' to 'runtime.Callers' seems to have much less overhead, than string compare func names.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This was discussed earlier in this PR

Copy link
Contributor

Choose a reason for hiding this comment

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

Yep. In the context of taking a stacktrace, which is more than a microsecond, there's no harm in a few cheap string comparisons. I'd very, very much like to avoid another hard-coded caller skip, since it limits our options for structuring code in zap's internals - either every user-facing API must be the same number of stack frames away from this code, or we need to plumb skip arguments everywhere.

stacktrace.go Outdated
for _, programCounter := range programCounters {
f := runtime.FuncForPC(programCounter)
name := f.Name()
if shouldIgnoreStacktraceName(name) {
Copy link
Contributor

Choose a reason for hiding this comment

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

Usually only stack suffix and prefix are trimmed, but here frames in middle of stack could be ignored. That can make stack inconsistent and hard to understand.
For example, if we pass Stringer field to logger, which String() string call cause panic, and then take Stack in defer, we will miss valuable runtime.panic frames, and zap frames that points to problem inside our stringer.
Test that illustrates example:

type corruptedStringer struct{}
func (*corruptedStringer) String() string {
	var someNilPtr *string
	return *someNilPtr
}
func TestMiddleStackFramesNotSkipped(t *testing.T) {
	l, err := zap.NewProduction()
	require.NoError(t, err)
	defer func() {
		require.NotNil(t, recover(), "should panic")
		f := zap.Stack("stacktrace")
		enc := zapcore.NewMapObjectEncoder()
		f.AddTo(enc)
		stack := enc.Fields["stacktrace"]
		t.Logf("real stack: %s\n", debug.Stack())
		assert.Contains(t, stack, "panic")
		assert.Contains(t, stack, "zap")
	}()
	l.Warn("", zap.Stringer("should panic inside zap package", &corruptedStringer{}))
}

Test run outside of zap repo (allows not to skip test frames) fails with message:

test_test.go:32: real stack: goroutine 5 [running]:
    runtime/debug.Stack(0x26b8e0, 0xc420019410, 0x2b9581)
        /usr/local/Cellar/go/1.7.4_2/libexec/src/runtime/debug/stack.go:24 +0x79
    github.com/skipor/playground.TestMiddleStackFramesNotSkipped.func1(0xc420088180)
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:32 +0x251
    panic(0x26cee0, 0xc4200120d0)
        /usr/local/Cellar/go/1.7.4_2/libexec/src/runtime/panic.go:458 +0x243
    github.com/skipor/playground.(*corruptedStringer).String(0x413898, 0x266240, 0x413898)
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:20 +0x2
    go.uber.org/zap/zapcore.Field.AddTo(0x2c0171, 0x1f, 0x17, 0x0, 0x0, 0x0, 0x266240, 0x413898, 0x3df600, 0xc4200ccb20)
        /Users/skipor/Dev/Go/src/go.uber.org/zap/zapcore/field.go:152 +0xca1
    go.uber.org/zap/zapcore.addFields(0x3df600, 0xc4200ccb20, 0xc42000cc40, 0x1, 0x1)
        /Users/skipor/Dev/Go/src/go.uber.org/zap/zapcore/field.go:178 +0x74
    go.uber.org/zap/zapcore.(*jsonEncoder).EncodeEntry(0xc4200cc9e0, 0x1, 0xed04740fa, 0x6396a92, 0x3f7160, 0x0, 0x0, 0x0, 0x0, 0x1, ...)
        /Users/skipor/Dev/Go/src/go.uber.org/zap/zapcore/json_encoder.go:312 +0x346
    go.uber.org/zap/zapcore.(*ioCore).Write(0xc4200193b0, 0x1, 0xed04740fa, 0x6396a92, 0x3f7160, 0x0, 0x0, 0x0, 0x0, 0x1, ...)
        /Users/skipor/Dev/Go/src/go.uber.org/zap/zapcore/core.go:85 +0xa9
    go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc4200a6370, 0xc42000cc40, 0x1, 0x1)
        /Users/skipor/Dev/Go/src/go.uber.org/zap/zapcore/entry.go:170 +0x147
    go.uber.org/zap.(*Logger).Warn(0xc4200107e0, 0x0, 0x0, 0xc42000cc40, 0x1, 0x1)
        /Users/skipor/Dev/Go/src/go.uber.org/zap/logger.go:169 +0x7f
    github.com/skipor/playground.TestMiddleStackFramesNotSkipped(0xc420088180)
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:36 +0x22c
    testing.tRunner(0xc420088180, 0x2dc2b8)
        /usr/local/Cellar/go/1.7.4_2/libexec/src/testing/testing.go:610 +0x81
    created by testing.(*T).Run
        /usr/local/Cellar/go/1.7.4_2/libexec/src/testing/testing.go:646 +0x2ec
		
Error Trace:	
    test_test.go:33
    asm_amd64.s:479
    panic.go:458
    panic.go:62
    sigpanic_unix.go:24
    test_test.go:20
    field.go:152
    field.go:178
    json_encoder.go:312
    core.go:85
    entry.go:170
    logger.go:169
    test_test.go:36
Error:		
    "github.com/skipor/playground.TestMiddleStackFramesNotSkipped.func1
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:28
    github.com/skipor/playground.(*corruptedStringer).String
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:19
    github.com/skipor/playground.TestMiddleStackFramesNotSkipped
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:36
    testing.tRunner
        /usr/local/Cellar/go/1.7.4_2/libexec/src/testing/testing.go:610" does not contain "panic"
    
Error Trace:	
    test_test.go:34
    asm_amd64.s:479
    panic.go:458
    panic.go:62
    sigpanic_unix.go:24
    test_test.go:20
    field.go:152
    field.go:178
    json_encoder.go:312
    core.go:85
    entry.go:170
    logger.go:169
    test_test.go:36
Error:	
    "github.com/skipor/playground.TestMiddleStackFramesNotSkipped.func1
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:28
    github.com/skipor/playground.(*corruptedStringer).String
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:19
    github.com/skipor/playground.TestMiddleStackFramesNotSkipped
        /Users/skipor/Dev/Go/src/github.com/skipor/playground/test_test.go:36
    testing.tRunner
        /usr/local/Cellar/go/1.7.4_2/libexec/src/testing/testing.go:610" does not contain "zap"

So, consider only to trim runtime stack bottom, and zap stack top.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I updated to just trim runtime.goexit and runtime.main.

Copy link
Contributor

Choose a reason for hiding this comment

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

zap frames in middle of the stack seems to be valuable too.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

We've discussed this a lot, I think I'd like to merge this as is and go from there :)

@bufdev
Copy link
Contributor Author

bufdev commented Feb 28, 2017

All comments are taken care of @akshayjshah

@bufdev
Copy link
Contributor Author

bufdev commented Mar 5, 2017

Ping

defer func() {
_stacktraceIgnorePrefixes = existing
}()
f()
Copy link
Contributor

Choose a reason for hiding this comment

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

I don't think we need either of these decorators anymore.

@akshayjshah akshayjshah changed the title Clean up stacktrace Skip runtime and some zap frames in stacktraces Mar 7, 2017
@akshayjshah akshayjshah merged commit e3f45be into master Mar 7, 2017
@akshayjshah akshayjshah deleted the stacktrace branch March 14, 2017 18:14
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

5 participants