os/exec: Cmd.Wait Cmd.StderrPipe data-loss race condition go1.22.3 240525 darwin-arm64 14.5

[haraldrudell]

Go version

1.22.3

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/foxyboy/Library/Caches/go-build'
GOENV='/Users/foxyboy/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/foxyboy/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/foxyboy/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.22.3/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.22.3/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.3'
GCCGO='gccgo'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/sq/0x1_9fyn1bv907s7ypfryt1c0000gn/T/go-build3913560309=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Send SIGABRT to Go-launched sub-process while capturing standard error

Reproduction:

// reproduce [exec.Cmd.Wait] [exec.Cmd.StderrPipe] race condition go1.22.3 240525 darwin-arm64 14.5
//   - Harald Rudell <harald.rudell@gmail.com> (https://haraldrudell.github.io/haraldrudell/)
//   - occurring for sub-process outputting >10 KiB to stderr just before exit
//   - success: stderr last line: register output, complete line: “fault...”
//   - failure: stderr last line: cut off stack trace somewhere before “fault…” like: “…sys_darwin.go:23 +0x58 fp=%”
//   - never fails while debugging
//   - failure rate: 33%
func main() {
	// some program with stack trace output exceeding 10 KiB
	var execCmd = exec.Command("cony", "8.8.8.8:443")
	execCmd.Stdin = os.Stdin
	var waitForReadThread = make(chan struct{})
	// stderr is [*os.File] from [os.Pipe] [syscall.Pipe]: OS-specific kernel pipe
	if stderr, err := execCmd.StderrPipe(); panick(err) {
		go func() {
			defer close(waitForReadThread)
			<-time.NewTimer(time.Second).C
			panick(execCmd.Process.Signal(unix.SIGABRT))
			// macOS: ReadFrom and WriteTo not handled
			//	- err: *fs.PathError *errors.errorString “read |0: file already closed”
			//	- error location: stderr: [os.File.Read] [internal/poll.FD.Read] [syscall.Read]
			//	- breakpoint: [os.File.wrapErr]: err = ErrClosed
			//	- issue: pipe hard-closes prior to being read to empty
			_, _ /*written, err*/ = io.Copy(os.Stderr, stderr)
		}()
	}
	// [exec.Cmd.Wait] invokes closeDescriptors
	panick2(execCmd.Run())
	<-waitForReadThread
}

func panick2(err error) {
	var exitError *exec.ExitError
	if !errors.As(err, &exitError) {
		panic(err)
	}
}

func panick(err error) (alwaysTrue bool) {
	if alwaysTrue = err == nil; !alwaysTrue {
		panic(err)
	}
	return
}

What did you see happen?

33% of cases, a cut-off stack trace: sys_darwin.go:23 +0x58 fp=%

• Caused by [exec.Cmd.Wait] invoking closeDescriptors, which
• in 33% of non-debugging cases leads to a close of the OS pipe discarding
• bytes read in parallel from the OS pipe returned by [exec.Cmd.StderrPipe]

never fails while debugging

What did you expect to see?

on success, last line a complete line-terminated register line: fault 0x19d6259ec

[haraldrudell]

I wrote a fast writer draining the OS-pipe within microseconds. Problem persists
— FastWriter receives many chunks, the longest 16,571 bytes, the large one in less than 118μs, smaller in less than 20μs
— FastWriter receives additional small chunks after the big chunk

Apple baselessly asserts macOS the best operating system in the world, where writing to a terminal window could erratically take 2 seconds

[ianlancetaylor]

This behavior is documented. See https://pkg.go.dev/os/exec#Cmd.StderrPipe. I'm not sure there is anything to do here.

[haraldrudell]

There is therefore an additional synchronizing wait required:
— in between successful [exec.Cmd.Start] and [exec.Cmd.Wait] where
— any stream obtained via [exec.Cmd.StderrPipe] [exec.Cmd.StdoutPipe] has to be read until io.EOF

the [exec.Cmd.Wait] subsequent to that does not await anything, it does cleanup

[haraldrudell]

worksforme