runtime: `TestCgoCCodeSIGPROF` failures

[mknyszek]

#!watchflakes
post <- test == "TestCgoCCodeSIGPROF" && date < "2023-08-08"

2023-08-07 19:31 linux-386-longtest go@d367ec6a runtime.TestCgoCCodeSIGPROF (log)
2023-08-07 19:31 linux-arm64-longtest go@aca65771 runtime.TestCgoCCodeSIGPROF (log)
2023-08-07 19:31 linux-amd64-longtest go@d367ec6a runtime.TestCgoCCodeSIGPROF (log)
2023-08-07 19:31 linux-amd64-longtest go@aca65771 runtime.TestCgoCCodeSIGPROF (log)
2023-08-07 21:16 linux-386-longtest go@008ab9ad runtime.TestCgoCCodeSIGPROF (log)
2023-08-07 21:16 darwin-amd64-longtest go@008ab9ad runtime.TestCgoCCodeSIGPROF (log)

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- test == "TestCgoCCodeSIGPROF"

2023-08-07 19:31 linux-386-longtest go@d367ec6a runtime.TestCgoCCodeSIGPROF (log)

--- FAIL: TestCgoCCodeSIGPROF (0.59s)
    crash_cgo_test.go:217: /workdir/tmp/go-build2217381702/testprogcgo.exe CgoCCodeSIGPROF: exit status 2
    crash_cgo_test.go:220: expected "OK\n" got runtime: pcdata is 212 and 6 locals stack map entries for runtime.cgocallbackg (targetpc=0x804ddae)
        fatal error: bad symbol table

        runtime stack:
        runtime.throw({0x81aa1ba, 0x10})
        	/workdir/go/src/runtime/panic.go:859 +0x4d fp=0xff9d074c sp=0xff9d0738 pc=0x808560d
        runtime.(*stkframe).getStackMap(0xff9d0850, 0xff9d0990, 0x1)
        	/workdir/go/src/runtime/stkframe.go:202 +0x5e2 fp=0xff9d07b8 sp=0xff9d074c pc=0x80a20f2
        runtime.adjustframe(0xff9d0850, 0xff9d0984)
        	/workdir/go/src/runtime/stack.go:679 +0x57 fp=0xff9d0834 sp=0xff9d07b8 pc=0x809fd47
        runtime.copystack(0xa007100, 0x800)
        	/workdir/go/src/runtime/stack.go:932 +0x2d5 fp=0xff9d0aa8 sp=0xff9d0834 pc=0x80a0435
        runtime.newstack()
        	/workdir/go/src/runtime/stack.go:1113 +0x46f fp=0xff9d0b80 sp=0xff9d0aa8 pc=0x80a09df
        runtime.morestack()
        	/workdir/go/src/runtime/asm_386.s:453 +0x7c fp=0xff9d0b84 sp=0xff9d0b80 pc=0x80ba7ec

2023-08-07 19:31 linux-amd64-longtest go@d367ec6a runtime.TestCgoCCodeSIGPROF (log)

--- FAIL: TestCgoCCodeSIGPROF (0.57s)
    crash_cgo_test.go:217: /workdir/tmp/go-build3951388949/testprogcgo.exe CgoCCodeSIGPROF: exit status 2
    crash_cgo_test.go:220: expected "OK\n" got runtime: pcdata is 32 and 2 args stack map entries for runtime.cgocallbackg (targetpc=0x475608)
        fatal error: bad symbol table

        runtime stack:
        runtime.throw({0x56e6e2?, 0x2?})
        	/workdir/go/src/runtime/panic.go:859 +0x5c fp=0x7ffe49afbd08 sp=0x7ffe49afbcd8 pc=0x43bcdc
        runtime.(*stkframe).getStackMap(0x7ffe49afbeb8, 0x7ffe49afc0b8?, 0x1?)
        	/workdir/go/src/runtime/stkframe.go:227 +0x43b fp=0x7ffe49afbdf0 sp=0x7ffe49afbd08 pc=0x45893b
        runtime.adjustframe(0x7ffe49afbeb8, 0x7ffe49afc0a0)
        	/workdir/go/src/runtime/stack.go:679 +0x9b fp=0x7ffe49afbe80 sp=0x7ffe49afbdf0 pc=0x4567bb
        runtime.copystack(0xc000007d40, 0x800?)
        	/workdir/go/src/runtime/stack.go:932 +0x325 fp=0x7ffe49afc278 sp=0x7ffe49afbe80 pc=0x456fa5
        runtime.newstack()
        	/workdir/go/src/runtime/stack.go:1113 +0x47f fp=0x7ffe49afc428 sp=0x7ffe49afc278 pc=0x45757f
        runtime.morestack()
        	/workdir/go/src/runtime/asm_amd64.s:593 +0x8f fp=0x7ffe49afc430 sp=0x7ffe49afc428 pc=0x47132f

