runtime: confusing stack traces for panics in defers triggered by other panics #5832

gopherbot · 2013-07-02T15:50:14Z

by leterip:

What steps will reproduce the problem?
If possible, include a link to a program on play.golang.org.
1. In some function, defer a call to some function (Two in the example) which deadlocks
2. In the same function, call some function (One in the example) which panics.
3. Observe the output of the stack trace.

http://play.golang.org/p/jUUC4O2XQu

What is the expected output?
A stack trace that doesn't indicate that One is calling Two.

What do you see instead?
A stack trace that does indicate that One called Two.

Which compiler are you using (5g, 6g, 8g, gccgo)?
6g

Which operating system are you using?
os x/playground

Which version are you using?  (run 'go version')
go1.1.1 or go1.1 (unknown if earlier)

Please provide any additional information below.

chai2010 · 2013-07-03T06:15:52Z

Comment 1:

the lock.Lock() called twice, so cause the deadlock.

minux · 2013-07-03T08:10:57Z

Comment 2:

it is working as intended, imo.
the stack is not unwound when the panic occurs, so it appears the panicking function
is calling the deferred function directly.
also, it's very useful in practice because it pinpoints the location where the panic
occurs.
if you want more details, you could set env. var. GOTRACEBACK=2 and rerun the example.

Status changed to WorkingAsIntended.

gopherbot · 2013-07-03T12:54:57Z

Comment 3 by leterip:

#1 Yes, of course. The point of the bug is to demonstrate a misleading (imo) traceback.
The deadlock was intentional.
#2 Fair enough but a couple points to maybe help you reconsider:
1. This hit me in real life during one of my first forays into cgo after a C call.
Because the tracebacks did not have meaningful line numbers, it compounded this issue
and caused me to believe I had done something wrong with the stacks or something to get
it to call a function it obviously wasn't calling.
2. Consider http://play.golang.org/p/WfZAAeIozq
In this case, the traceback is actively misleading because what appears to be a normal
function call is actually called from a deferred function call. I can imagine pulling my
hair out for hours if a condition like this happened in a larger code base. "But I
unlocked the mutex  right above it!"
3. I asked this in #go-nuts before filing this ticket and many long timers and newcomers
both agreed I should file a bug. I believe the behavior is confusing.
I agree with you that the information is useful and I would prefer to see the panicing
goroutine (and consequently how it got there) in the traceback, but perhaps it would be
better to annotate the ways in which those functions were called in the defer/panic
case? Something like
    main.Two(0x5) (defer from main.main)
        /tmpfs/gosandbox-5213630e_c5b38c2f_e31419de_afd0d3f1_bf594733/prog.go:15 +0x28
    main.One() (panic)
        /tmpfs/gosandbox-5213630e_c5b38c2f_e31419de_afd0d3f1_bf594733/prog.go:11 +0x64
    main.main()
        /tmpfs/gosandbox-5213630e_c5b38c2f_e31419de_afd0d3f1_bf594733/prog.go:23 +0x67
adds enough information to make it immediately clear what happened while retaining the
simplicity and readability of typical stack traces. If this information is otherwise
unavailable without GOTRACEBACK=2 I feel like I am forced to run with that debug flag on
always, which isn't very nice.
Thanks.

minux · 2013-07-03T16:22:31Z

Comment 4:

ok, let's wait for others' opinions.
to make stack traces for the example in #3 (http://play.golang.org/p/WfZAAeIozq) clearer,
we can make runtime·showframe() return true for runtime.panic so that the result looks
like this:
fatal error: all goroutines are asleep - deadlock!
goroutine 1 [semacquire]:
sync.runtime_Semacquire(0x6808c)
    /Users/minux/go/src/pkg/runtime/zsema_darwin_amd64.c:165 +0x30
sync.(*Mutex).Lock(0x68088)
    /Users/minux/go/src/pkg/sync/mutex.go:66 +0xbd
main.Two(0x5)
    /Users/minux/go/src/WfZAAeIozq.go:15 +0x2a
runtime.panic(0x1fce0, 0xc21000a010)
    /Users/minux/go/src/pkg/runtime/panic.c:233 +0x103
main.One()
    /Users/minux/go/src/WfZAAeIozq.go:11 +0x66
