runtime: stack traces do not indicate the caller for deferred calls

[bcmills]

The stack trace in https://build.golang.org/log/ee6465ff7dc022b6679688af37b7b40211d8521c seems to omit an important line number from the stack trace. It appears to be reporting a panic within a deferred function call.

The start of the call to the deferred function occurs at line 1129:

go/src/testing/testing.go

Line 1129 in 8a5a6f4

defer func() {

The parentheses that actually invoke it are at line 1233:

go/src/testing/testing.go

Line 1233 in 8a5a6f4

}()

However, neither of those lines is included in any of the frames in the stack trace:

panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0x5e2520]

goroutine 3241 [running]:
panic({0x6470a0, 0x7f5d60})
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/panic.go:1147 +0x465 fp=0xc00089f938 sp=0xc00089f860 pc=0x43bba5
testing.tRunner.func1.2({0x6470a0, 0x7f5d60})
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1192 +0x339 fp=0xc00089f9f8 sp=0xc00089f938 pc=0x4e1859
testing.tRunner.func1(0xc000291a00)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1195 +0x256 fp=0xc00089faf0 sp=0xc00089f9f8 pc=0x4e1116
runtime.call16(0x0, 0x685890, 0xc000286318, 0x8, 0x8, 0x8, 0xc00089fb40)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/asm_amd64.s:625 +0x49 fp=0xc00089fb10 sp=0xc00089faf0 pc=0x470289
runtime.reflectcallSave(0xc00089fc68, 0x685890, 0xc000286318, 0x8)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/panic.go:927 +0xb5 fp=0xc00089fb50 sp=0xc00089fb10 pc=0x43b6f5
runtime.runOpenDeferFrame(0xc0004969c0, 0xc0002862d0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/panic.go:891 +0x2bb fp=0xc00089fbd8 sp=0xc00089fb50 pc=0x43b01b
panic({0x6470a0, 0x7f5d60})
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/panic.go:1038 +0x25b fp=0xc00089fcb0 sp=0xc00089fbd8 pc=0x43b99b
runtime.panicmem(...)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/panic.go:221
runtime.sigpanic()
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/signal_unix.go:735 +0x40e fp=0xc00089fd10 sp=0xc00089fcb0 pc=0x45412e
net.TestUnixAndUnixpacketServer(0xc000291a00)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/server_test.go:191 +0xae0 fp=0xc00089ff80 sp=0xc00089fd10 pc=0x5e2520
testing.tRunner(0xc000291a00, 0x684fc0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1242 +0x102 fp=0xc00089ffd0 sp=0xc00089ff80 pc=0x4e0de2
runtime.goexit()
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc00089ffd8 sp=0xc00089ffd0 pc=0x472061
created by testing.(*T).Run
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1289 +0x3ab

[bcmills]

The non-GOTRACEBACK=system stack trace for this panic is the one found in #34611, I think.

It is also missing the frame for the actual defer call.

--- FAIL: TestUnixAndUnixpacketServer (0.00s)
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
	panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0x5de13f]

goroutine 3255 [running]:
testing.tRunner.func1.2(0x64cf60, 0x7f2d40)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1185 +0x339
testing.tRunner.func1(0xc0002a7500)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1188 +0x1b8
panic(0x64cf60, 0x7f2d40)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/panic.go:1031 +0x25b
net.TestUnixAndUnixpacketServer(0xc0002a7500)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/net/server_test.go:198 +0xadf
testing.tRunner(0xc0002a7500, 0x696ca0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1235 +0x102
created by testing.(*T).Run
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1280 +0x3ab
FAIL	net	7.608s

[bcmills]

For an illustration of why this matters, consider a user debugging a function that defers multiple calls to the same function (https://play.golang.org/p/Ws12WDC1KuI). Without the stack traces to thread the calls together, it can be much harder to figure out the actual sequence of calls that lead to the panic.

[bcmills]

Thinking about this some more...

go and defer share the property of executing the function call non-locally.
For go calls, we have created by lines in the stack trace. Maybe we should have deferred by lines too.

Perhaps:

testing.tRunner.func1
	testing/testing.go:1195
deferred by testing.tRunner
	testing/testing.go:1233
panic
	runtime/panic.go:1038
net.TestUnixAndUnixpacketServer
	net/server_test.go:191
testing.tRunner
	testing/testing.go:1235
created by testing.(*T).Run
	testing/testing.go:1280

[bcmills]

Another example in https://build.golang.org/log/1a19e22ad826bedeb5a939c6130f368f9979208a:

panic: close of closed channel

goroutine 476 [running]:
runtime.Goexit()
	C:/workdir/go/src/runtime/panic.go:482 +0x190
testing.(*common).FailNow(0x4000234820)
	C:/workdir/go/src/testing/testing.go:864 +0x48
testing.(*common).Fatalf(0x4000234820, {0x7ff6a835e0c5?, 0x0?}, {0x400033be80?, 0xeda0b3426?, 0x0?})
	C:/workdir/go/src/testing/testing.go:948 +0x64
golang.org/x/crypto/acme/autocert.TestRenewFromCacheAlreadyRenewed.func2(0x2f3c74aa43a?, {0x7ff6a83f1b28?, 0x40001e1740?})
	C:/workdir/gopath/src/golang.org/x/crypto/acme/autocert/renewal_test.go:208 +0x634
golang.org/x/crypto/acme/autocert.(*domainRenewal).renew(0x400011a680)
	C:/workdir/gopath/src/golang.org/x/crypto/acme/autocert/renewal.go:71 +0x1e0
created by time.goFunc
	C:/workdir/go/src/time/sleep.go:176 +0x3c

The top of that goroutine dump is the runtime's own call to runOpenDeferFrame:
https://cs.opensource.google/go/go/+/master:src/runtime/panic.go;l=482;drc=2580d0e08d5e9f979b943758d3c49877fb2324cb

The first frame in actual user code is here:
https://cs.opensource.google/go/x/crypto/+/master:acme/autocert/renewal_test.go;l=208;drc=198e4374d7ed0909af956c010c19ee6bae6a1bc9

But the code at that line does not match the panic message at all. The actual panic is likely from this line:
https://cs.opensource.google/go/x/crypto/+/master:acme/autocert/renewal_test.go;l=166;drc=198e4374d7ed0909af956c010c19ee6bae6a1bc9
which doesn't show up in the stack trace at all.