CC @aclements

The confusing call sequence is because it's in the process of unwinding defers. It looks like TestEntityIssuesBaseEntityQuerySequentiallyForPromulgatedURL pushed (*Cache).Close on the defer stack, so the panic in Unlock, in a sense, did call (*Cache).Close, though I agree that the presentation of this could perhaps be less confusing. Close wound up waiting on a waitgroup that never finished (and perhaps never will?), so you got stuck in the middle of unwinding the defers. Since, in principle, it was still possible to recover this panic at this point, it couldn't print out the panic.

So, given this, I'm curious if you have thoughts on what you would like to see in the stack trace that would make this clearer.

I'd expect to see some mention of "panic" in the stack trace. I'd expect to see it
called by the function that panicked (Mutex.Unlock in this case).

As it turned out, this particular case happened when there were two nested
panics - the code in newChanStore.func2 was trying to send on a closed
channel, which caused a deferred unlock to run, which panicked (because
it was unlocking an unlocked mutex), which caused the
deferred Close to run, which deadlocked because the Unlock
actually locked the mutex (see issue #13879)

Here's a simpler piece of code that illustrates the same issue (http://play.golang.org/p/r8F94naBit):

package main
import (
    "fmt"
)

var c = make(chan int)

func main() {
    close(c)
    defer halt()
    defer b()
    a()
}

func halt() {
    select{}
}

func a() {
    fmt.Println("a")
    c <- 1
}

func b() {
    fmt.Println("b")
    panic("b")
}

Something along this kind of line would be preferable (without any
thought as to whether it's possible or not!)

fatal error: all goroutines are asleep - deadlock!

goroutine 1 [select (no cases)]:
main.halt()
    /home/rog/src/tst.go:16 +0x1b
panic()
    ???
main.b()
    /home/rog/src/tst.go:26 +0x124
panic()
    ???
main.a()
    /home/rog/src/tst.go:21 +0x10c
main.main()
    /home/rog/src/tst.go:12 +0x5b

Of course it would be even better if there was some indication of
where the deferred calls were being made from... when there's a
very deep stack trace, it can be challenging trying to work out
what's actually going on.

It should be easy to show the panics in the traceback. In fact, you will see them if you run with GOTRACEBACK=system. They just don't show by default because "panic" doesn't actually exist and the runtime function that implements it gets elided because it's a runtime function. We could just special case traceback to show the runtime.gopanic frame and probably rewrite it to "runtime.panic" (or maybe even "panic") to make it really clear.

Giving more information about what frames belong to the defer and where that defer came from is a bit trickier, but I think still doable. The defer is still on the G's defer list while it's running, so most of the information is there, including the exact PC where the defer was created. We might have to record not just that the defer has started, but what SP it's running at to give traceback enough bread crumbs.

/cc @randall77 for any thoughts.

As @ohler pointed out in #5832, not printing panics is actually a regression from when we renamed the runtime panic function but didn't update some string matching in traceback. I have a CL to fix that which I'll send when the tree reopens.

I don't think this is important enough to hold up 1.6.0, but we could cherry-pick it for 1.6.1.

@rogpeppe, any thoughts on how you would like deferrals to appear in the traceback? Adding the panic calls in is straightforward, but I'm not sure what to show for deferrals (if anything). Already any call from a panic frame is a deferral. Is there more information you'd like to see? We could simply mark those as deferred calls so users don't need to know that that's what it means when panic "calls" a function. We could add a line that says where they were deferred from, perhaps printing the function name so it's easier to match up with the later frame?

I didn't mean to suggest we would do 1.6.1 just for this. But, yes, it is just a few string comparisons that need to be fixed. I've posted my CL at https://go-review.googlesource.com/19492 and will let @rsc decide if we should go ahead and push it for 1.6.

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

@aclements It would be useful to show where the defer call is made, otherwise it can be hard to find that out. ("deferred from xxxxx" where xxxxx would indicate calling function and source location of defer statement? )

@rogpeppe, I thought about that, but it's not obvious to me why that's particularly useful. If the defer is for a closure constructed at the defer point, the source location is only going to be a few lines from what it already prints in the traceback. But perhaps it's more useful when you defer something other than a closure? It looks like that's the case in your original traceback.

@aclements Is there anything left to do as part of this issue? Do you want to add more information about the location of the defer call?

@quentinmit, the important part (showing panic calls) is fixed. The defer part is a "nice to have" and may break things that try to parse the backtrace format, so maybe bump this to Go1.8Early?

@rogpeppe's program now prints:

a
b
fatal error: all goroutines are asleep - deadlock!

goroutine 1 [select (no cases)]:
main.halt()
    /tmp/x.go:16 +0x14
panic(0x84ae0, 0xc42000a310)
    /Users/rsc/go/src/runtime/panic.go:485 +0x241
main.b()
    /tmp/x.go:26 +0xdd
panic(0x8a360, 0xc42000a2f0)
    /Users/rsc/go/src/runtime/panic.go:485 +0x241
main.a()
    /tmp/x.go:21 +0xc5
main.main()
    /tmp/x.go:12 +0x6e
exit status 2

I think that's clear enough.