log/slog: log.Fatal() reports wrong source location when both log.Lshortfile or log.Llongfile and slog with source is enabled

[ascherkus]

Go version

go version go1.21.5 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/andrew/Library/Caches/go-build'
GOENV='/Users/andrew/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/andrew/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/andrew/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.21.5/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.21.5/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.21.5'
GCCGO='gccgo'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/Users/andrew/src/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/8b/qq9znh551qv_r0lhlj8bs0hr0000gn/T/go-build2100671700=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Our applications have log.Lshortfile set and while migrating to log/slog, we noticed that in a few spots where we call log.Fatal() that the source line information points to inside the standard library as opposed to the line where the log was called.

Other package-level functions such as log.Print() report the correct source line location.

log.Llongfile exhibits the same bug.

Playground: https://go.dev/play/p/k-eOzUuhr1f

package main

import (
	"log"
	"log/slog"
	"os"
)

func main() {
	log.SetFlags(log.Lshortfile)
	slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{
		AddSource: true,
	})))
	log.Print("hello")
	log.Fatal("world")
}

What did you see happen?

When slog is enabled with source location, we see the following:

time=2009-11-10T23:00:00.000Z level=INFO source=/tmp/sandbox1731373776/prog.go:14 msg=hello
time=2009-11-10T23:00:00.000Z level=INFO source=/usr/local/go-faketime/src/log/log.go:412 msg=world

What did you expect to see?

When slog is disabled, we see the following:

prog.go:12: hello
prog.go:13: world

I would expect with slog enabled, we should see the following:

time=2009-11-10T23:00:00.000Z level=INFO source=/tmp/sandbox1731373776/prog.go:14 msg=hello
time=2009-11-10T23:00:00.000Z level=INFO source=/tmp/sandbox1731373776/prog.go:15 msg=world

[dmitshur]

CC @robpike.

[seankhliao]

cc @jba for slog

[jba]

This is a slog bug. Changing the title.

[op]

Ran into this too. Here's a dirty workaround;

type pcHandler struct {
	slog.Handler
	skip int
}

func (h pcHandler) Handle(ctx context.Context, r slog.Record) error {
	var pcs [2]uintptr
	n := runtime.Callers(h.skip, pcs[:])
	frames := runtime.CallersFrames(pcs[:n])
	frame, _ := frames.Next()
	if frame.Function == "log.Fatal" {
		r.PC = pcs[1]
	}
	return h.Handler.Handle(ctx, r)
}

[gopherbot]

Change https://go.dev/cl/588335 mentions this issue: log/slog: use consistent call depth for all output