runtime: waitforsingleobject wait_failed

[pjweinb]

Go version

go1.21.6

Output of go env in your module/workspace:

set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\pjw\AppData\Local\go-build
set GOENV=C:\Users\pjw\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\pjw\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\pjw\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLCHAIN=auto
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.21.6
set GCCGO=gccgo
set GOAMD64=v1
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=0
set GOMOD=C:\Users\pjw\telemetry\go.mod
set GOWORK=
set CGO_CFLAGS=-O2 -g
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-O2 -g
set CGO_FFLAGS=-O2 -g
set CGO_LDFLAGS=-O2 -g
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -fno-caret-diagnostics -Qunused-arguments -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=C:\Users\pjw\AppData\Local\Temp\go-build1353919923=/tmp/go-build -gno-record-gcc-switches

What did you do?

I downloaded golang.org/x/telemetry and ran
go test ./internal/counter/... -run Rotate -count 70

What did you see happen?

runtime: waitforsingleobject wait_failed; errno=6
fatal error: runtime.semasleep wait_failed
runtime.preemptM: duplicatehandle failed; errno=6
fatal error: runtime.preemptM: duplicatehandle failed
panic during panic

runtime stack:
runtime.throw({0xb08f80?, 0xffffffffffffffff?})
        C:/Program Files/Go/src/runtime/panic.go:1077 +0x65 fp=0x6f267ff038 sp=0x6f267ff008 pc=0x9c95e5
runtime.preemptM(0x1?)
        C:/Program Files/Go/src/runtime/os_windows.go:1313 +0x476 fp=0x6f267ff598 sp=0x6f267ff038 pc=0x9c6f36
runtime.preemptone(0x6f267ff5d8?)
        C:/Program Files/Go/src/runtime/proc.go:5790 +0x55 fp=0x6f267ff5b0 sp=0x6f267ff598 pc=0x9d7a75
runtime.preemptall()
        C:/Program Files/Go/src/runtime/proc.go:5752 +0x4f fp=0x6f267ff5e8 sp=0x6f267ff5b0 pc=0x9d79ef
runtime.freezetheworld()
        C:/Program Files/Go/src/runtime/proc.go:961 +0x105 fp=0x6f267ff618 sp=0x6f267ff5e8 pc=0x9cd565
runtime.startpanic_m()
        C:/Program Files/Go/src/runtime/panic.go:1263 +0x13c fp=0x6f267ff640 sp=0x6f267ff618 pc=0x9c9c3c
runtime.fatalthrow.func1()
        C:/Program Files/Go/src/runtime/panic.go:1168 +0x2e fp=0x6f267ff680 sp=0x6f267ff640 pc=0x9c994e
runtime.fatalthrow(0x267ff6c8?)
        C:/Program Files/Go/src/runtime/panic.go:1163 +0x65 fp=0x6f267ff6c0 sp=0x6f267ff680 pc=0x9c98e5
runtime.throw({0xb05c02?, 0x9c61d6?})
        C:/Program Files/Go/src/runtime/panic.go:1077 +0x65 fp=0x6f267ff6f0 sp=0x6f267ff6c0 pc=0x9c95e5
runtime.semasleep.func2()
        C:/Program Files/Go/src/runtime/os_windows.go:822 +0x6a fp=0x6f267ff718 sp=0x6f267ff6f0 pc=0x9f2c8a
runtime.semasleep(0xc0003249c0?)
        C:/Program Files/Go/src/runtime/os_windows.go:820 +0x11c fp=0x6f267ff780 sp=0x6f267ff718 pc=0x9c55bc
runtime.notesleep(0xc0000a1518)
        C:/Program Files/Go/src/runtime/lock_sema.go:181 +0x92 fp=0x6f267ff7b8 sp=0x6f267ff780 pc=0x99c072
runtime.mPark(...)
        C:/Program Files/Go/src/runtime/proc.go:1632
runtime.stopm()
        C:/Program Files/Go/src/runtime/proc.go:2536 +0x8c fp=0x6f267ff7e8 sp=0x6f267ff7b8 pc=0x9d016c
runtime.findRunnable()
        C:/Program Files/Go/src/runtime/proc.go:3229 +0xb9c fp=0x6f267ff8f8 sp=0x6f267ff7e8 pc=0x9d1a9c
runtime.schedule()
        C:/Program Files/Go/src/runtime/proc.go:3582 +0xb1 fp=0x6f267ff930 sp=0x6f267ff8f8 pc=0x9d2891
