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: runtime.Caller returns invalid zero frame #24108

Open
ohler opened this Issue Feb 25, 2018 · 5 comments

Comments

Projects
None yet
7 participants
@ohler

ohler commented Feb 25, 2018

What version of Go are you using (go version)?

1.10

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

playground

What did you do?

https://play.golang.org/p/GwgbEnX3_7N

What did you expect to see?

missingFunction (see the link) should be among the return values of runtime.Caller(k) for some k but is not.

What did you see instead?

runtime.Caller returns ok=true but zero values for pc, filePath, and line for the value of k where missingFunction should be.

runtime.Callers does not have this problem.

output from runtime.Caller(k) for k=0..6:

869823 /tmp/sandbox093329260/main.go 16 true main.st.M
0  0 true   <-- this looks wrong
0  0 false 
871455 /tmp/sandbox093329260/main.go 50 true main.main  <-- these duplicates are
871455 /tmp/sandbox093329260/main.go 50 true main.main  <-- also surprising
341311 /usr/local/go/src/runtime/proc.go 198 true runtime.main
562560 /usr/local/go/src/runtime/asm_amd64p32.s 968 true runtime.goexit

output from runtime.Callers/CallersFrames:

{158111 0x130e18 runtime.Callers /usr/local/go/src/runtime/extern.go 212 158016}
{870559 0x16bbd4 main.st.M /tmp/sandbox093329260/main.go 25 869760}
{871167 0x16bc6c main.missingFunction /tmp/sandbox093329260/main.go 44 871040}
{871455 0x16bcd0 main.main /tmp/sandbox093329260/main.go 50 871232}
{341311 0x13f304 runtime.main /usr/local/go/src/runtime/proc.go 198 340576}
{562560 0x14fe18 runtime.goexit /usr/local/go/src/runtime/asm_amd64p32.s 968 562560}

This is a regression in 1.10; for 1.9.2, the program prints

17381142 /Users/ohler/tmp/go-bug/foo.go 16 true main.st.M
17382754 <autogenerated> 1 true main.(*st).M
17382859 <autogenerated> 1 true main.(*wrapper).M
17382379 /Users/ohler/tmp/go-bug/foo.go 44 true main.missingFunction
17382585 /Users/ohler/tmp/go-bug/foo.go 50 true main.main
[...]
@odeke-em

This comment has been minimized.

Member

odeke-em commented Feb 26, 2018

@FiloSottile

This comment has been minimized.

Member

FiloSottile commented Apr 24, 2018

@gopherbot please open a backport tracking issue, as this is a 1.10 regression.

@gopherbot

This comment has been minimized.

gopherbot commented Apr 24, 2018

Backport issue(s) opened: #25041 (for 1.10).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

@odeke-em

This comment has been minimized.

Member

odeke-em commented Jun 15, 2018

On examining the history of the runtime.Caller edits in extern.go [1]
runtimeexterneditshistory

  1. At 0ea120a, the posted repro panics
$ go run main.go 
devel +0ea120a70c Tue Apr 18 19:56:30 2017 +0000

4717371 /home/emmanuel/Desktop/opensrc/bugs/golang/24108/main.go 24 true main.st.M
4718642 <autogenerated> 1 true main.(*st).M
4718747 <autogenerated> 1 true main.(*wrapper).M
4717275 /home/emmanuel/Desktop/opensrc/bugs/golang/24108/main.go 15 true main.missingFunction
4717145 /home/emmanuel/Desktop/opensrc/bugs/golang/24108/main.go 11 true main.main
4359668 /home/emmanuel/go/src/go.googlesource.com/go/src/runtime/proc.go 185 true runtime.main
4524096 /home/emmanuel/go/src/go.googlesource.com/go/src/runtime/asm_amd64.s 2347 true runtime.goexit
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x4402e2]

goroutine 1 [running]:
main.st.M()
	/home/emmanuel/Desktop/opensrc/bugs/golang/24108/main.go:25 +0xaf
main.(*st).M(0x533078)
	<autogenerated>:1 +0x33
main.(*wrapper).M(0xc42000e2a0)
	<autogenerated>:1 +0x3c
main.missingFunction()
	/home/emmanuel/Desktop/opensrc/bugs/golang/24108/main.go:15 +0x6c
main.main()
	/home/emmanuel/Desktop/opensrc/bugs/golang/24108/main.go:11 +0xba
exit status 2
  1. 032678e is the origin story of the current report
@aclements

This comment has been minimized.

Member

aclements commented Jun 22, 2018

I've spent a while thinking about this one now, and I'm worried we've managed to back ourselves into a corner with the skip count and how tracebacking is currently structured. The logic behind ignoring frames in CallersFrames (internally, the stackExpander) is pretty complicated. However, the skip count isn't handled by stackExpander; it's handled much earlier, in gentraceback when it's walking the stack. That's why skipping N frames is different from getting the whole traceback and then discarding the first N frames.

It's hard to make these agree. I would love to make stack unwinding internally demand-driven (not unlike CallersFrames), but right now it's all sort of inside-out. Then the unwinder wouldn't have to worry about skips at all and runtime.Caller could just apply all of the frame filtering, discard the first N frames of the filtered stream, and return the next frame. But that's a really complicated change.

As a stop-gap, it may be possible to keep runtime.Caller efficient in the common case of small skip values by unwinding some of the stack without any skip and taking the Nth frame if there is one. If it turns out we didn't unwind enough of the stack, just unwind it again with a larger buffer. We could keep small unwinds on the stack and only heap-allocate for large skip values, which should be incredible rare.

The exact same problem affects runtime.Callers' skip count, and I think the solution there would be roughly the same.

@ianlancetaylor ianlancetaylor modified the milestones: Go1.11, Go1.12 Jul 10, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment