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

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

Closed
gopherbot opened this issue Jul 2, 2013 · 13 comments
Milestone

Comments

@gopherbot
Copy link

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
Copy link
Contributor

chai2010 commented Jul 3, 2013

Comment 1:

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

@minux
Copy link
Member

minux commented Jul 3, 2013

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
Copy link
Author

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
Copy link
Member

minux commented Jul 3, 2013

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
Copy link
Author

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
Copy link
Member

minux commented Jul 3, 2013

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
Copy link
Contributor

rsc commented Jul 8, 2013

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
Copy link
Contributor

rsc commented Sep 11, 2013

Comment 8:

This issue was closed by revision fa4984d.

Status changed to Fixed.

@rsc rsc added this to the Go1.2 milestone Apr 14, 2015
@rsc rsc removed the go1.2 label Apr 14, 2015
@ohler
Copy link

ohler commented Feb 12, 2016

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
Copy link
Contributor

rsc commented Feb 12, 2016

/cc @aclements @randall77

@aclements
Copy link
Member

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

@gopherbot
Copy link
Author

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

gopherbot pushed a commit that referenced this issue Feb 16, 2016
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 <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Russ Cox <rsc@golang.org>
@gopherbot
Copy link
Author

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

gopherbot pushed a commit that referenced this issue Nov 22, 2016
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 <rsc@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
@golang golang locked and limited conversation to collaborators Nov 13, 2017
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

6 participants