main.main()
    /Users/minux/go/src/WfZAAeIozq.go:23 +0x69
exit status 2
and it's clear that panic occurred at in main.One(), and then defers runs.
i doubt we can make main.Two(0x5) line say [defer from main.main].

Status changed to Thinking.

gopherbot · 2013-07-03T16:24:33Z

Comment 5 by leterip:

I think something like that is great. In hindsight I think the defer part is less
useful. After a panic you can be sure that the function being called was deferred from a
caller in the stack trace.

minux · 2013-07-03T16:36:25Z

Comment 6:

FYI, the change for #4 is pretty simple, see patch in
https://golang.org/cl/10914043.
it's not yet ready for code review though, as we have got consensus on how to
best present the stack trace.

rsc · 2013-07-08T19:16:06Z

Comment 7:

I like this idea. However, we have a lot of other things that need to settle in the
runtime first. Let's remember this for later.

Labels changed: added priority-later, go1.2, removed priority-triage.

rsc · 2013-09-11T15:59:30Z

Comment 8:

This issue was closed by revision fa4984d.

Status changed to Fixed.

ohler · 2016-02-12T05:09:45Z

Did this regress? runtime.panic was renamed to runtime.gopanic, and the code still checks for the old function name, AFAICT.

Running the code from http://play.golang.org/p/WfZAAeIozq with Go 1.5.3:

$ go run test.go
fatal error: all goroutines are asleep - deadlock!

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xd62c4)
    /usr/local/go/src/runtime/sema.go:43 +0x26
sync.(*Mutex).Lock(0xd62c0)
    /usr/local/go/src/sync/mutex.go:82 +0x1c4
main.Two(0x5)
    /Users/ohler/tmp/panictrace/test.go:15 +0x23
main.One()
    /Users/ohler/tmp/panictrace/test.go:11 +0x5e
main.main()
    /Users/ohler/tmp/panictrace/test.go:23 +0x7b

and with Go 1.2:

fatal error: all goroutines are asleep - deadlock!

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0x60304)
    /private/var/folders/00/0sdwh000h01000cxqpysvccm0035qk/T/bindist922710130/go/src/pkg/runtime/sema.goc:199 +0x30
sync.(*Mutex).Lock(0x60300)
    /usr/local/go/src/pkg/sync/mutex.go:66 +0xd6
main.Two(0x5)
    /Users/ohler/tmp/panictrace/test.go:15 +0x2a
runtime.panic(0x21ea0, 0x57137)
    /usr/local/go/src/pkg/runtime/panic.c:248 +0x106
main.One()
    /Users/ohler/tmp/panictrace/test.go:11 +0x66
main.main()
    /Users/ohler/tmp/panictrace/test.go:23 +0x69

pprof also has a reference to runtime.panic that looks like it needs updating.

rsc · 2016-02-12T05:17:21Z

/cc @aclements @randall77

aclements · 2016-02-12T15:26:56Z

@ohler, you're right that this regressed. However, let's move the discussion to #13857, which is a bit broader.

gopherbot · 2016-02-12T22:00:10Z

CL https://golang.org/cl/19492 mentions this issue.

We used to include panic calls in tracebacks; however, when runtime.panic was renamed to runtime.gopanic in the conversion of the runtime to Go, we missed the special case in showframe that includes panic calls even though they're in package runtime. Fix the function name check in showframe (and, while we're here, fix the other check for "runtime.panic" in runtime/pprof). Since the "runtime.gopanic" name doesn't match what users call panic and hence isn't very user-friendly, make traceback rewrite it to just "panic". Updates #5832, #13857. Fixes #14315. Change-Id: I8059621b41ec043e63d5cfb4cbee479f47f64973 Reviewed-on: https://go-review.googlesource.com/19492 Run-TryBot: Austin Clements <[email protected]> TryBot-Result: Gobot Gobot <[email protected]> Reviewed-by: Russ Cox <[email protected]>

gopherbot · 2016-11-13T04:10:20Z

CL https://golang.org/cl/33165 mentions this issue.

