cmd/compile: deferred log prints wrong line number

[dc0d]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.10.1 linux/amd64

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="amd64"
GOBIN="/home/x2m2018/C/gobin"
GOCACHE="/home/x2m2018/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/x2m2018/C/gopath"
GORACE=""
GOROOT="/home/x2m2018/C/go"
GOTMPDIR=""
GOTOOLDIR="/home/x2m2018/C/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build020362735=/tmp/go-build -gno-record-gcc-switches"

What did you do?

*Logger.Println with log.Lshortfile flag, logs the wrong line number - Go code to reproduce this.

And the output is:

main.go 61 main.trace calling
main.go 61 main.trace calling
main.go 61 main.trace calling
main.go 58 main.call2 called
main.go 53 main.call1 called
main.go 47 main.testCustom called
NaClMain [ info  ] main.go:20: calling
NaClMain [ info  ] main.go:20: calling
NaClMain [ info  ] main.go:20: calling
NaClMain [ info  ] main.go:31: called
NaClMain [ info  ] main.go:27: called
NaClMain [ info  ] main.go:22: called

What did you expect to see?

The three lines of output which report line number 20 should be showing line number 61.

What did you see instead?

Line numbers logged by *Logger.Println are not correct.

[pam4]

See if this simpler example demonstrates the same problem:
https://play.golang.org/p/ZhkHnmq0ESg
May be related to this: #24488

EDIT: it seems that the line of the first occurrence of the method value is used, see:
https://play.golang.org/p/l2s2_gad56J

[dc0d]

@pam4 Thanks; yes, your code describes the same problem.

[ianlancetaylor]

This is interesting. Using gccgo does indeed log line 61. But using the gc compiler all the way back to 1.0.3 logs line 20.

CC @randall77 @josharian @griesemer @mdempsky

[ianlancetaylor]

Shorter test case. The first line of output should show line 19, not line 15.

package main

import (
	"log"
	"os"
)

var lg = log.New(os.Stdout, "x: ", log.Lshortfile)

func main() {
	F()
}

func F() {
	defer lg.Println(trace(lg.Println))
}

func trace(f func(v ...interface{})) interface{} {
	f("calling")
	return "called"
}

[AlexRouSg]

Even shorter test case not even using log or defer

package main

import (
	"fmt"
	"runtime"
)

type foo struct{}

func (*foo) trace() {
	_, fileName, fileLine, _ := runtime.Caller(1)
	fmt.Println(fileName, fileLine)
}

func test(f func()) {
	f()
}

func main() {
	f := foo{}
	test(f.trace)
	test(f.trace)
	test(f.trace)
}

[pam4]

This issue is definitely a duplicate of #24488.

Also the title is misleading because there is nothing specific about defer or the log package (except for the fact that the log package makes use of stack information).

The problem is that method values end up in the stack trace, even though they are not function calls.

But oddly, the method value that ends up in the stack trace is not necessarily the one that leads to the function call; please take a look at this example: https://play.golang.org/p/RKQj5JcxvJH

I would prefer method values not to end up in the stack trace at all (unless they are actually called) because some of my code depends on it.

EDIT: the unexpected frames may represent compiler generated wrapper methods, see #16723.
The traceback API should reflect the programmer's model of the stack rather than the implementation's model.

[ianlancetaylor]

Closing as dup.