sync/atomic: TestNilDeref flaky failure on windows-386 with runtime fatal error

[cherrymui]

#!watchflakes
default <- builder ~ `windows-386` && pkg == "sync/atomic" && test == "TestNilDeref"

sync/atomic.TestNilDeref has been flaky on windows-386 with runtime fatal error "traceback did not unwind completely"

=== RUN   TestNilDeref
runtime: g388: frame.sp=0x1922f8c top=0x1922ff0
	stack=[0x1922000-0x1923000
fatal error: traceback did not unwind completely

runtime stack:
runtime.throw({0xb0b5fb, 0x23})
	C:/b/s/w/ir/x/w/goroot/src/runtime/panic.go:1084 +0x35 fp=0x21aff5d4 sp=0x21aff5c0 pc=0x9fd5f5
runtime.(*unwinder).finishInternal(0x21aff65c)
	C:/b/s/w/ir/x/w/goroot/src/runtime/traceback.go:566 +0x16d fp=0x21aff5f4 sp=0x21aff5d4 pc=0x9ec57d
...
runtime.gopark(0xb109e4, 0x18122d0, 0x1a, 0xa, 0x0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/proc.go:435 +0xfd fp=0x1896f8c sp=0x1896f78 pc=0x9fd72d
runtime.gcBgMarkWorker(0x188e1c0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1363 +0xe2 fp=0x1896fe8 sp=0x1896f8c pc=0x9a6aa2
runtime.gcBgMarkStartWorkers.gowrap1()
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x25 fp=0x1896ff0 sp=0x1896fe8 pc=0x9a69a5
runtime.goexit({})
	C:/b/s/w/ir/x/w/goroot/src/runtime/asm_386.s:1393 +0x1 fp=0x1896ff4 sp=0x1896ff0 pc=0xa02c61
created by runtime.gcBgMarkStartWorkers in goroutine 333
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x11a

It started since today (Nov 11).

https://ci.chromium.org/ui/test/golang/sync%2Fatomic.TestNilDeref?q=V%3Abuilder%3Dgotip-windows-386-test_only+V%3Ago_branch%3Dmaster+V%3Agoarch%3D386+V%3Agoos%3Dwindows+V%3Ahost_goarch%3D386+V%3Ahost_goos%3Dwindows

All other platforms look fine. Only windows-386.

I've seen it on trybot more than once, e.g. https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-386/b8731553101305354337/test-results?sortby=&groupby=

[gabyhelp]

Related Issues

• sync/atomic: AddUint64 panic on windows/386 #5278 (closed)

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

[cherrymui]

cc @golang/runtime

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- builder ~ `windows-386` && pkg == "sync/atomic" && test == "TestNilDeref" && `traceback did not unwind completely`

2024-11-11 23:49 gotip-windows-386 go@f9159b11 sync/atomic.TestNilDeref [ABORT] (log)

=== RUN   TestNilDeref
runtime: g388: frame.sp=0x1922f8c top=0x1922ff0
	stack=[0x1922000-0x1923000
fatal error: traceback did not unwind completely

runtime stack:
runtime.throw({0xb0b5fb, 0x23})
	C:/b/s/w/ir/x/w/goroot/src/runtime/panic.go:1084 +0x35 fp=0x21aff5d4 sp=0x21aff5c0 pc=0x9fd5f5
runtime.(*unwinder).finishInternal(0x21aff65c)
	C:/b/s/w/ir/x/w/goroot/src/runtime/traceback.go:566 +0x16d fp=0x21aff5f4 sp=0x21aff5d4 pc=0x9ec57d
...
runtime.gopark(0xb109e4, 0x18122d0, 0x1a, 0xa, 0x0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/proc.go:435 +0xfd fp=0x1896f8c sp=0x1896f78 pc=0x9fd72d
runtime.gcBgMarkWorker(0x188e1c0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1363 +0xe2 fp=0x1896fe8 sp=0x1896f8c pc=0x9a6aa2
runtime.gcBgMarkStartWorkers.gowrap1()
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x25 fp=0x1896ff0 sp=0x1896fe8 pc=0x9a69a5
runtime.goexit({})
	C:/b/s/w/ir/x/w/goroot/src/runtime/asm_386.s:1393 +0x1 fp=0x1896ff4 sp=0x1896ff0 pc=0xa02c61
created by runtime.gcBgMarkStartWorkers in goroutine 333
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x11a

2024-11-11 23:50 gotip-windows-386 go@4c8ab993 sync/atomic.TestNilDeref [ABORT] (log)

=== RUN   TestNilDeref
runtime: g226: frame.sp=0x1049f8c top=0x1049ff0
	stack=[0x1049000-0x104a000
fatal error: traceback did not unwind completely

runtime stack:
runtime.throw({0x6bb5fb, 0x23})
	C:/b/s/w/ir/x/w/goroot/src/runtime/panic.go:1084 +0x35 fp=0x21c2f9d0 sp=0x21c2f9bc pc=0x5ad5f5
runtime.(*unwinder).finishInternal(0x21c2fa58)
	C:/b/s/w/ir/x/w/goroot/src/runtime/traceback.go:566 +0x16d fp=0x21c2f9f0 sp=0x21c2f9d0 pc=0x59c57d
...
runtime.gopark(0x6c09e4, 0x10123a8, 0x1a, 0xa, 0x0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/proc.go:435 +0xfd fp=0x111bf8c sp=0x111bf78 pc=0x5ad72d
runtime.gcBgMarkWorker(0x1088480)
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1363 +0xe2 fp=0x111bfe8 sp=0x111bf8c pc=0x556aa2
runtime.gcBgMarkStartWorkers.gowrap1()
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x25 fp=0x111bff0 sp=0x111bfe8 pc=0x5569a5
runtime.goexit({})
	C:/b/s/w/ir/x/w/goroot/src/runtime/asm_386.s:1393 +0x1 fp=0x111bff4 sp=0x111bff0 pc=0x5b2c61
created by runtime.gcBgMarkStartWorkers in goroutine 254
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x11a

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- builder ~ `windows-386` && pkg == "sync/atomic" && test == "TestNilDeref" && `traceback did not unwind completely`

2024-11-12 17:16 gotip-windows-386 go@c969491e sync/atomic.TestNilDeref [ABORT] (log)

=== RUN   TestNilDeref
runtime: g225: frame.sp=0x1449f8c top=0x1449ff0
	stack=[0x1449000-0x144a000
fatal error: traceback did not unwind completely

runtime stack:
runtime.throw({0x21b5fb, 0x23})
	C:/b/s/w/ir/x/w/goroot/src/runtime/panic.go:1084 +0x35 fp=0x214ff9dc sp=0x214ff9c8 pc=0x10d5f5
runtime.(*unwinder).finishInternal(0x214ffa64)
	C:/b/s/w/ir/x/w/goroot/src/runtime/traceback.go:566 +0x16d fp=0x214ff9fc sp=0x214ff9dc pc=0xfc57d
...
runtime.gopark(0x2209e4, 0x1412288, 0x1a, 0xa, 0x0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/proc.go:435 +0xfd fp=0x14a0f8c sp=0x14a0f78 pc=0x10d72d
runtime.gcBgMarkWorker(0x14663c0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1363 +0xe2 fp=0x14a0fe8 sp=0x14a0f8c pc=0xb6aa2
runtime.gcBgMarkStartWorkers.gowrap1()
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x25 fp=0x14a0ff0 sp=0x14a0fe8 pc=0xb69a5
runtime.goexit({})
	C:/b/s/w/ir/x/w/goroot/src/runtime/asm_386.s:1393 +0x1 fp=0x14a0ff4 sp=0x14a0ff0 pc=0x112c61
created by runtime.gcBgMarkStartWorkers in goroutine 330
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x11a

— watchflakes

[cherrymui]

cc @golang/windows

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- builder ~ `windows-386` && pkg == "sync/atomic" && test == "TestNilDeref" && `traceback did not unwind completely`

2024-11-12 18:35 gotip-windows-386 go@70f6c139 sync/atomic.TestNilDeref [ABORT] (log)

=== RUN   TestNilDeref
runtime: g319: frame.sp=0x1135f8c top=0x1135ff0
	stack=[0x1135000-0x1136000
fatal error: traceback did not unwind completely

runtime stack:
runtime.throw({0x2cb5fb, 0x23})
	C:/b/s/w/ir/x/w/goroot/src/runtime/panic.go:1084 +0x35 fp=0x2146fac4 sp=0x2146fab0 pc=0x1bd5f5
runtime.(*unwinder).finishInternal(0x2146fb4c)
	C:/b/s/w/ir/x/w/goroot/src/runtime/traceback.go:566 +0x16d fp=0x2146fae4 sp=0x2146fac4 pc=0x1ac57d
...
runtime.gopark(0x2d09e4, 0x1012330, 0x1a, 0xa, 0x0)
	C:/b/s/w/ir/x/w/goroot/src/runtime/proc.go:435 +0xfd fp=0x10aef8c sp=0x10aef78 pc=0x1bd72d
runtime.gcBgMarkWorker(0x1110140)
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1363 +0xe2 fp=0x10aefe8 sp=0x10aef8c pc=0x166aa2
runtime.gcBgMarkStartWorkers.gowrap1()
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x25 fp=0x10aeff0 sp=0x10aefe8 pc=0x1669a5
runtime.goexit({})
	C:/b/s/w/ir/x/w/goroot/src/runtime/asm_386.s:1393 +0x1 fp=0x10aeff4 sp=0x10aeff0 pc=0x1c2c61
created by runtime.gcBgMarkStartWorkers in goroutine 316
	C:/b/s/w/ir/x/w/goroot/src/runtime/mgc.go:1279 +0x11a

— watchflakes

[mknyszek]

The test binary seems to die abruptly. The package tests are marked as failed, but there are JSON lines missing from the full log (https://logs.chromium.org/logs/golang/buildbucket/cr-buildbucket/8731450114802979457/+/u/step/11/log/3). That's also why the test is marked as "aborted": the JSON test parser loses track of what exactly happened.

This also appears to have started yesterday based on the test history: https://ci.chromium.org/ui/test/golang/sync%2Fatomic.TestNilDeref?q=V%3Abuilder%3Dgotip-windows-386-test_only+V%3Ago_branch%3Dmaster+V%3Agoarch%3D386+V%3Agoos%3Dwindows+V%3Ahost_goarch%3D386+V%3Ahost_goos%3Dwindows. Though, there's no obvious culprit.

On Linux, we've seen immediate deaths like this end up being a bad dereference during a signal handler. Does something similar happen for crashes in the exception handler? (At least we have a stack trace here.)

CC @qmuntal who might have additional insights.

[rsc]

I've reproduced this as early as Go 1.20, with -count=10000. It is a stack unwinding / stack corruption problem.

Here is one error I saw at a later commit:

runtime: g1: frame.sp=0x94a6fa4 top=0x94a6ff0
    stack=[0x94a6000-0x94a7000
fatal error: traceback did not unwind completely

...

goroutine 1 [chan receive (scan)]:
runtime.gopark(0x3b8d20, 0x9414570, 0xe, 0x17, 0x2)
    /Users/rsc/go/src/runtime/proc.go:398 +0xfd fp=0x94a6c70 sp=0x94a6c5c pc=0x29e29d
runtime.chanrecv(0x9414540, 0x944fce3, 0x1)
    /Users/rsc/go/src/runtime/chan.go:583 +0x3ad fp=0x94a6cac sp=0x94a6c70 pc=0x265f0d
runtime.chanrecv1(0x9414540, 0x944fce3)
    /Users/rsc/go/src/runtime/chan.go:442 +0x1c fp=0x94a6cc0 sp=0x94a6cac pc=0x265b5c
testing.(*T).Run(0x94e21e0, {0x3abfbd, 0xc}, 0x3b89e0)
    /Users/rsc/go/src/testing/testing.go:1649 +0x3fa fp=0x94a6d24 sp=0x94a6cc0 pc=0x32f8ca
testing.runTests.func1(0x94e21e0)
    /Users/rsc/go/src/testing/testing.go:2054 +0x49 fp=0x94a6d48 sp=0x94a6d24 pc=0x3318e9
testing.tRunner(0x94e21e0, 0x944fdf0)
    /Users/rsc/go/src/testing/testing.go:1595 +0x11e fp=0x94a6d94 sp=0x94a6d48 pc=0x32ea7e
testing.runTests(0x94980c0, {0x4a6e20, 0x4c, 0x4c}, {0xc1c50eb92c798d2c, 0x8bb2fda08d, 0x4a8400})
    /Users/rsc/go/src/testing/testing.go:2052 +0x3a1 fp=0x94a6e04 sp=0x94a6d94 pc=0x331801
testing.(*M).Run(0xf8659c22)
    /Users/rsc/go/src/testing/testing.go:1925 +0x6b6 fp=0x94a6f68 sp=0x94a6e04 pc=0x3301e6
main.main()
    _testmain.go:201 +0x16f fp=0x94a6fa4 sp=0x94a6f68 pc=0x37cedf
sync/atomic_test.TestNilDeref.func59(0x29b680)
    /Users/rsc/go/src/sync/atomic/atomic_test.go:2526 +0x48 fp=0x94a6fb0 sp=0x94a6fa4 pc=0x378b18

...
goroutine 211 [wait for GC cycle]:
runtime.gopark(0x3b8ea4, 0x4a8764, 0x19, 0x14, 0x1)
    /Users/rsc/go/src/runtime/proc.go:398 +0xfd fp=0x94a7cb4 sp=0x94a7ca0 pc=0x29e29d
runtime.goparkunlock(...)
    /Users/rsc/go/src/runtime/proc.go:404
runtime.gcWaitOnMark(0x1dd2)
    /Users/rsc/go/src/runtime/mgc.go:529 +0x5c fp=0x94a7cc8 sp=0x94a7cb4 pc=0x2783ac
runtime.GC()
    /Users/rsc/go/src/runtime/mgc.go:472 +0x6d fp=0x94a7ce8 sp=0x94a7cc8 pc=0x27822d
sync/atomic_test.TestNilDeref.func59.1()
    /Users/rsc/go/src/sync/atomic/atomic_test.go:2522 +0x18 fp=0x94a7cf8 sp=0x94a7ce8 pc=0x37bc38
runtime.deferCallSave(0x94a7d5c, 0x3b8bec)
    /Users/rsc/go/src/runtime/panic.go:798 +0x76 fp=0x94a7d00 sp=0x94a7cf8 pc=0x29ad56
runtime.runOpenDeferFrame(0x9450090)
    /Users/rsc/go/src/runtime/panic.go:771 +0x1b0 fp=0x94a7d28 sp=0x94a7d00 pc=0x29abb0
panic({0x393320, 0x4a2028})
    /Users/rsc/go/src/runtime/panic.go:914 +0x1df fp=0x94a7d7c sp=0x94a7d28 pc=0x29af9f
runtime.panicmem(...)
    /Users/rsc/go/src/runtime/panic.go:261
runtime.sigpanic()
    /Users/rsc/go/src/runtime/signal_windows.go:364 +0x1f3 fp=0x94a7da0 sp=0x94a7d7c pc=0x2b06a3
sync/atomic.(*Int32).Load(...)
    /Users/rsc/go/src/sync/atomic/type.go:74
sync/atomic_test.TestNilDeref.func36()
    /Users/rsc/go/src/sync/atomic/atomic_test.go:2495 +0x15 fp=0x94a7dac sp=0x94a7da0 pc=0x37b725
sync/atomic_test.TestNilDeref.func59(0x94a7dc0)
    /Users/rsc/go/src/sync/atomic/atomic_test.go:2525 +0x3a fp=0x94a7db8 sp=0x94a7dac pc=0x378b0a
sync/atomic_test.TestNilDeref(0x94e22d0)
    /Users/rsc/go/src/sync/atomic/atomic_test.go:2526 +0x2f6 fp=0x94a7f98 sp=0x94a7db8 pc=0x378aa6
testing.tRunner(0x94e22d0, 0x3b89e0)
    /Users/rsc/go/src/testing/testing.go:1595 +0x11e fp=0x94a7fe4 sp=0x94a7f98 pc=0x32ea7e
testing.(*T).Run.func1()
    /Users/rsc/go/src/testing/testing.go:1648 +0x2c fp=0x94a7ff0 sp=0x94a7fe4 pc=0x32fa0c
runtime.goexit()
    /Users/rsc/go/src/runtime/asm_386.s:1363 +0x1 fp=0x94a7ff4 sp=0x94a7ff0 pc=0x2cd341
created by testing.(*T).Run in goroutine 1
    /Users/rsc/go/src/testing/testing.go:1648 +0x3db
FAIL    sync/atomic    15.498s

The panic is about not fully unwinding goroutine 1. You can see the traceback printer get it wrong too. main.main should be called from goexit, but it has been "called" from TestNilDeref.func59 instead. This suggests stack corruption near the top of goroutine 1's stack. The top of goroutine 1's stack is the bottom of goroutine 211's stack, which coincidentally (?) is the goroutine that did the nil dereference. func59 is also on that stack, but with a different caller pc (0x378b0a vs 0x378b18).

At Go 1.20, I got this error:

%  GOOS=windows GOARCH=386 go test sync/atomic -run=NilDeref -timeout=1h -count=10000
runtime: g 38: unexpected return pc for runtime.gcBgMarkWorker called from 0x0
stack: frame={sp:0x9892f94, fp:0x9892ff0} stack=[0x9892000,0x9893000)
0x09892f14:  0x00000000  0x00000000  0x0000000f  0x00000010 
0x09892f24:  0x0098a37c <runtime.lock2+0x0000005c>  0xf8659c22  0x00007fff  0x3fd00000 
0x09892f34:  0x00bb5518  0x00000001  0x00000000  0x00000001 
0x09892f44:  0x099823c0  0x09880000  0x00000000  0x009a0da4 <runtime.(*gcControllerState).removeIdleMarkWorker+0x00000054> 
0x09892f54:  0x00bdb3d8  0x00000001  0x0000000c  0x00000000 
0x09892f64:  0x00000000  0x098840f0  0x00000000  0x009b8ca0 <runtime.recovery+0x00000000> 
0x09892f74:  0x00000000  0xf9130e7c  0x00007fff  0x00aca390 
0x09892f84:  0x00000002  0x09a00240  0x099823c0  0x0099845e <runtime.gcBgMarkWorker+0x000000ee> 
0x09892f94: <0x00aca2e8  0x09812318  0xffff141a  0x00a8d97a <sync/atomic_test.TestNilDeref.func59+0x0000004a> 
0x09892fa4:  0x00000000  0x09884b40  0x00000000  0x0010005f 
0x09892fb4:  0x00001fa0  0x002b0023  0x0053002b  0x002b002b 
0x09892fc4:  0x00010246  0x00000000  0x00000000  0x00000000 
0x09892fd4:  0x00000000  0x00000000  0x00000000  0x00000000 
0x09892fe4:  0x00000000  0x00000000 !0x00000000 >0x00000000 
0x09892ff4:  0x00000000  0x00000000  0x00000000 
fatal error: unknown caller pc

Again, instead of finding goexit near the top of the stack, we find corruption and a PC in sync/atomic_test.TestNilDeref.func59.

I wonder whether the Windows fault handler is pushing a larger-than-expected fault descriptor onto the goroutine stack (should it be using the system stack), although func59 is a few frames above the actual fault, so I don't know why the fault descriptor would mention it.

Definitely looks like stack corruption somehow.