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

cmd/compile: deferred log prints wrong line number #24839

Closed
dc0d opened this issue Apr 13, 2018 · 7 comments
Closed

cmd/compile: deferred log prints wrong line number #24839

dc0d opened this issue Apr 13, 2018 · 7 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@dc0d
Copy link

dc0d commented Apr 13, 2018

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.

@ALTree ALTree changed the title *Logger.Println with log.Lshortfile Flag log: bad line numbers with *Logger.Println and log.Lshortfile flag Apr 13, 2018
@ALTree ALTree added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 13, 2018
@pam4
Copy link

pam4 commented Apr 13, 2018

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

dc0d commented Apr 13, 2018

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

@ianlancetaylor ianlancetaylor changed the title log: bad line numbers with *Logger.Println and log.Lshortfile flag cmd/compile: deferred log prints wrong line number Apr 13, 2018
@ianlancetaylor
Copy link
Contributor

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

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

AlexRouSg commented Apr 13, 2018

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)
}

@griesemer griesemer added this to the Go1.11 milestone Apr 16, 2018
@pam4
Copy link

pam4 commented Apr 25, 2018

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

Closing as dup.

@golang golang locked and limited conversation to collaborators Jun 30, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

7 participants