2023-08-07 19:31 linux-amd64-longtest go@aca65771 runtime.TestCgoCCodeSIGPROF (log)

--- FAIL: TestCgoCCodeSIGPROF (0.92s)
    crash_cgo_test.go:217: /workdir/tmp/go-build249561495/testprogcgo.exe CgoCCodeSIGPROF: exit status 2
    crash_cgo_test.go:220: expected "OK\n" got runtime: g 35: unexpected return pc for main._Cfunc_CallGoNop called from 0xc0000a5790
        stack: frame={sp:0xc0000a5768, fp:0xc0000a5778} stack=[0xc0000a5000,0xc0000a5800)
        0x000000c0000a5668:  0x0000000000000000  0x0000000000000000 
        0x000000c0000a5678:  0x0000000000000000  0x0000000000000000 
        0x000000c0000a5688:  0x000000000040686b <runtime.cgocall+0x000000000000004b>  0x0000000000000000 
        0x000000c0000a5698:  0x000000c0000a5730  0x000000c000186680 
        0x000000c0000a56a8:  0x000000c000060b00  0x00000000005270c0 <_cgoexp_e2caf0c5ce4d_GoNop+0x0000000000000000> 
        0x000000c0000a56b8:  0x00007f6f0ab73dd7  0x000000c0000a56e8 
...
        fatal error: unknown caller pc

        runtime stack:
        runtime.throw({0x56ebab?, 0xc0000a5800?})
        	/workdir/go/src/runtime/panic.go:859 +0x5c fp=0x7f6f0ab73a38 sp=0x7f6f0ab73a08 pc=0x43bc9c
        runtime.(*unwinder).next(0x7f6f0ab73ae8)
        	/workdir/go/src/runtime/traceback.go:462 +0x254 fp=0x7f6f0ab73ab0 sp=0x7f6f0ab73a38 pc=0x463c34
        runtime.copystack(0xc000186680, 0x800?)
        	/workdir/go/src/runtime/stack.go:930 +0x314 fp=0x7f6f0ab73ba8 sp=0x7f6f0ab73ab0 pc=0x456f54
        runtime.newstack()
        	/workdir/go/src/runtime/stack.go:1112 +0x47f fp=0x7f6f0ab73d58 sp=0x7f6f0ab73ba8 pc=0x45751f
        runtime.morestack()
        	/workdir/go/src/runtime/asm_amd64.s:593 +0x8f fp=0x7f6f0ab73d60 sp=0x7f6f0ab73d58 pc=0x47112f

2023-08-07 19:31 linux-arm64-longtest go@aca65771 runtime.TestCgoCCodeSIGPROF (log)

