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/seelog@v0.0.0-20190304065841-ce4aa56b4caa/writers_formattedwriter.go 48
2 github.com/zhuzhengyang/seelog.(*dispatcher).Dispatch /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/dispatch_dispatcher.go 96
3 github.com/zhuzhengyang/seelog.(*commonLogger).processLogMsg /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/logger.go 312
4 github.com/zhuzhengyang/seelog.(*syncLogger).innerLog /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/behavior_synclogger.go 51
5 github.com/zhuzhengyang/seelog.(*commonLogger).log /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/logger.go 302
6 github.com/zhuzhengyang/seelog.(*commonLogger).debugWithCallDepth /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/logger.go 234
7 github.com/zhuzhengyang/seelog.(*commonLogger).Debug /tmp/gopath1385612752/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/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/seelog@v0.0.0-20190304065841-ce4aa56b4caa/writers_formattedwriter.go 48
2 github.com/zhuzhengyang/seelog.(*dispatcher).Dispatch /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/dispatch_dispatcher.go 96
3 github.com/zhuzhengyang/seelog.(*commonLogger).processLogMsg /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/logger.go 312
4 github.com/zhuzhengyang/seelog.(*syncLogger).innerLog /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/behavior_synclogger.go 51
5 github.com/zhuzhengyang/seelog.(*commonLogger).log /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/logger.go 302
6 github.com/zhuzhengyang/seelog.(*commonLogger).debugWithCallDepth /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/logger.go 234
7 github.com/zhuzhengyang/seelog.(*commonLogger).Debug /tmp/gopath1333955029/pkg/mod/github.com/zhuzhengyang/seelog@v0.0.0-20190304065841-ce4aa56b4caa/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

[randall77]

Bisect points to https://go-review.googlesource.com/c/go/+/650455
@amusman

[cherrymui]

Interesting. The CL above enables inlining of tail calls. We do build wrappers that contain tail calls. Perhaps before that, a wrapper can never be in an inlined frame. Now they can? And the runtime doesn't skip wrapper frames when unwinding inlined frames?

[amusman]

Previously, the wrappers were always marked with the wrapper attribute. When enabling using tail calls in such wrappers (e.g. see in https://go-review.googlesource.com/c/go/+/578235 ), this setting was removed because a tail call already means that wrapper will not be seen in an inner frame, so we can save code size on instructions added for functions marked as wrapper. Because we can now inline such tail call, it seems we may need to mark it as wrapper, e.g. something like this:

--- a/src/cmd/compile/internal/inline/interleaved/interleaved.go
+++ b/src/cmd/compile/internal/inline/interleaved/interleaved.go
@@ -311,6 +311,8 @@ func (s *inlClosureState) unparenthesize() {
                return // short circuit
        }
 
+       hasInlinedTailCalls := false
+
        var unparen func(ir.Node) ir.Node
        unparen = func(n ir.Node) ir.Node {
                if paren, ok := n.(*ir.ParenExpr); ok {
@@ -322,6 +324,7 @@ func (s *inlClosureState) unparenthesize() {
                // otherwise replace it with the inlined expression followed by a return.
                if tail, ok := n.(*ir.TailCallStmt); ok {
                        if inl, done := tail.Call.(*ir.InlinedCallExpr); done {
+                               hasInlinedTailCalls = true
                                if len(inl.ReturnVars) != 0 {
                                        ret := ir.NewReturnStmt(tail.Pos(), []ir.Node{inl})
                                        if len(inl.ReturnVars) > 1 {
@@ -337,6 +340,9 @@ func (s *inlClosureState) unparenthesize() {
                return n
        }
        ir.EditChildren(s.fn, unparen)
+       if hasInlinedTailCalls {
+               s.fn.SetWrapper()
+       }
 }
 
 // fixpoint repeatedly edits a function until it stabilizes, returning

But I'm not sure yet it's fine to assume that any caller of tail call is wrapper, maybe we can or plan to use tail calls at ir Nodes representation in some other functions?
(Also I'm going to check how it affects code size).