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

Jump to bottom

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

Open
bcmills opened this issue Jun 15, 2021 · 4 comments
Open

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

bcmills opened this issue Jun 15, 2021 · 4 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@bcmills
Copy link
Contributor

bcmills commented Jun 15, 2021 •
edited

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 bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jun 15, 2021
@bcmills bcmills added this to the Backlog milestone Jun 15, 2021
@bcmills
Copy link
Contributor Author

bcmills commented Jun 15, 2021 •
edited

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 bcmills changed the title runtime: missing or incorrect line number for deferred call in stack trace with GOTRACEBACK=system runtime: missing or incorrect line number for deferred call in stack trace Jun 15, 2021
@bcmills
Copy link
Contributor Author

bcmills commented Jun 15, 2021

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

bcmills commented Jun 15, 2021 •
edited

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 bcmills changed the title runtime: missing or incorrect line number for deferred call in stack trace runtime: stack traces do not indicate the caller for deferred calls Jun 15, 2021
@bcmills
Copy link
Contributor Author

bcmills commented Feb 8, 2022

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.

@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jul 7, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Go Compiler / Runtime
Status: Triage Backlog
Milestone
Backlog
Development

No branches or pull requests
2 participants
@bcmills @gopherbot