runtime: unexpected return pc on windows-386-2016

[prattmic]

#!watchflakes
post <- `unexpected return pc` && builder == "windows-386-2016"

2023-02-09T21:13:56-da47cd6/windows-386-2016

runtime: g 35: unexpected return pc for os.MkdirTemp called from 0x0
stack: frame={sp:0xa8e7e08, fp:0xa8e7ebc} stack=[0xa8e6000,0xa8e8000)
0x0a8e7d88:  0x00000031  0x00000000  0x013d4d20  0x00000000 
0x0a8e7d98:  0x00000000  0x0a54eff0  0x00000000  0x00000000 
0x0a8e7da8:  0x00000000  0x00000000  0x0a54f000  0x01528b30 
0x0a8e7db8:  0x00000000  0x013d4d20  0x01528b30  0x00000000 
0x0a8e7dc8:  0x00000000  0x00000000  0x00000000  0x0128ffae <runtime.sigpanic+0x000001ee> 
0x0a8e7dd8:  0x013d4d20  0x01528b30  0x00000000  0x00000000 
0x0a8e7de8:  0x0a54eff0  0x00000000  0x00000000  0x00000000 
0x0a8e7df8:  0x012ef118 <os.prefixAndSuffix+0x00000028>  0x0140323c  0x0a606000  0x012ef266 <os.MkdirTemp+0x00000066> 
0x0a8e7e08: <0x00000020  0x00000021  0x0125ffec <runtime.gcmarknewobject+0x0000004c>  0x01d410b0 
0x0a8e7e18:  0xffffff10  0x0124c2cc <runtime.mallocgc+0x000004fc>  0x2a4c4d18  0x0a6d20c0 
0x0a8e7e28:  0x00000030  0x01d41058  0x00000002  0x0001000b 
0x0a8e7e38:  0x2a4c4d18  0x016702d8  0x2a4c4d18  0x00000030 
0x0a8e7e48:  0x0a438900  0x00000024  0x00000000  0x0131657f <strings.Map+0x0000008f> 
0x0a8e7e58:  0x00000065  0x00000065  0x0a54f1d0  0xffffffff 
0x0a8e7e68:  0x00000000  0x012b82b8 <sync.(*RWMutex).Unlock+0x00000098>  0x0a54f1d0  0x40000000 
0x0a8e7e78:  0x00000000  0x00000000  0x00000065  0x00000010 
0x0a8e7e88:  0x00000065  0x0133099f <testing.(*common).Helper+0x0000014f>  0x013d05e0  0x0a6d0020 
0x0a8e7e98:  0x00000011  0x0a6d20e8  0x00000000  0x00000000 
0x0a8e7ea8:  0x0a6d20f0  0x00000000  0x00000000  0x00000000 
0x0a8e7eb8: !0x00000000 >0x00000000  0x00000000  0x00000020 
0x0a8e7ec8:  0x00000021  0xbd96f6e5  0x01d9423d  0xbd96f6e5 
0x0a8e7ed8:  0x0152e0c0  0x00000000  0x00000000  0x01331a00 <testing.pcToName+0x00000000> 
0x0a8e7ee8:  0x0a9c4098  0x01331f34 <testing.tRunner+0x00000034>  0x0a54f268  0x013f2606 
0x0a8e7ef8:  0x0a54f298  0x014579d2  0x00000024  0x07a801b8 
0x0a8e7f08:  0xc0f3bf37  0x0077ec01  0x00000000  0x0152e0c0 
0x0a8e7f18:  0x200aa814  0xc0f3bf37  0x18da92c1  0x00000000 
0x0a8e7f28:  0x0152e0c0  0x0138c67f <os_test.TestReaddirOfFile+0x0000003f>  0x0a54f1d0  0x014579d2 
0x0a8e7f38:  0x00000024 
fatal error: unknown caller pc

runtime stack:
runtime.throw({0x13f29e0, 0x11})
	C:/workdir/go/src/runtime/panic.go:1075 +0x4d fp=0x2afef8a4 sp=0x2afef890 pc=0x127a5ed
runtime.gentraceback(0x128ffae, 0xa8e7dd8, 0x0, 0xa54eff0, 0x0, 0x0, 0x7fffffff, 0x2afefaf0, 0x0, 0x0)
	C:/workdir/go/src/runtime/traceback.go:270 +0x1a53 fp=0x2afefac4 sp=0x2afef8a4 pc=0x12a04d3
runtime.addOneOpenDeferFrame.func1()
	C:/workdir/go/src/runtime/panic.go:645 +0x95 fp=0x2afefb00 sp=0x2afefac4 pc=0x1279845
runtime.systemstack()
	C:/workdir/go/src/runtime/asm_386.s:374 +0x3d fp=0x2afefb04 sp=0x2afefb00 pc=0x12ac02d

goroutine 35 [running]:
runtime.systemstack_switch()
	C:/workdir/go/src/runtime/asm_386.s:341 fp=0xa8e7d5c sp=0xa8e7d58 pc=0x12abfe0
