os: TestPipeIOCloseRace timeout on Windows blocked in `syscall.CancelIoEx`

[gopherbot]

#!watchflakes
post <- goos == "windows" && pkg == "os" && ((log ~ `panic: test timed out` && log ~ `^\s*syscall\.CancelIoEx`) || status == "ABORT" )

Issue created automatically to collect these failures.

Example (log):

panic: test timed out after 3m0s
running tests:
	TestPipeIOCloseRace (2m59s)

goroutine 879 gp=0x4000174340 m=10 mp=0x4000180708 [running]:
panic({0x7ff7b437a3a0?, 0x4000400040?})
	C:/workdir/go/src/runtime/panic.go:779 +0x140 fp=0x400017bf00 sp=0x400017be50 pc=0x7ff7b4229d10
testing.(*M).startAlarm.func1()
	C:/workdir/go/src/testing/testing.go:2366 +0x30c fp=0x400017bfd0 sp=0x400017bf00 pc=0x7ff7b42f001c
runtime.goexit({})
...

goroutine 273 gp=0x4000443860 m=nil [GC worker (idle), 2 minutes]:
runtime.gopark(0x8501acdde81b4?, 0x0?, 0x0?, 0x0?, 0x0?)
	C:/workdir/go/src/runtime/proc.go:402 +0xc8 fp=0x400034bf30 sp=0x400034bf10 pc=0x7ff7b422d398
runtime.gcBgMarkWorker()
	C:/workdir/go/src/runtime/mgc.go:1310 +0xd8 fp=0x400034bfd0 sp=0x400034bf30 pc=0x7ff7b420c1c8
runtime.goexit({})
	C:/workdir/go/src/runtime/asm_arm64.s:1222 +0x4 fp=0x400034bfd0 sp=0x400034bfd0 pc=0x7ff7b4263734
created by runtime.gcBgMarkStartWorkers in goroutine 308
	C:/workdir/go/src/runtime/mgc.go:1234 +0x28

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "os" && test == ""

2023-11-30 18:35 windows-arm64-11 go@bda1ef13 os (log)

panic: test timed out after 3m0s
running tests:
	TestPipeIOCloseRace (2m59s)

goroutine 879 gp=0x4000174340 m=10 mp=0x4000180708 [running]:
panic({0x7ff7b437a3a0?, 0x4000400040?})
	C:/workdir/go/src/runtime/panic.go:779 +0x140 fp=0x400017bf00 sp=0x400017be50 pc=0x7ff7b4229d10
testing.(*M).startAlarm.func1()
	C:/workdir/go/src/testing/testing.go:2366 +0x30c fp=0x400017bfd0 sp=0x400017bf00 pc=0x7ff7b42f001c
runtime.goexit({})
...

goroutine 273 gp=0x4000443860 m=nil [GC worker (idle), 2 minutes]:
runtime.gopark(0x8501acdde81b4?, 0x0?, 0x0?, 0x0?, 0x0?)
	C:/workdir/go/src/runtime/proc.go:402 +0xc8 fp=0x400034bf30 sp=0x400034bf10 pc=0x7ff7b422d398
runtime.gcBgMarkWorker()
	C:/workdir/go/src/runtime/mgc.go:1310 +0xd8 fp=0x400034bfd0 sp=0x400034bf30 pc=0x7ff7b420c1c8
runtime.goexit({})
	C:/workdir/go/src/runtime/asm_arm64.s:1222 +0x4 fp=0x400034bfd0 sp=0x400034bfd0 pc=0x7ff7b4263734
created by runtime.gcBgMarkStartWorkers in goroutine 308
	C:/workdir/go/src/runtime/mgc.go:1234 +0x28

— watchflakes

[bcmills]

@golang/windows, any idea why CancelIoEx would block for over 2 minutes?

[alexbrainman]

@golang/windows, any idea why CancelIoEx would block for over 2 minutes?

No idea. According to https://learn.microsoft.com/en-us/windows/win32/fileio/cancelioex-func

The CancelIoEx function does not wait for all canceled operations to complete.

Alex

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- goos == "windows" && pkg == "os" && ((log ~ `panic: test timed out` && log ~ `^\s*syscall\.CancelIoEx`) || status == "ABORT" )

2024-03-07 05:26 gotip-windows-386 go@a0624701 os.TestPipeIOCloseRace [ABORT] (log)

=== RUN   TestPipeIOCloseRace
=== PAUSE TestPipeIOCloseRace
=== CONT  TestPipeIOCloseRace

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- goos == "windows" && pkg == "os" && ((log ~ `panic: test timed out` && log ~ `^\s*syscall\.CancelIoEx`) || status == "ABORT" )

2025-02-22 21:25 gotip-windows-arm64 go@38825ef3 os.TestPipeIOCloseRace [ABORT] (log)

=== RUN   TestPipeIOCloseRace
=== PAUSE TestPipeIOCloseRace
=== CONT  TestPipeIOCloseRace

— watchflakes

[wiresock]

Hello!

I extracted the test from this issue and turned it into a standalone application. It consistently hangs under load, and after digging into the cause, I believe the root issue is in how Go handles pipe cleanup on Windows.

Specifically, os.Pipe() uses CreatePipe, which creates synchronous handles (i.e., not created with FILE_FLAG_OVERLAPPED). However, in (*FD).Close() Go still calls:

if fd.kind == kindPipe {
    syscall.CancelIoEx(fd.Sysfd, nil)
}

This is unsafe because CancelIoEx is designed for canceling overlapped I/O, not synchronous I/O. Calling it on a synchronous pipe handle can lead to hangs.

After commenting out that call and rebuilding Go from source, the hang completely disappeared.

So this is an issue in the runtime: Go calls CancelIoEx on handles where it's neither needed nor safe. A fix could be to avoid calling CancelIoEx unless the handle was explicitly created with FILE_FLAG_OVERLAPPED.

I actually stepped into this issue while investigating another CancelIoEx-related hang, which occurs at this line. Any ideas on that one?