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.

Sign up for GitHub

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

Jump to bottom

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

Closed
ascherkus opened this issue May 14, 2024 · 5 comments
Closed

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

ascherkus opened this issue May 14, 2024 · 5 comments
Assignees
@jba
Labels
NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.25

Comments

@ascherkus
Copy link

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

CC @robpike.

@dmitshur dmitshur added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 14, 2024
@dmitshur dmitshur added this to the Backlog milestone May 14, 2024
@seankhliao
Copy link
Member

cc @jba for slog

@jba jba changed the title log: Fatal() reports wrong source location when both log.Lshortfile or log.Llongfile and slog with source is enabled log/slog: log.Fatal() reports wrong source location when both log.Lshortfile or log.Llongfile and slog with source is enabled May 15, 2024
@jba jba self-assigned this May 15, 2024
@jba
Copy link
Contributor

jba commented May 15, 2024

This is a slog bug. Changing the title.

@op
Copy link
Contributor

op commented May 22, 2024

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

@op op mentioned this issue May 24, 2024
Closed
@gopherbot
Copy link
Contributor

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

op added a commit to op/go that referenced this issue May 25, 2024
@op
log/slog: use consistent call depth for all output
149de49 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.
op added a commit to op/go that referenced this issue May 25, 2024
@op
log/slog: use consistent call depth for all output
eb20aad 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
op added a commit to op/go that referenced this issue May 25, 2024
@op
log/slog: use consistent call depth for all output
141c79e 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
op added a commit to op/go that referenced this issue May 25, 2024
@op
log/slog: use consistent call depth for all output
f86ebd9 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
op added a commit to op/go that referenced this issue May 25, 2024
@op
log/slog: use consistent call depth for all output
9c7830e 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
op added a commit to op/go that referenced this issue May 25, 2024
@op
log/slog: use consistent call depth for all output
89c79ac 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
op added a commit to op/go that referenced this issue May 28, 2024
@op
log/slog: use consistent call depth for all output
d709fb4 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
op added a commit to op/go that referenced this issue Nov 25, 2024
@op
log/slog: use consistent call depth for all output
d9193e3 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
op added a commit to op/go that referenced this issue Mar 4, 2025
@op
log/slog: use consistent call depth for all output
dba691b 
This makes all log functions keep a consistent call structure to be nice
with the handleWriter in the slog package which expects a strict level
of 4.

Fixes golang#67362.

Change-Id: Ib967c696074b1ca931f6656dd27ff1ec484233b8
@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Mar 11, 2025
@dmitshur dmitshur modified the milestones: Backlog, Go1.25 Mar 11, 2025
@gabyhelp gabyhelp mentioned this issue Mar 26, 2025
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jba jba

Labels
NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.25
Development

Successfully merging a pull request may close this issue.

log/slog: use consistent call depth for all output op/go
6 participants
@op @ascherkus @dmitshur @gopherbot @seankhliao @jba