runtime.addOneOpenDeferFrame(0xa54eff0, 0x128ffae, 0xa8e7dd8)
	C:/workdir/go/src/runtime/panic.go:644 +0x6d fp=0xa8e7d78 sp=0xa8e7d5c pc=0x127979d
panic({0x13d4d20, 0x1528b30})
	C:/workdir/go/src/runtime/panic.go:872 +0x11a fp=0xa8e7dd8 sp=0xa8e7d78 pc=0x1279f5a
runtime.panicmem(...)
	C:/workdir/go/src/runtime/panic.go:260
runtime.sigpanic()
	C:/workdir/go/src/runtime/signal_windows.go:350 +0x1ee fp=0xa8e7dfc sp=0xa8e7dd8 pc=0x128ffae
os.prefixAndSuffix({0x20, 0x21})
	C:/workdir/go/src/os/tempfile.go:61 +0x28 fp=0xa8e7e08 sp=0xa8e7dfc pc=0x12ef118
runtime: g 35: unexpected return pc for os.MkdirTemp called from 0x0
stack: frame={sp:0xa8e7e08, fp:0xa8e7ebc} stack=[0xa8e6000,0xa8e8000)
0x0a8e7d88:  0x00000031  0x00000000  0x013d4d20  0x00000000 
0x0a8e7d98:  0x00000000  0x0a54eff0  0x00000000  0x00000000 
0x0a8e7da8:  0x00000000  0x00000000  0x0a54f000  0x01528b30 
0x0a8e7db8:  0x00000000  0x013d4d20  0x01528b30  0x00000000 
0x0a8e7dc8:  0x00000000  0x00000000  0x00000000  0x0128ffae <runtime.sigpanic+0x000001ee> 
0x0a8e7dd8:  0x013d4d20  0x01528b30  0x00000000  0x00000000 
0x0a8e7de8:  0x0a54eff0  0x00000000  0x00000000  0x00000000 
0x0a8e7df8:  0x012ef118 <os.prefixAndSuffix+0x00000028>  0x0140323c  0x0a606000  0x012ef266 <os.MkdirTemp+0x00000066> 
0x0a8e7e08: <0x00000020  0x00000021  0x0125ffec <runtime.gcmarknewobject+0x0000004c>  0x01d410b0 
0x0a8e7e18:  0xffffff10  0x0124c2cc <runtime.mallocgc+0x000004fc>  0x2a4c4d18  0x0a6d20c0 
0x0a8e7e28:  0x00000030  0x01d41058  0x00000002  0x0001000b 
0x0a8e7e38:  0x2a4c4d18  0x016702d8  0x2a4c4d18  0x00000030 
0x0a8e7e48:  0x0a438900  0x00000024  0x00000000  0x0131657f <strings.Map+0x0000008f> 
0x0a8e7e58:  0x00000065  0x00000065  0x0a54f1d0  0xffffffff 
0x0a8e7e68:  0x00000000  0x012b82b8 <sync.(*RWMutex).Unlock+0x00000098>  0x0a54f1d0  0x40000000 
0x0a8e7e78:  0x00000000  0x00000000  0x00000065  0x00000010 
0x0a8e7e88:  0x00000065  0x0133099f <testing.(*common).Helper+0x0000014f>  0x013d05e0  0x0a6d0020 
0x0a8e7e98:  0x00000011  0x0a6d20e8  0x00000000  0x00000000 
0x0a8e7ea8:  0x0a6d20f0  0x00000000  0x00000000  0x00000000 
0x0a8e7eb8: !0x00000000 >0x00000000  0x00000000  0x00000020 
0x0a8e7ec8:  0x00000021  0xbd96f6e5  0x01d9423d  0xbd96f6e5 
0x0a8e7ed8:  0x0152e0c0  0x00000000  0x00000000  0x01331a00 <testing.pcToName+0x00000000> 
0x0a8e7ee8:  0x0a9c4098  0x01331f34 <testing.tRunner+0x00000034>  0x0a54f268  0x013f2606 
0x0a8e7ef8:  0x0a54f298  0x014579d2  0x00000024  0x07a801b8 
0x0a8e7f08:  0xc0f3bf37  0x0077ec01  0x00000000  0x0152e0c0 
0x0a8e7f18:  0x200aa814  0xc0f3bf37  0x18da92c1  0x00000000 
0x0a8e7f28:  0x0152e0c0  0x0138c67f <os_test.TestReaddirOfFile+0x0000003f>  0x0a54f1d0  0x014579d2 
0x0a8e7f38:  0x00000024 
os.MkdirTemp({0x0, 0x0}, {0x20, 0x21})
	C:/workdir/go/src/os/tempfile.go:85 +0x66 fp=0xa8e7ebc sp=0xa8e7e08 pc=0x12ef266
created by testing.(*T).Run
	C:/workdir/go/src/testing/testing.go:1629 +0x417

Notes:

