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: Caller returns wrong file and line if called in a deferred function during panic #26320

Open
ainar-g opened this issue Jul 10, 2018 · 6 comments
Milestone

Comments

@ainar-g
Copy link
Contributor

@ainar-g ainar-g commented Jul 10, 2018

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

Does this issue reproduce with the latest release?

Tested on b001ffb.

What did you do?

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

What did you expect to see?

    return: main.go:13
     panic: main.go:18

What did you see instead?

    return: main.go:13
     panic: asm_amd64p32.s:459

This bug was found in the discussion of #26275.

@odeke-em
Copy link
Member

@odeke-em odeke-em commented Nov 9, 2018

Kindly paging @aclements @davidlazar

@randall77
Copy link
Contributor

@randall77 randall77 commented Dec 28, 2018

Would:

     return: main.go:13
     panic: panic.go:522

Make any more sense? That's the implementation of panic in the runtime.
The parent of that frame would be main.go:18.

@ainar-g
Copy link
Contributor Author

@ainar-g ainar-g commented Dec 28, 2018

@randall77 That looks better in that there is no mention of the assembly files, but it is still not the correct behaviour the way I see it. I think there shouldn't be any difference between the printLine calls in f1 and f2.

@gopherbot
Copy link

@gopherbot gopherbot commented Dec 28, 2018

Change https://golang.org/cl/152537 mentions this issue: cmd/compile,runtime: redo mid-stack inlining tracebacks

gopherbot pushed a commit that referenced this issue Dec 28, 2018
Work involved in getting a stack trace is divided between
runtime.Callers and runtime.CallersFrames.

Before this CL, runtime.Callers returns a pc per runtime frame.
runtime.CallersFrames is responsible for expanding a runtime frame
into potentially multiple user frames.

After this CL, runtime.Callers returns a pc per user frame.
runtime.CallersFrames just maps those to user frame info.

Entries in the result of runtime.Callers are now pcs
of the calls (or of the inline marks), not of the instruction
just after the call.

Fixes #29007
Fixes #28640
Update #26320

Change-Id: I1c9567596ff73dc73271311005097a9188c3406f
Reviewed-on: https://go-review.googlesource.com/c/152537
Run-TryBot: Keith Randall <khr@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: David Chase <drchase@google.com>
@andybons andybons modified the milestones: Go1.12, Go1.13 Feb 12, 2019
@randall77
Copy link
Contributor

@randall77 randall77 commented Jun 3, 2019

The assembly function is now no longer reported. We now report the panic.go as the parent.
There's a more general question here, as evidenced by the following modification of your program:

package main

import (
	"fmt"
	"runtime"
)

func main() {
	f1()
}

func f1() {
	defer printLine("f1")
	f2()
}
func f2() {
	defer printLine("f2")
	f3()
}
func f3() {
	defer printLine("f3")
	panic(nil)
}
func printLine(s string) {
	fmt.Printf("%s:\n", s)
	var pcs [10]uintptr
	n := runtime.Callers(1, pcs[:])
	iter := runtime.CallersFrames(pcs[:n])
	for {
		f, more := iter.Next()
		fmt.Printf("  %s %s:%d\n", f.Function, f.File, f.Line)
		if !more {
			break
		}
	}
}

This currently prints:

f3:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  runtime.gopanic /usr/local/google/home/khr/sandbox/readonly/src/runtime/panic.go:619
  main.f3 /usr/local/google/home/khr/gowork/issue26320b.go:22
  main.f2 /usr/local/google/home/khr/gowork/issue26320b.go:18
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
f2:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  runtime.gopanic /usr/local/google/home/khr/sandbox/readonly/src/runtime/panic.go:619
  main.f3 /usr/local/google/home/khr/gowork/issue26320b.go:22
  main.f2 /usr/local/google/home/khr/gowork/issue26320b.go:18
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
f1:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  runtime.gopanic /usr/local/google/home/khr/sandbox/readonly/src/runtime/panic.go:619
  main.f3 /usr/local/google/home/khr/gowork/issue26320b.go:22
  main.f2 /usr/local/google/home/khr/gowork/issue26320b.go:18
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
panic: nil

goroutine 1 [running]:
main.f3()
	/usr/local/google/home/khr/gowork/issue26320b.go:22 +0x5a
main.f2()
	/usr/local/google/home/khr/gowork/issue26320b.go:18 +0x53
main.f1()
	/usr/local/google/home/khr/gowork/issue26320b.go:14 +0x53
main.main()
	/usr/local/google/home/khr/gowork/issue26320b.go:9 +0x20
exit status 2

I think the crux if the issue is that when doing the defer printLine("f1"), say, do we still want to report that gopanic, f3, and f2 are still on the stack? That is the actual state of the stack. We need to keep that actual state for when the panic unwinds all the way to the top of the goroutine and we need to print a panic stack trace (I'm assuming that everyone agrees that everything printed after goroutine 1 is correct).

But maybe for runtime.Callers and friends, we skip the frames that are already known to be dead if the defer in question recovers. Then we'd get:

f3:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  main.f3 /usr/local/google/home/khr/gowork/issue26320b.go:22
  main.f2 /usr/local/google/home/khr/gowork/issue26320b.go:18
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
f2:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  main.f2 /usr/local/google/home/khr/gowork/issue26320b.go:18
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
f1:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
panic: nil

goroutine 1 [running]:
main.f3()
	/usr/local/google/home/khr/gowork/issue26320b.go:22 +0x5a
main.f2()
	/usr/local/google/home/khr/gowork/issue26320b.go:18 +0x53
main.f1()
	/usr/local/google/home/khr/gowork/issue26320b.go:14 +0x53
main.main()
	/usr/local/google/home/khr/gowork/issue26320b.go:9 +0x20
exit status 2

I'm not sure exactly what the mechanism for that would be - we'd need to skip frames between the gopanic and the frame of the current defer (which might recover, so still might be live). And I can't wrap my head around what we'd want for recursive panics (panics in defers that were being run due to a panic).

FYI, if I comment out the panic line, we get the following output:

f3:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  main.f3 /usr/local/google/home/khr/gowork/issue26320b.go:23
  main.f2 /usr/local/google/home/khr/gowork/issue26320b.go:18
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
f2:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  main.f2 /usr/local/google/home/khr/gowork/issue26320b.go:19
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:14
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357
f1:
  main.printLine /usr/local/google/home/khr/gowork/issue26320b.go:27
  main.f1 /usr/local/google/home/khr/gowork/issue26320b.go:15
  main.main /usr/local/google/home/khr/gowork/issue26320b.go:9
  runtime.main /usr/local/google/home/khr/sandbox/readonly/src/runtime/proc.go:203
  runtime.goexit /usr/local/google/home/khr/sandbox/readonly/src/runtime/asm_amd64.s:1357

which does argue for hiding the intervening functions in the traceback.

In any case, punting to 1.14.

@randall77 randall77 modified the milestones: Go1.13, Go1.14 Jun 3, 2019
@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Jun 3, 2019

In my opinion the current output is correct. During a panic, a deferred function should see all the functions on the stack, not just the ones at which the defer occurs.

@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
7 participants
You can’t perform that action at this time.