runtime: autogenerated frames not being skipped in CallersFrames

[pgimalac]

Go version

go version go1.25-devel_045b5c1b 2025-05-15 22:00:16 -0700 darwin/arm64

Output of go env in your module/workspace:

AR='ar'
CC='clang'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='clang++'
GCCGO='gccgo'
GO111MODULE='auto'
GOARCH='arm64'
GOARM64='v8.0'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/Users/pierre.gimalac/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/pierre.gimalac/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/zp/m8h1x16s30g3f656sxsdt7rm0000gp/T/go-build2291899110=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/tmp/em85xHTyOnUj0GY8/go.mod'
GOMODCACHE='/Users/pierre.gimalac/go/pkg/mod'
GONOPROXY='github.com/DataDog'
GONOSUMDB='github.com/DataDog,go.ddbuild.io'
GOOS='darwin'
GOPATH='/Users/pierre.gimalac/go'
GOPRIVATE='github.com/DataDog'
GOPROXY='binaries.ddbuild.io,proxy.golang.org,direct'
GOROOT='/Users/pierre.gimalac/sdk/gotip'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/pierre.gimalac/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/pierre.gimalac/sdk/gotip/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.25-devel_045b5c1b 2025-05-15 22:00:16 -0700'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

Similar issue as #16723 (from 2016).

I'm trying to build a software I work on with gotip, to test an experimental feature, and I noticed many tests around logging were failing.
Looking into it, the root cause is that with some specific code path, runtime.CallersFrames unexpectedly returns an autogenerated frame, which makes the logger display the wrong function name for the caller.

Here is an example showing this https://go.dev/play/p/9xwoAXbmgCt?v=gotip, you can notice that when using gotip the stack trace contains an autogenerated frame (and the log line points to the wrong function), while when using Go 1.24 it's not the case.

I tried making a minimal example (in particular without going through the logger dependency), but it seems to only trigger with a very specific combination of structs, embedding, function calls, inlining, etc. For example it doesn't happen with Warn, Error, or Critical, only with Trace, Debug, or Info, I believe because the first three also build and return an error, which prevents inlining.

What did you see happen?

I use a custom io.Writer which displays its stack trace when written to, and we can see that there is an autogenerated frame when running the code in https://go.dev/play/p/9xwoAXbmgCt?v=gotip:

=== CALLERS ===
0 main.(*writer).Write /tmp/sandbox1743791452/prog.go 44
1 github.com/zhuzhengyang/seelog.(*formattedWriter).Write /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/[email protected]/writers_formattedwriter.go 48
2 github.com/zhuzhengyang/seelog.(*dispatcher).Dispatch /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/[email protected]/dispatch_dispatcher.go 96
3 github.com/zhuzhengyang/seelog.(*commonLogger).processLogMsg /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 312
4 github.com/zhuzhengyang/seelog.(*syncLogger).innerLog /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/[email protected]/behavior_synclogger.go 51
5 github.com/zhuzhengyang/seelog.(*commonLogger).log /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 302
6 github.com/zhuzhengyang/seelog.(*commonLogger).debugWithCallDepth /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 234
7 github.com/zhuzhengyang/seelog.(*commonLogger).Debug /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 200
8 github.com/zhuzhengyang/seelog.(*syncLogger).Debug <autogenerated> 1
9 main.myFunction /tmp/sandbox1743791452/prog.go 29
10 main.main /tmp/sandbox1743791452/prog.go 15
11 runtime.main /usr/local/go-faketime/src/runtime/proc.go 283
12 runtime.goexit /usr/local/go-faketime/src/runtime/asm_amd64.s 1693
=== END CALLERS ===
[DEBUG] Debug: test

With Go 1.24:

=== CALLERS ===
0 main.(*writer).Write /tmp/sandbox20610824/prog.go 44
1 github.com/zhuzhengyang/seelog.(*formattedWriter).Write /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/[email protected]/writers_formattedwriter.go 48
2 github.com/zhuzhengyang/seelog.(*dispatcher).Dispatch /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/[email protected]/dispatch_dispatcher.go 96
3 github.com/zhuzhengyang/seelog.(*commonLogger).processLogMsg /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 312
4 github.com/zhuzhengyang/seelog.(*syncLogger).innerLog /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/[email protected]/behavior_synclogger.go 51
5 github.com/zhuzhengyang/seelog.(*commonLogger).log /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 302
6 github.com/zhuzhengyang/seelog.(*commonLogger).debugWithCallDepth /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 234
7 github.com/zhuzhengyang/seelog.(*commonLogger).Debug /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/[email protected]/logger.go 200
8 main.myFunction /tmp/sandbox20610824/prog.go 29
9 main.main /tmp/sandbox20610824/prog.go 15
10 runtime.main /usr/local/go-faketime/src/runtime/proc.go 283
11 runtime.goexit /usr/local/go-faketime/src/runtime/asm_amd64.s 1700
=== END CALLERS ===
[DEBUG] myFunction: test

What did you expect to see?

Looking at #16723 and https://go-review.googlesource.com/c/go/+/45412, I would say it's a bug in Go as autogenerated stack frames are supposed to be skipped.

[gabyhelp]

Related Issues

• runtime.Caller return frame of bad function #39342 (closed)
• runtime: `Caller` can return `<autogenerated>` as filename when called from a global variable #64520
• runtime/debug: PrintStack function prints incorrect stack information in go1.21.0 #62132 (closed)
• runtime: runtime_expandFinalInlineFrame doesn't skip trailing wrappers #58288 (closed)
• Wrong frame name in error.StackFrames(), right in debug.PrintStack() #38284 (closed)
• runtime: extra stack frames in Go 1.12beta2 compared to 1.11 #29919 (closed)
• runtime: frame pointer check fails on arm64 for C-to-Go calls #59401
• runtime.Callers does not include all callers. #29526 (closed)
• runtime/pprof: block and mutex profile stacks sometimes have "gowrap" root frames #69294
• cmd/compile: Autotmp* variables causing unnecessary escape #58111 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[mknyszek]

CC @golang/runtime