The expected default behavior (no explicit GOTRACEBACK setting) is for the stack trace to start in user code, eliding unnecessary runtime frames that led up to the actual trace printing code. The idea was that the first line number printed was the one that crashed. For #5832 we added code to show 'panic' frames so that if code panics and then starts running defers and then we trace from there, the panic frame can help explain why the code seems to have made a call not present in the code. But that's only needed for panics between two different call frames, not the panic at the very top of the stack trace. Fix the fix to again elide the runtime code at the very top of the stack trace. Simple panic: package main func main() { var x []int println(x[1]) } Before this CL: panic: runtime error: index out of range goroutine 1 [running]: panic(0x1056980, 0x1091bf0) /Users/rsc/go/src/runtime/panic.go:531 +0x1cf main.main() /tmp/x.go:5 +0x5 After this CL: panic: runtime error: index out of range goroutine 1 [running]: main.main() /tmp/x.go:5 +0x5 Panic inside defer triggered by panic: package main func main() { var x []int defer func() { println(x[1]) }() println(x[2]) } Before this CL: panic: runtime error: index out of range panic: runtime error: index out of range goroutine 1 [running]: panic(0x1056aa0, 0x1091bf0) /Users/rsc/go/src/runtime/panic.go:531 +0x1cf main.main.func1(0x0, 0x0, 0x0) /tmp/y.go:6 +0x62 panic(0x1056aa0, 0x1091bf0) /Users/rsc/go/src/runtime/panic.go:489 +0x2cf main.main() /tmp/y.go:8 +0x59 The middle panic is important: it explains why main.main ended up calling main.main.func1 on a line that looks like a call to println. The top panic is noise. After this CL: panic: runtime error: index out of range panic: runtime error: index out of range goroutine 1 [running]: main.main.func1(0x0, 0x0, 0x0) /tmp/y.go:6 +0x62 panic(0x1056ac0, 0x1091bf0) /Users/rsc/go/src/runtime/panic.go:489 +0x2cf main.main() /tmp/y.go:8 +0x59 Fixes #17901. Change-Id: Id6d7c76373f7a658a537a39ca32b7dc23e1e76aa Reviewed-on: https://go-review.googlesource.com/33165 Run-TryBot: Russ Cox <[email protected]> TryBot-Result: Gobot Gobot <[email protected]> Reviewed-by: Ian Lance Taylor <[email protected]> Reviewed-by: Brad Fitzpatrick <[email protected]>

gopherbot added fixed labels Sep 11, 2013

rsc added this to the Go1.2 milestone Apr 14, 2015

rsc removed the go1.2 label Apr 14, 2015

aclements mentioned this issue Feb 12, 2016

runtime: stack trace shows confusing call sequence during panic #13857

Closed

ohler mentioned this issue Feb 12, 2016

pprof.go references "runtime.panic", which is actually called "runtime.gopanic" #14315

Closed

golang locked and limited conversation to collaborators Nov 13, 2017

gopherbot added the FrozenDueToAge label Nov 13, 2017

This issue was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: confusing stack traces for panics in defers triggered by other panics #5832

runtime: confusing stack traces for panics in defers triggered by other panics #5832

gopherbot commented Jul 2, 2013

chai2010 commented Jul 3, 2013

minux commented Jul 3, 2013

gopherbot commented Jul 3, 2013

minux commented Jul 3, 2013

gopherbot commented Jul 3, 2013

minux commented Jul 3, 2013

rsc commented Jul 8, 2013

rsc commented Sep 11, 2013

ohler commented Feb 12, 2016

rsc commented Feb 12, 2016

aclements commented Feb 12, 2016

gopherbot commented Feb 12, 2016

gopherbot commented Nov 13, 2016

runtime: confusing stack traces for panics in defers triggered by other panics #5832

runtime: confusing stack traces for panics in defers triggered by other panics #5832

Comments

gopherbot commented Jul 2, 2013

chai2010 commented Jul 3, 2013

minux commented Jul 3, 2013

gopherbot commented Jul 3, 2013

minux commented Jul 3, 2013

gopherbot commented Jul 3, 2013

minux commented Jul 3, 2013

rsc commented Jul 8, 2013

rsc commented Sep 11, 2013

ohler commented Feb 12, 2016

rsc commented Feb 12, 2016

aclements commented Feb 12, 2016

gopherbot commented Feb 12, 2016

gopherbot commented Nov 13, 2016