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 different result after we upgrade go1.11.6 to go1.12.1 #31185

Closed
tomwei7 opened this issue Apr 1, 2019 · 2 comments

Comments

Projects
None yet
3 participants
@tomwei7
Copy link

commented Apr 1, 2019

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

$ go version
go version go1.12.1 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/weicheng/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/weicheng/Documents/bilibili/code/go:/Users/weicheng/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.12.1/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.12.1/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/dz/yrw4n9b168n2_w8dj8cjzdz00000gn/T/go-build579051166=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

run this demo code on go1.11.6 and go1.12.1 will get different result.

package main

import (
	"runtime"
	"strconv"
)

type Handler interface {
	Log()
}

// Handlers a bundle for hander with filter function.
type Handlers struct{}

var h Handler = Handlers{}

// funcName get func name.
func funcName(skip int) (name string) {
	if _, file, lineNo, ok := runtime.Caller(skip); ok {
		return file + ":" + strconv.Itoa(lineNo)
	}
	return "unknown:0"
}

// Log handlers logging.
func (hs Handlers) Log() {
	println(funcName(4))
}

func Error() {
	h.Log()
}

func main() {
	Error()
}

What did you expect to see?

{filepath}:35

What did you see instead?

go1.11.6 print

{filepath}:35

go1.12.1 print

/usr/local/Cellar/go/1.12.1/libexec/src/runtime/proc.go:200

looks like if skip greater than 3 will get different result.

@josharian josharian changed the title runtime.Caller return different result after we upgrade go1.11.6 to go1.12.1 runtime: Caller returns different result after we upgrade go1.11.6 to go1.12.1 Apr 1, 2019

@randall77

This comment has been minimized.

Copy link
Contributor

commented Apr 1, 2019

This is a result of eliding wrapper functions in tracebacks.

There's a wrapper function main.(*Handlers).Log which is required for the interface call. That function used to be reported in 1.11 and is no longer reported in 1.12.

Upgrading your example to print all the skips:

package main

import (
	"fmt"
	"runtime"
	"strconv"
	"strings"
)

type Handler interface {
	Log()
}

// Handlers a bundle for hander with filter function.
type Handlers struct{}

var h Handler = Handlers{}

// funcName get func name.
func funcName(skip int) (name string) {
	for i := 0; true; i++ {
		_, file, line, ok := runtime.Caller(i) // line 22
		if !ok {
			break
		}
		fmt.Printf("%d %s:%d\n", i, file[strings.LastIndex(file, "/")+1:], line)
	}
	if _, file, lineNo, ok := runtime.Caller(skip); ok {
		return file[strings.LastIndex(file, "/")+1:] + ":" + strconv.Itoa(lineNo)
	}
	return "unknown:0"
}

// Log handlers logging.
func (hs Handlers) Log() {
	println(funcName(4)) // line 36
}

func Error() {
	h.Log() // line 40
}

func main() {
	Error() // line 44
}

If you look at all the locations reported for different skips, in 1.11 you get:

0 issue31185.go:22
1 issue31185.go:36
2 issue31185.go:40
3 issue31185.go:44
4 issue31185.go:44
5 proc.go:201
6 asm_amd64.s:1333
issue31185.go:44

Notice the duplicate :44. One of those is for the call to the wrapper function main.(*Handlers).Log and one of those is for the call from the wrapper function to the user's function main.Handlers.Log.

From the user's perspective, though, the duplicate :44 is nonsense. What called itself at line 44? There's only one call there. To avoid this confusion, we decided to remove all the wrapper functions from tracebacks because their existence is implicit - there's no callsite to point to in the user's code where wrapper calls happened.

In 1.12, you get:

0 issue31185.go:22
1 issue31185.go:36
2 issue31185.go:40
3 issue31185.go:44
4 proc.go:200
5 asm_amd64.s:1337
proc.go:200

Which correctly corresponds to the callsites present in the user's code.

@andybons andybons changed the title runtime: Caller returns different result after we upgrade go1.11.6 to go1.12.1 runtime: caller returns different result after we upgrade go1.11.6 to go1.12.1 Apr 1, 2019

@andybons

This comment has been minimized.

Copy link
Member

commented Apr 1, 2019

Thanks. This behavior change was mentioned in the release notes: https://golang.org/doc/go1.12#runtime

Closing for now given that @randall77 has provided a solution for you that takes the new behavior into account.

@andybons andybons closed this Apr 1, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.