os/exec: test timeouts on openbsd

[josharian]

Build dashboard:

panic: test timed out after 3m0s

goroutine 22 [running]:
testing.startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:1029 +0xf9
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:170 +0x44

goroutine 1 [chan receive, 2 minutes]:
testing.(*T).Run(0xc42006ed00, 0x736e60, 0x1c, 0x741ee0, 0x474f01)
	/tmp/workdir/go/src/testing/testing.go:702 +0x304
testing.runTests.func1(0xc42006ed00)
	/tmp/workdir/go/src/testing/testing.go:888 +0x67
testing.tRunner(0xc42006ed00, 0xc420047e10)
	/tmp/workdir/go/src/testing/testing.go:659 +0x98
testing.runTests(0xc4200b6440, 0x8d6fa0, 0x1b, 0x1b, 0x42)
	/tmp/workdir/go/src/testing/testing.go:886 +0x2b5
testing.(*M).Run(0xc420d20f20, 0xc420047f78)
	/tmp/workdir/go/src/testing/testing.go:828 +0xfc
main.main()
	os/exec/_test/_testmain.go:98 +0xdb

goroutine 17 [syscall, 2 minutes, locked to thread]:
runtime.goexit()
	/tmp/workdir/go/src/runtime/asm_amd64.s:2142 +0x1

goroutine 11 [chan receive, 2 minutes]:
testing.(*T).Parallel(0xc42006f520)
	/tmp/workdir/go/src/testing/testing.go:591 +0x145
os/exec_test.TestWaitid(0xc42006f520)
	/tmp/workdir/go/src/os/exec/exec_posix_test.go:51 +0x40
testing.tRunner(0xc42006f520, 0x741f40)
	/tmp/workdir/go/src/testing/testing.go:659 +0x98
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:701 +0x2da

goroutine 102 [chan receive, 2 minutes]:
os/exec.(*Cmd).Wait(0xc4203098c0, 0x0, 0x0)
	/tmp/workdir/go/src/os/exec/exec.go:447 +0x118
os/exec.(*Cmd).Run(0xc4203098c0, 0xc42030c770, 0xa00000)
	/tmp/workdir/go/src/os/exec/exec.go:284 +0x5c
os/exec_test.TestIgnorePipeErrorOnSuccess(0xc42030eea0)
	/tmp/workdir/go/src/os/exec/exec_test.go:893 +0x18a
testing.tRunner(0xc42030eea0, 0x741ee0)
	/tmp/workdir/go/src/testing/testing.go:659 +0x98
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:701 +0x2da

goroutine 64 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x275d85d08, 0x77, 0x465ea9)
	/tmp/workdir/go/src/runtime/netpoll.go:173 +0x59
