Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
bcmills opened this issue Oct 7, 2019 · 6 comments
Open

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

bcmills opened this issue Oct 7, 2019 · 6 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@bcmills
Copy link
Contributor

bcmills commented Oct 7, 2019 •
edited

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
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 7, 2019
@bcmills bcmills added this to the Go1.14 milestone Oct 7, 2019
@FiloSottile
Copy link
Contributor

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
Copy link
Contributor Author

bcmills commented Oct 7, 2019

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‽)

@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@bcmills bcmills mentioned this issue Oct 31, 2019
Open
@bcmills
Copy link
Contributor Author

bcmills commented Apr 1, 2020

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 bcmills changed the title crypto/tls: TestDynamicRecordSizingWithStreamCipher timeout on darwin-amd64-race builder crypto/tls: TestDynamicRecordSizingWithStreamCipher timeout on darwin-amd64-10_12 builder Sep 8, 2020
@bcmills
Copy link
Contributor Author

bcmills commented Sep 8, 2020

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

@bcmills
Copy link
Contributor Author

bcmills commented Feb 9, 2021

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

@bcmills
Copy link
Contributor Author

bcmills commented Feb 19, 2021

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
3 participants
@rsc @FiloSottile @bcmills