--- FAIL: TestCgoCCodeSIGPROF (0.28s)
    crash_cgo_test.go:217: /tmp/workdir/tmp/go-build2962622675/testprogcgo.exe CgoCCodeSIGPROF: exit status 2
    crash_cgo_test.go:220: expected "OK\n" got runtime: g6: frame.sp=0x4000284782 top=0x40002847d0
        	stack=[0x4000284000-0x4000284800
        fatal error: traceback did not unwind completely

        runtime stack:
        runtime.throw({0x572985?, 0x1?})
        	/tmp/workdir/go/src/runtime/panic.go:859 +0x40 fp=0xf8d5df7fb400 sp=0xf8d5df7fb3d0 pc=0x43dc00
        runtime.(*unwinder).finishInternal(0xf8d5df7fb518?)
        	/tmp/workdir/go/src/runtime/traceback.go:558 +0x138 fp=0xf8d5df7fb440 sp=0xf8d5df7fb400 pc=0x468c98
        runtime.(*unwinder).next(0xf8d5df7fb518?)
        	/tmp/workdir/go/src/runtime/traceback.go:439 +0x2c8 fp=0xf8d5df7fb4d0 sp=0xf8d5df7fb440 pc=0x468aa8
        runtime.copystack(0x4000003d40, 0x800)
        	/tmp/workdir/go/src/runtime/stack.go:930 +0x2fc fp=0xf8d5df7fb5d0 sp=0xf8d5df7fb4d0 pc=0x45b5bc
        runtime.newstack()
        	/tmp/workdir/go/src/runtime/stack.go:1112 +0x384 fp=0xf8d5df7fb780 sp=0xf8d5df7fb5d0 pc=0x45ba84
        runtime.morestack()
        	/tmp/workdir/go/src/runtime/asm_arm64.s:316 +0x70 fp=0xf8d5df7fb780 sp=0xf8d5df7fb780 pc=0x476ab0

2023-08-07 21:16 darwin-amd64-longtest go@008ab9ad runtime.TestCgoCCodeSIGPROF (log)

--- FAIL: TestCgoCCodeSIGPROF (0.51s)
    crash_cgo_test.go:217: /tmp/buildlet/tmp/go-build2813057027/testprogcgo.exe CgoCCodeSIGPROF: exit status 2
    crash_cgo_test.go:220: expected "OK\n" got runtime: pcdata is 32 and 2 locals stack map entries for main._Cfunc_CallGoNop (targetpc=0x10e37df7e)
        fatal error: bad symbol table

        runtime stack:
        runtime.throw({0x10e38cc1e?, 0x2?})
        	/tmp/buildlet/go/src/runtime/panic.go:859 +0x5c fp=0x70000a8d3a18 sp=0x70000a8d39e8 pc=0x10e2a023c
        runtime.(*stkframe).getStackMap(0x70000a8d3bb8, 0x1?)
        	/tmp/buildlet/go/src/runtime/stkframe.go:202 +0x5bb fp=0x70000a8d3af0 sp=0x70000a8d3a18 pc=0x10e2bcf3b
        runtime.adjustframe(0x70000a8d3bb8, 0x70000a8d3c20)
        	/tmp/buildlet/go/src/runtime/stack.go:678 +0x92 fp=0x70000a8d3b80 sp=0x70000a8d3af0 pc=0x10e2bac52
        runtime.copystack(0xc000102b60, 0x800?)
        	/tmp/buildlet/go/src/runtime/stack.go:931 +0x30a fp=0x70000a8d3c78 sp=0x70000a8d3b80 pc=0x10e2bb42a
        runtime.newstack()
        	/tmp/buildlet/go/src/runtime/stack.go:1112 +0x47f fp=0x70000a8d3e28 sp=0x70000a8d3c78 pc=0x10e2bb9ff
        runtime.morestack()
        	/tmp/buildlet/go/src/runtime/asm_amd64.s:593 +0x8f fp=0x70000a8d3e30 sp=0x70000a8d3e28 pc=0x10e2d5daf

2023-08-07 21:16 linux-386-longtest go@008ab9ad runtime.TestCgoCCodeSIGPROF (log)

--- FAIL: TestCgoCCodeSIGPROF (0.73s)
    crash_cgo_test.go:217: /workdir/tmp/go-build80679251/testprogcgo.exe CgoCCodeSIGPROF: exit status 2
    crash_cgo_test.go:220: expected "OK\n" got runtime: g 19: unexpected return pc for runtime.cgocallbackg1.func3 called from 0x4e07d00
        stack: frame={sp:0x920e6dc, fp:0x920e6df} stack=[0x920e000,0x920e800)
        0x0920e65c:  0x00000000  0x00000000  0x00000000  0x00000000 
        0x0920e66c:  0x00000000  0x00000000  0x00000000  0x00000000 
        0x0920e67c:  0x00000000  0x00000000  0x00000000  0x00000000 
        0x0920e68c:  0x00000000  0x00000000  0x00000000  0x00000000 
        0x0920e69c:  0x00000000  0x00000000  0x00000000  0x00000000 
        0x0920e6ac:  0x00000000  0x00000000  0x00000000  0x00000000 
...
        fatal error: unknown caller pc

        runtime stack:
        runtime.throw({0x81aa6a3, 0x11})
        	/workdir/go/src/runtime/panic.go:859 +0x4d fp=0xeeec80d8 sp=0xeeec80c4 pc=0x808551d
        runtime.(*unwinder).next(0xeeec8130)
        	/workdir/go/src/runtime/traceback.go:462 +0x27d fp=0xeeec8114 sp=0xeeec80d8 pc=0x80ace7d
        runtime.copystack(0x9084300, 0x800)
        	/workdir/go/src/runtime/stack.go:930 +0x270 fp=0xeeec8188 sp=0xeeec8114 pc=0x80a0280
        runtime.newstack()
        	/workdir/go/src/runtime/stack.go:1112 +0x46f fp=0xeeec8260 sp=0xeeec8188 pc=0x80a07ff
        runtime.morestack()
        	/workdir/go/src/runtime/asm_386.s:453 +0x7c fp=0xeeec8264 sp=0xeeec8260 pc=0x80ba2cc

— watchflakes

[aclements]

Observation: These are all in mayMoreStackMove mode.

[aclements]

Also, they are almost all calling morestack from

        runtime.cgocallbackg1.func3()
        	/workdir/go/src/runtime/cgocall.go:318 +0x37 fp=0x920e6e0 sp=0x920e6dc pc=0x804e117
        runtime.cgocallbackg1(0x816e980, 0xeeec82ab, 0x0)
        	/workdir/go/src/runtime/cgocall.go:338 +0x24d fp=0x920e73c sp=0x920e6e0 pc=0x804e07d
        runtime.cgocallbackg(0x816e980, 0xeeec82ab, 0x0)
        	/workdir/go/src/runtime/cgocall.go:245 +0xef fp=0x920e774 sp=0x920e73c pc=0x804ddaf
        runtime.cgocallback(0x804dc66, 0x816f8e3, 0x920e7b4)
        	/workdir/go/src/runtime/asm_386.s:779 +0x9f fp=0x920e784 sp=0x920e774 pc=0x80bb4bf
        runtime.systemstack_switch()
        	/workdir/go/src/runtime/asm_386.s:341 fp=0x920e788 sp=0x920e784 pc=0x80ba1c0
        runtime.cgocall(0x816f8e3, 0x9044fb4)
        	/workdir/go/src/runtime/cgocall.go:175 +0x86 fp=0x920e7a0 sp=0x920e788 pc=0x804dc66
        main._Cfunc_CallGoNop()
        	_cgo_gotypes.go:155 +0x33 fp=0x920e7b4 sp=0x920e7a0 pc=0x81646c3
        main.CgoCCodeSIGPROF.func1()
        	/workdir/go/src/runtime/testdata/testprogcgo/aprof.go:44 +0x4a fp=0x920e7f0 sp=0x920e7b4 pc=0x81654fa

https://build.golang.org/log/92454d0a9eff3074e86a7705f9cf8c0e706bbd1e has this at the top of the stack instead:

        runtime.cgocallbackg1(0x5270c0, 0x7f6f0ab73dd7?, 0x0)
        	/workdir/go/src/runtime/cgocall.go:268 +0x37b fp=0xc0000a5640 sp=0xc0000a5638 pc=0x406e1b

But I would guess it's the same failure and we just failed to print the "real" top of stack in this one.

[bcmills]

The traceback did not unwind completely failure mode also appears in one of the recent failures on #62105, and one found in #55161 (comment) (for which watchflakes may file a new issue shortly).

[bcmills]

All of the non-timeout failures here and on #62105 occurred on 2023-08-07, and not after.
(It appears that this is exactly the breakage that was rolled back in https://go.dev/cl/516856?)

[aclements]

Yeah, I should have looked more closely at the commit hashes. This is exactly what was fixed by CL 516856, as @bcmills pointed out. Closing.