runtime.park_m(0xc0000949c0?)
        C:/Program Files/Go/src/runtime/proc.go:3745 +0x11f fp=0x6f267ff978 sp=0x6f267ff930 pc=0x9d2d9f
traceback: unexpected SPWRITE function runtime.mcall
runtime.mcall()
        C:/Program Files/Go/src/runtime/asm_amd64.s:458 +0x53 fp=0x6f267ff990 sp=0x6f267ff978 pc=0x9f8f33

goroutine 1 [chan receive]:
runtime.gopark(0xc0000d19e8?, 0x99da05?, 0x88?, 0xfd?, 0x18?)
        C:/Program Files/Go/src/runtime/proc.go:398 +0xce fp=0xc000587980 sp=0xc000587960 pc=0x9cc26e
runtime.chanrecv(0xc0003abe30, 0xc0000d1a67, 0x1)
        C:/Program Files/Go/src/runtime/chan.go:583 +0x3d0 fp=0xc0005879f8 sp=0xc000587980 pc=0x996b50
runtime.chanrecv1(0xc28640?, 0xad18a0?)
        C:/Program Files/Go/src/runtime/chan.go:442 +0x12 fp=0xc000587a20 sp=0xc0005879f8 pc=0x996772
testing.(*T).Run(0xc00038f860, {0xb00959?, 0x9ffe0d?}, 0xb0cc10)
        C:/Program Files/Go/src/testing/testing.go:1649 +0x3c8 fp=0xc000587ae0 sp=0xc000587a20 pc=0xa6e388
testing.runTests.func1(0xc290a0?)
        C:/Program Files/Go/src/testing/testing.go:2054 +0x3e fp=0xc000587b30 sp=0xc000587ae0 pc=0xa7043e
testing.tRunner(0xc00038f860, 0xc0000d1c48)
        C:/Program Files/Go/src/testing/testing.go:1595 +0xff fp=0xc000587b80 sp=0xc000587b30 pc=0xa6d55f
testing.runTests(0xc0000b6460?, {0xc24680, 0xb, 0xb}, {0x9a36bf?, 0xc0000d1d08?, 0xc28880?})
        C:/Program Files/Go/src/testing/testing.go:2052 +0x445 fp=0xc000587c78 sp=0xc000587b80 pc=0xa70325
testing.(*M).Run(0xc0000b6460)
        C:/Program Files/Go/src/testing/testing.go:1925 +0x636 fp=0xc000587ec0 sp=0xc000587c78 pc=0xa6ed16
main.main()
        _testmain.go:67 +0x19c fp=0xc000587f40 sp=0xc000587ec0 pc=0xac2f7c
runtime.main()
        C:/Program Files/Go/src/runtime/proc.go:267 +0x2b2 fp=0xc000587fe0 sp=0xc000587f40 pc=0x9cbe32
runtime.goexit()
        C:/Program Files/Go/src/runtime/asm_amd64.s:1650 +0x1 fp=0xc000587fe8 sp=0xc000587fe0 pc=0x9faf61

goroutine 2 [force gc (idle)]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
        C:/Program Files/Go/src/runtime/proc.go:398 +0xce fp=0xc000097fa8 sp=0xc000097f88 pc=0x9cc26e
runtime.goparkunlock(...)
        C:/Program Files/Go/src/runtime/proc.go:404
runtime.forcegchelper()
        C:/Program Files/Go/src/runtime/proc.go:322 +0xb8 fp=0xc000097fe0 sp=0xc000097fa8 pc=0x9cc0d8
runtime.goexit()
        C:/Program Files/Go/src/runtime/asm_amd64.s:1650 +0x1 fp=0xc000097fe8 sp=0xc000097fe0 pc=0x9faf61
created by runtime.init.6 in goroutine 1
        C:/Program Files/Go/src/runtime/proc.go:310 +0x1a

goroutine 3 [GC sweep wait]:
runtime.gopark(0x1?, 0x0?, 0x0?, 0x0?, 0x0?)
        C:/Program Files/Go/src/runtime/proc.go:398 +0xce fp=0xc000099f78 sp=0xc000099f58 pc=0x9cc26e
runtime.goparkunlock(...)
        C:/Program Files/Go/src/runtime/proc.go:404
runtime.bgsweep(0x0?)
        C:/Program Files/Go/src/runtime/mgcsweep.go:321 +0xdf fp=0xc000099fc8 sp=0xc000099f78 pc=0x9b4ebf
runtime.gcenable.func1()
        C:/Program Files/Go/src/runtime/mgc.go:200 +0x25 fp=0xc000099fe0 sp=0xc000099fc8 pc=0x9aa005
runtime.goexit()
        C:/Program Files/Go/src/runtime/asm_amd64.s:1650 +0x1 fp=0xc000099fe8 sp=0xc000099fe0 pc=0x9faf61
created by runtime.gcenable in goroutine 1
        C:/Program Files/Go/src/runtime/mgc.go:200 +0x66

goroutine 4 [runnable]:
runtime.gopark(0xc0000a4000?, 0xb35678?, 0x0?, 0x0?, 0x0?)
        C:/Program Files/Go/src/runtime/proc.go:398 +0xce fp=0xc0000abf70 sp=0xc0000abf50 pc=0x9cc26e
runtime.goparkunlock(...)
        C:/Program Files/Go/src/runtime/proc.go:404
runtime.(*scavengerState).park(0xc28900)
        C:/Program Files/Go/src/runtime/mgcscavenge.go:425 +0x49 fp=0xc0000abfa0 sp=0xc0000abf70 pc=0x9b2749
runtime.bgscavenge(0xc0000a4000?)
        C:/Program Files/Go/src/runtime/mgcscavenge.go:658 +0x59 fp=0xc0000abfc8 sp=0xc0000abfa0 pc=0x9b2cf9
runtime.gcenable.func2()
        C:/Program Files/Go/src/runtime/mgc.go:201 +0x25 fp=0xc0000abfe0 sp=0xc0000abfc8 pc=0x9a9fa5
runtime.goexit()
        C:/Program Files/Go/src/runtime/asm_amd64.s:1650 +0x1 fp=0xc0000abfe8 sp=0xc0000abfe0 pc=0x9faf61
created by runtime.gcenable in goroutine 1
        C:/Program Files/Go/src/runtime/mgc.go:201 +0xa5

etc....

What did you expect to see?

I expected either the test to pass or flaky test failures.

This failure is reproducible for me on my Windows virtual machine.

[mknyszek]

In triage: something really went wrong here. It looks like this is a failure in asynchronous preemption, but I think we've also never seen a failure like this before.

The fact that it's reproducible is super interesting as well. I guess we should try to reproduce this on a gomote too.

CC @golang/windows, has anyone there seen something like this before?

[bcmills]

According to https://learn.microsoft.com/en-us/windows/win32/debug/system-error-codes--0-499-, Windows error number 6 is ERROR_INVALID_HANDLE.

And it looks like the waitforsingleobject wait_failed error message is specific to semasleep.

That failure mode suggests a close connection to #43720.

[qmuntal]

I can reproduce it locally. Don't know how is that the runtime fails so catastrophically, but it has something to do with a bug I just found in x/telemetry: a mapped file can be unmapped twice, one here and the other here, called from a finalizer set in here.

The second call to munmap could be corrupting some memory which produces the runtime failure. The fact that the runtime crash happens after ~70 test runs also indicates that it has something to do with the GC and a finalizer doing something wrong.

Replacing the munmap call inside rotate1 for previous.close() fixes the issue, as mappedFile.close ensures that munmap is only ever called once.

[pjweinb]

excellent! Thank you for that.

…

On Mon, Jan 29, 2024 at 9:36 AM Quim Muntal ***@***.***> wrote: I can reproduce it locally. Don't know how is that the runtime fails so catastrophically, but it has something to do with a bug I just found in x/telemetry: a mapped file can be unmapped twice, one here <https://github.com/golang/telemetry/blob/262b4901faf4875a13bf0b9ef1b08af9ea54187c/internal/counter/file.go#L280-L284> and the other here <https://github.com/golang/telemetry/blob/262b4901faf4875a13bf0b9ef1b08af9ea54187c/internal/counter/file.go#L500-L511>, called from a finalizer set in here <https://github.com/golang/telemetry/blob/262b4901faf4875a13bf0b9ef1b08af9ea54187c/internal/counter/file.go#L409> . The second call to munmap could be corrupting some memory which produces the runtime failure. The fact that the runtime crash happens after ~70 test runs also indicates that it has something to do with the GC and a finalizer doing something wrong. Replacing the munmap call inside rotate1 for previous.close() fixes the issue, as mappedFile.close ensures that munmap is only ever called once. — Reply to this email directly, view it on GitHub <#65255 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABJIAI57NDOGNXHUXNIQPALYQ6XWFAVCNFSM6AAAAABCI2BVYWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMJUHAZDCOBYGA> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[gopherbot]

Change https://go.dev/cl/559498 mentions this issue: internal/counter: fix flaky test