internal/poll.(*pollDesc).wait(0xc42012a068, 0x77, 0x8a9ba0, 0x8a5520)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitWrite(0xc42012a068, 0xc421734000, 0x9f0000)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:94 +0x34
internal/poll.(*FD).Write(0xc42012a050, 0xc421724000, 0xa00000, 0xa00000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:221 +0x219
os.(*File).write(0xc42000e028, 0xc421724000, 0xa00000, 0xa00000, 0xc420037d60, 0x445c13, 0xc421724000)
	/tmp/workdir/go/src/os/file_unix.go:220 +0x4e
os.(*File).Write(0xc42000e028, 0xc421724000, 0xa00000, 0xa00000, 0xa00000, 0xa00000, 0x40fa9d)
	/tmp/workdir/go/src/os/file.go:144 +0x7d
os.(*File).WriteString(0xc42000e028, 0xc420d24000, 0xa00000, 0x275d86140, 0xc42000e028, 0x1)
	/tmp/workdir/go/src/os/file.go:202 +0x6f
io.WriteString(0x8a83a0, 0xc42000e028, 0xc420d24000, 0xa00000, 0x6daaa0, 0x70c820, 0x1)
	/tmp/workdir/go/src/io/io.go:289 +0x76
strings.(*Reader).WriteTo(0xc42000c0e0, 0x8a83a0, 0xc42000e028, 0x275d86118, 0xc42000c0e0, 0x1)
	/tmp/workdir/go/src/strings/reader.go:133 +0xa3
io.copyBuffer(0x8a83a0, 0xc42000e028, 0x8a8620, 0xc42000c0e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/io/io.go:380 +0x31a
io.Copy(0x8a83a0, 0xc42000e028, 0x8a8620, 0xc42000c0e0, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/io/io.go:360 +0x68
os/exec.(*Cmd).stdin.func1(0x0, 0x0)
	/tmp/workdir/go/src/os/exec/exec.go:213 +0x55
os/exec.(*Cmd).Start.func1(0xc4203098c0, 0xc42000c120)
	/tmp/workdir/go/src/os/exec/exec.go:375 +0x27
created by os/exec.(*Cmd).Start
	/tmp/workdir/go/src/os/exec/exec.go:374 +0x4f4
FAIL	os/exec	180.093s

https://build.golang.org/log/7fc2593c7c90818805f1d623fbe9fa9f3d1d4aec

trybot run:

panic: test timed out after 3m0s

goroutine 106 [running]:
testing.startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:1029 +0xf9
created by time.goFunc
	/tmp/workdir/go/src/time/sleep.go:170 +0x44

goroutine 1 [chan receive, 2 minutes]:
testing.(*T).Run(0xc420064ea0, 0x736e60, 0x1c, 0x741ee0, 0x474f01)
	/tmp/workdir/go/src/testing/testing.go:702 +0x304
testing.runTests.func1(0xc420064ea0)
	/tmp/workdir/go/src/testing/testing.go:888 +0x67
testing.tRunner(0xc420064ea0, 0xc420047e10)
	/tmp/workdir/go/src/testing/testing.go:659 +0x98
testing.runTests(0xc4200b6460, 0x8d6fa0, 0x1b, 0x1b, 0x42)
	/tmp/workdir/go/src/testing/testing.go:886 +0x2b5
testing.(*M).Run(0xc420037f20, 0xc420047f78)
	/tmp/workdir/go/src/testing/testing.go:828 +0xfc
main.main()
	os/exec/_test/_testmain.go:98 +0xdb

goroutine 17 [syscall, 2 minutes, locked to thread]:
runtime.goexit()
	/tmp/workdir/go/src/runtime/asm_amd64.s:2142 +0x1

goroutine 11 [chan receive, 2 minutes]:
testing.(*T).Parallel(0xc4200656c0)
	/tmp/workdir/go/src/testing/testing.go:591 +0x145
os/exec_test.TestWaitid(0xc4200656c0)
	/tmp/workdir/go/src/os/exec/exec_posix_test.go:51 +0x40
testing.tRunner(0xc4200656c0, 0x741f40)
	/tmp/workdir/go/src/testing/testing.go:659 +0x98
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:701 +0x2da

goroutine 120 [chan receive, 2 minutes]:
os/exec.(*Cmd).Wait(0xc42010cc60, 0x0, 0x0)
	/tmp/workdir/go/src/os/exec/exec.go:447 +0x118
os/exec.(*Cmd).Run(0xc42010cc60, 0xc420110460, 0xa00000)
	/tmp/workdir/go/src/os/exec/exec.go:284 +0x5c
os/exec_test.TestIgnorePipeErrorOnSuccess(0xc42010a9c0)
	/tmp/workdir/go/src/os/exec/exec_test.go:893 +0x18a
testing.tRunner(0xc42010a9c0, 0x741ee0)
	/tmp/workdir/go/src/testing/testing.go:659 +0x98
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:701 +0x2da

goroutine 104 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x281069d08, 0x77, 0x465ea9)
	/tmp/workdir/go/src/runtime/netpoll.go:173 +0x59
internal/poll.(*pollDesc).wait(0xc42017c068, 0x77, 0x8a9ba0, 0x8a5520)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitWrite(0xc42017c068, 0xc42172e000, 0x9f0000)
	/tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:94 +0x34
internal/poll.(*FD).Write(0xc42017c050, 0xc42171e000, 0xa00000, 0xa00000, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/internal/poll/fd_unix.go:221 +0x219
os.(*File).write(0xc42000e028, 0xc42171e000, 0xa00000, 0xa00000, 0xc420038d60, 0x445c13, 0xc42171e000)
	/tmp/workdir/go/src/os/file_unix.go:220 +0x4e
os.(*File).Write(0xc42000e028, 0xc42171e000, 0xa00000, 0xa00000, 0xa00000, 0xa00000, 0x40fa9d)
	/tmp/workdir/go/src/os/file.go:144 +0x7d
os.(*File).WriteString(0xc42000e028, 0xc420d1e000, 0xa00000, 0x265940078, 0xc42000e028, 0x1)
	/tmp/workdir/go/src/os/file.go:202 +0x6f
io.WriteString(0x8a83a0, 0xc42000e028, 0xc420d1e000, 0xa00000, 0x6daaa0, 0x70c820, 0xc420020e01)
	/tmp/workdir/go/src/io/io.go:289 +0x76
strings.(*Reader).WriteTo(0xc420160000, 0x8a83a0, 0xc42000e028, 0x265940050, 0xc420160000, 0xc420001b01)
	/tmp/workdir/go/src/strings/reader.go:133 +0xa3
io.copyBuffer(0x8a83a0, 0xc42000e028, 0x8a8620, 0xc420160000, 0x0, 0x0, 0x0, 0xc4202f3c70, 0x0, 0x0)
	/tmp/workdir/go/src/io/io.go:380 +0x31a
io.Copy(0x8a83a0, 0xc42000e028, 0x8a8620, 0xc420160000, 0x6bb8e0, 0xc4203125a0, 0xc420020fb0)
	/tmp/workdir/go/src/io/io.go:360 +0x68
os/exec.(*Cmd).stdin.func1(0x6bb8e0, 0xc4203125a0)
	/tmp/workdir/go/src/os/exec/exec.go:213 +0x55
os/exec.(*Cmd).Start.func1(0xc42010cc60, 0xc420160020)
	/tmp/workdir/go/src/os/exec/exec.go:375 +0x27
created by os/exec.(*Cmd).Start
	/tmp/workdir/go/src/os/exec/exec.go:374 +0x4f4
FAIL	os/exec	180.085s

https://storage.googleapis.com/go-build-log/581bc46b/openbsd-amd64-60_3bfc9d56.log

[bradfitz]

/cc @mdempsky for OpenBSD

[alexbrainman]

Found this during CL 38761 trybot run https://storage.googleapis.com/go-build-log/99b40820/openbsd-amd64-60_178381c2.log

Alex

[martisch]

Another one during CL 39950: https://storage.googleapis.com/go-build-log/772dd722/openbsd-amd64-60_91338d40.log

[enj]

Seen in CL 40436: https://storage.googleapis.com/go-build-log/f48e4bd9/openbsd-amd64-60_0be4f0a9.log

[mdempsky]

It looks like the timeouts always happen in TestIgnorePipeErrorOnSuccess. Also, TestWaitid is always blocked waiting in t.Parallel. (The latter seems expected: TestIgnorePipeErrorOnSuccess is a serial test, so TestWaitid logically has to wait for it to finish, but I don't really understand the inner working of package testing.)

Casually reading through the OpenBSD-specific code, I don't see anything obviously wrong. I'll have to try running the code on an actual OpenBSD box and see if I can reproduce a failure under ktrace.

From the trace, it seems like one of the io.Copy calls (either copying the StringReader to pipe, or pipe to bytes.Buffer) is hanging. That would make me suspect a kqueue issue, but then I'd expect to see the issue on 386 too.

One minor observation: OpenBSD 5.7 added functions like pipe2 and dup3 so it's now possible to create FDs with the CLOEXEC flag already set, which would allow us to get rid of a lot of uses of ForkLock. I don't think that's the issue though.

[bradfitz]

I created an OpenBSD VM yesterday with the same builder image & ran the test in a loop tens of thousands of times. I did finally get it to fail once, but it wasn't easy. It seems to happen more easily under load, so then I started running go test -short std in a loop, went away, and later saw my dead ssh window showing that it had indeed hung, but I wasn't around to investigate.

tl;dr: reproducible at least.

[bradfitz]

@mdempsky, can you look into this?

Our openbsd-386 column is 2/3rds red. Currently our 386 builder is only OpenBSD 6.0. I'm brining up an OpenBSD/386 6.2 builder now. That is #22835. But our amd64 OpenBSD columns look happy for both 6.0 and 6.2