• This is on the brand new windows-386-2016 builder.
• GC is in mark termination based on some later goroutines waiting in gcMarkDone in assists.
• As far as I can tell, the panic in prefixAndSuffix is unexpected; none of the os tests expect panics.
• Panic is reading a string passed from MkdirTemp?

cc @mknyszek @aclements @golang/runtime @golang/windows

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- `unexpected return pc` && builder == "windows-386-2016"

2023-02-09 21:13 windows-386-2016 go@da47cd61 os.TestFTruncate (log)

runtime: g 35: unexpected return pc for os.MkdirTemp called from 0x0
stack: frame={sp:0xa8e7e08, fp:0xa8e7ebc} stack=[0xa8e6000,0xa8e8000)
0x0a8e7d88:  0x00000031  0x00000000  0x013d4d20  0x00000000 
0x0a8e7d98:  0x00000000  0x0a54eff0  0x00000000  0x00000000 
0x0a8e7da8:  0x00000000  0x00000000  0x0a54f000  0x01528b30 
0x0a8e7db8:  0x00000000  0x013d4d20  0x01528b30  0x00000000 
0x0a8e7dc8:  0x00000000  0x00000000  0x00000000  0x0128ffae <runtime.sigpanic+0x000001ee> 
0x0a8e7dd8:  0x013d4d20  0x01528b30  0x00000000  0x00000000 
0x0a8e7de8:  0x0a54eff0  0x00000000  0x00000000  0x00000000 
0x0a8e7df8:  0x012ef118 <os.prefixAndSuffix+0x00000028>  0x0140323c  0x0a606000  0x012ef266 <os.MkdirTemp+0x00000066> 
...
fatal error: unknown caller pc

runtime stack:
runtime.throw({0x13f29e0, 0x11})
	C:/workdir/go/src/runtime/panic.go:1075 +0x4d fp=0x2afef8a4 sp=0x2afef890 pc=0x127a5ed
runtime.gentraceback(0x128ffae, 0xa8e7dd8, 0x0, 0xa54eff0, 0x0, 0x0, 0x7fffffff, 0x2afefaf0, 0x0, 0x0)
	C:/workdir/go/src/runtime/traceback.go:270 +0x1a53 fp=0x2afefac4 sp=0x2afef8a4 pc=0x12a04d3
runtime.addOneOpenDeferFrame.func1()
	C:/workdir/go/src/runtime/panic.go:645 +0x95 fp=0x2afefb00 sp=0x2afefac4 pc=0x1279845
runtime.systemstack()
...
	C:/workdir/go/src/os/types_windows.go:64 +0x21d fp=0xa552eb8 sp=0xa552e54 pc=0x12efa8d
os.statHandle({0xa8847c0, 0x3f}, 0x14d0)
	C:/workdir/go/src/os/stat_windows.go:111 +0xe8 fp=0xa552ee4 sp=0xa552eb8 pc=0x12ee8b8
os.(*File).Stat(0xa6cc130)
	C:/workdir/go/src/os/stat_windows.go:19 +0x3c fp=0xa552f04 sp=0xa552ee4 pc=0x12edd3c
os_test.checkSize(0xa57a0f0, 0xa6cc130, 0x400)
	C:/workdir/go/src/os/os_test.go:1285 +0x31 fp=0xa552f58 sp=0xa552f04 pc=0x1391d41
os_test.TestFTruncate(0xa57a0f0)
	C:/workdir/go/src/os/os_test.go:1307 +0x1d5 fp=0xa552f9c sp=0xa552f58 pc=0x1392125
testing.tRunner(0xa57a0f0, 0x1402ca4)

— watchflakes

[alexbrainman]

• As far as I can tell, the panic in prefixAndSuffix is unexpected; none of the os tests expect panics.
• Panic is reading a string passed from MkdirTemp?

Panic happens on line 61

go/src/os/tempfile.go

Lines 59 to 64 in da47cd6

	func prefixAndSuffix(pattern string) (prefix, suffix string, err error) {
	for i := 0; i < len(pattern); i++ {
	if IsPathSeparator(pattern[i]) {
	return "", "", errPatternHasSeparator
	}
	}

I don't see how the panic is possible unless the problem is in runtime or GC. IsPathSeparator is a function so it cannot be nil. And pattern is a string, so if pattern is "", then we would not be inside the loop on line 61, otherwise pattern[i] should work.

Alex

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

[bcmills]

Got one of these on a release-branch.go1.19 TryBot on the windows-386-2016-oldcc builder:
https://storage.googleapis.com/go-build-log/a6efcc56/windows-386-2016-oldcc_f1adeab9.log

[mknyszek]

In triage, both of the failures look like a failure during a panic to process open-coded defers. Possibly the stack got corrupted, it tried to panic, but then the panic broke because, well, the stack is corrupted.

[mknyszek]

@prattmic notes the test is intentionally panicking, and then it fails.

Unfortunately there's not a lot to go off of here. The two failures we've seen happened in totally different places. We could try to reproduce I suppose?

[mknyszek]

We haven't seen this fail in quite a long time, and @mdempsky simplified defer processing this cycle. I wonder if that fixed it? Optimistically closing.