crypto/tls: TestDynamicRecordSizingWithStreamCipher timeout on darwin-amd64-10_12 builder

[bcmills]

From the darwin-amd64-race builder (https://build.golang.org/log/f1bbcc56f8b0a11004fddd58fdf1942d658c9e1c), a timeout due to an IO wait in crypto/tls.TestDynamicRecordSizingWithStreamCipher:

panic: test timed out after 3m0s

goroutine 23 [running]:
testing.(*M).startAlarm.func1()
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:1377 +0x11c
created by time.goFunc
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/time/sleep.go:168 +0x52

goroutine 1 [chan receive, 3 minutes]:
testing.(*T).Run(0xc000128100, 0x153f504, 0x27, 0x1553d60, 0x1)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:961 +0x68a
testing.runTests.func1(0xc000128100)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:1202 +0xa7
testing.tRunner(0xc000128100, 0xc00011db18)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:909 +0x19a
testing.runTests(0xc0000b4f60, 0x1859ac0, 0x80, 0x80, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:1200 +0x522
testing.(*M).Run(0xc0000f2080, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:1117 +0x300
crypto/tls.runMain(0xc0000f2080, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/crypto/tls/handshake_test.go:364 +0x9c6
crypto/tls.TestMain(0xc0000f2080)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/crypto/tls/handshake_test.go:310 +0xd1
main.main()
	_testmain.go:304 +0x224

goroutine 52 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x50a8f38, 0x72, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc0000f2118, 0x72, 0x0, 0x0, 0x1531467)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/internal/poll/fd_poll_runtime.go:87 +0xe4
internal/poll.(*pollDesc).waitRead(...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc0000f2100, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/internal/poll/fd_unix.go:384 +0x2c9
net.(*netFD).accept(0xc0000f2100, 0xc29f4b27680a5945, 0xfe, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/fd_unix.go:238 +0x56
net.(*TCPListener).accept(0xc0000b4220, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/tcpsock_posix.go:139 +0x50
net.(*TCPListener).Accept(0xc0000b4220, 0x0, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/tcpsock.go:261 +0x50
crypto/tls.localServer(0x15d1660, 0xc0000b4220)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/crypto/tls/handshake_test.go:234 +0x81
created by crypto/tls.runMain
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/crypto/tls/handshake_test.go:336 +0x312

goroutine 58 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x50a8e68, 0x77, 0xc0000f2200)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc0000f2218, 0x77, 0xc0000be000, 0x1, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/internal/poll/fd_poll_runtime.go:87 +0xe4
internal/poll.(*pollDesc).waitWrite(...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/internal/poll/fd_poll_runtime.go:96
internal/poll.(*FD).WaitWrite(...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/internal/poll/fd_unix.go:498
net.(*netFD).connect(0xc0000f2200, 0x15d2460, 0xc0000be008, 0x0, 0x0, 0x15cc4c0, 0xc0000dab40, 0x0, 0x0, 0x0, ...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/fd_unix.go:152 +0x376
net.(*netFD).dial(0xc0000f2200, 0x15d2460, 0xc0000be008, 0x15d3e80, 0x0, 0x15d3e80, 0xc00009f500, 0x0, 0x1, 0xc0000a93b8)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/sock_posix.go:149 +0x13a
net.socket(0x15d2460, 0xc0000be008, 0x1530d30, 0x3, 0x2, 0x1, 0x0, 0x0, 0x15d3e80, 0x0, ...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/sock_posix.go:70 +0x2a4
net.internetSocket(0x15d2460, 0xc0000be008, 0x1530d30, 0x3, 0x15d3e80, 0x0, 0x15d3e80, 0xc00009f500, 0x1, 0x0, ...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/ipsock_posix.go:141 +0x152
net.(*sysDialer).doDialTCP(0xc0000f2180, 0x15d2460, 0xc0000be008, 0x0, 0xc00009f500, 0x20000000000804, 0xc00009f4d0, 0xc0000bfa50)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/tcpsock_posix.go:65 +0x12f
net.(*sysDialer).dialTCP(0xc0000f2180, 0x15d2460, 0xc0000be008, 0x0, 0xc00009f500, 0x1099bc0, 0xc0000a9668, 0x15e79f3a)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/tcpsock_posix.go:61 +0x167
net.(*sysDialer).dialSingle(0xc0000f2180, 0x15d2460, 0xc0000be008, 0x15ceee0, 0xc00009f500, 0x0, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/dial.go:580 +0x765
net.(*sysDialer).dialSerial(0xc0000f2180, 0x15d2460, 0xc0000be008, 0xc00012c100, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/dial.go:548 +0x248
net.(*Dialer).DialContext(0xc0000a9ad8, 0x15d2460, 0xc0000be008, 0x1530d30, 0x3, 0xc0000bfa50, 0xf, 0x0, 0x0, 0x0, ...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/dial.go:426 +0x942
net.(*Dialer).Dial(...)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/dial.go:349
net.Dial(0x1530d30, 0x3, 0xc0000bfa50, 0xf, 0xc000046b98, 0x10448d8, 0x30, 0x14c1340)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/net/dial.go:320 +0xc9
crypto/tls.localPipe(0x15d7fa0, 0xc000128600, 0x0, 0x0, 0x0, 0x0)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/crypto/tls/handshake_test.go:257 +0x6aa
crypto/tls.runDynamicRecordSizingTest(0xc000128600, 0xc000062d80)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/crypto/tls/conn_test.go:137 +0x60
crypto/tls.TestDynamicRecordSizingWithStreamCipher(0xc000128600)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/crypto/tls/conn_test.go:244 +0x112
testing.tRunner(0xc000128600, 0x1553d60)
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:909 +0x19a
created by testing.(*T).Run
	/var/folders/dx/k53rs1s93538b4x20g46cj_w0000gn/T/workdir/go/src/testing/testing.go:960 +0x652
FAIL	crypto/tls	180.096s

See previously #27902, #27833 (crypto/tls timeouts on darwin); #32919, #29225, #32534 (various timeout-related errors in the net package on darwin).

CC @FiloSottile @ianlancetaylor @mikioh

[FiloSottile]

This is stuck in Dial/Accept, like many other issues, and AFAICT it's not TLS specific. The crypto/tls already grew a lot of code just to try to get a connected TCP pipe, and I feel like it's getting out of scope. There should probably be some helper package that crypto/tls and others can rely on.

[bcmills]

There should probably be some helper package that crypto/tls and others can rely on.

Agreed — ideally exported somewhere. (If we can't write non-flaky tests using the net API as written, what are users supposed to do‽)

[bcmills]

2020-03-31T20:59:14-3431428/darwin-amd64-10_12
2019-11-21T19:27:16-f4a8bf1/darwin-amd64-10_12
2019-11-12T04:09:39-72e043e/darwin-amd64-10_12
2019-11-08T17:00:57-dac936a/darwin-amd64-10_12
2019-11-05T05:22:07-3c0fbee/darwin-amd64-10_12
2019-10-31T17:09:48-a9b37ae/darwin-amd64-10_12

[bcmills]

Retitling to reflect #34920. (The -race builder was upgraded, so this now appears to only affect darwin-amd64-10_12.)

[bcmills]

I wonder if this is the same general problem as in #29583 (see CL 184157)..?

[bcmills]

2021-02-19T00:03:52-38672d3/darwin-amd64-10_12
2021-01-21T19:15:21-3c2f11b/darwin-amd64-10_12
2020-09-15T18:53:55-dbde566/darwin-amd64-10_12
2020-09-06T20:23:50-5cc030a/darwin-amd64-10_12
2020-06-29T08:06:32-152ffca/darwin-amd64-10_12