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

crypto/tls: test is flaky on Dragonfly builder #29583

Closed
timdarbydotnet opened this issue Jan 5, 2019 · 16 comments
Closed

crypto/tls: test is flaky on Dragonfly builder #29583

timdarbydotnet opened this issue Jan 5, 2019 · 16 comments
Labels
FrozenDueToAge help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Dragonfly Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone

Comments

@timdarbydotnet
Copy link

timdarbydotnet commented Jan 5, 2019

tracefile.zip

What version of Go are you using (go version)?

1.11

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

DragonflyBSD amd64

What did you do?

The Dragonfly builder sporadically fails on the crypto/tls test. This is a recent example:
https://build.golang.org/log/820d1356dcba0a2db4f1397b513f9ab4b744ed14

I ran this test manually enough times to get it to fail:
bin/go test -count 1 crypto/tls -test.timeout 120s -test.trace tracefile

--- FAIL: TestServerResumptionDisabled (0.00s)
    --- FAIL: TestServerResumptionDisabled/TLSv12#01 (0.00s)
        handshake_test.go:250: Failed to dial local connection: dial tcp 127.0.0.1:62744: connect: connection refused
panic: test timed out after 2m0s

goroutine 623 [running]:
testing.(*M).startAlarm.func1()
        /home/tim/go/src/testing/testing.go:1331 +0xdf
created by time.goFunc
        /home/tim/go/src/time/sleep.go:169 +0x44

goroutine 1 [chan receive, 1 minutes]:
testing.(*T).Run(0xc000597200, 0x781326, 0x10, 0x79d4c0, 0x4a3400)
        /home/tim/go/src/testing/testing.go:914 +0x37e
testing.runTests.func1(0xc00010a000)
        /home/tim/go/src/testing/testing.go:1154 +0x78
testing.tRunner(0xc00010a000, 0xc0000cbd90)
        /home/tim/go/src/testing/testing.go:862 +0xc0
testing.runTests(0xc00000f4a0, 0x9fd240, 0x7f, 0x7f, 0x0)
        /home/tim/go/src/testing/testing.go:1152 +0x2a9
testing.(*M).Run(0xc000104000, 0x0)
        /home/tim/go/src/testing/testing.go:1069 +0x162
crypto/tls.TestMain(0xc000104000)
        /home/tim/go/src/crypto/tls/handshake_test.go:266 +0x166
main.main()
        _testmain.go:300 +0x13e

goroutine 377 [chan receive, 1 minutes]:
testing.(*T).Parallel(0xc00010a600)
        /home/tim/go/src/testing/testing.go:767 +0x1d9
crypto/tls.TestHandshakeRace(0xc00010a600)
        /home/tim/go/src/crypto/tls/handshake_client_test.go:1720 +0x35
testing.tRunner(0xc00010a600, 0x79d600)
        /home/tim/go/src/testing/testing.go:862 +0xc0
created by testing.(*T).Run
        /home/tim/go/src/testing/testing.go:913 +0x357

goroutine 620 [chan receive, 1 minutes]:
testing.tRunner.func1(0xc000597200)
        /home/tim/go/src/testing/testing.go:838 +0x1f5
testing.tRunner(0xc000597200, 0x79d4c0)
        /home/tim/go/src/testing/testing.go:866 +0xca
created by testing.(*T).Run
        /home/tim/go/src/testing/testing.go:913 +0x357

goroutine 622 [IO wait, 1 minutes]:
internal/poll.runtime_pollWait(0x800ccefc8, 0x72, 0x0)
        /home/tim/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000104098, 0x72, 0x0, 0x0, 0x77e644)
        /home/tim/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
        /home/tim/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000104080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/tim/go/src/internal/poll/fd_unix.go:384 +0x1ba
net.(*netFD).accept(0xc000104080, 0xc0001fa900, 0xc000034f98, 0x66d9c0)
        /home/tim/go/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc000010038, 0xc00005b680, 0x571b9, 0x253812a1)
        /home/tim/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc000010038, 0x77e225, 0xc0004b2a80, 0x77e44c, 0x4a3416)
        /home/tim/go/src/net/tcpsock.go:260 +0x48
crypto/tls.localPipe.func1(0x801720, 0xc000597300, 0xc000254420)
        /home/tim/go/src/crypto/tls/handshake_test.go:241 +0x41
created by crypto/tls.localPipe
        /home/tim/go/src/crypto/tls/handshake_test.go:240 +0xde

goroutine 621 [chan receive, 1 minutes]:
crypto/tls.localPipe(0x801720, 0xc000597300, 0x0, 0x0, 0x0, 0x0)
        /home/tim/go/src/crypto/tls/handshake_test.go:252 +0x2b2
crypto/tls.(*serverTest).run(0xc0004b2af0, 0xc000597300, 0x0)
        /home/tim/go/src/crypto/tls/handshake_server_test.go:654 +0x1298
crypto/tls.runServerTestForVersion.func1(0xc000597300)
        /home/tim/go/src/crypto/tls/handshake_server_test.go:760 +0x263
testing.tRunner(0xc000597300, 0xc000152570)
        /home/tim/go/src/testing/testing.go:862 +0xc0
created by testing.(*T).Run
        /home/tim/go/src/testing/testing.go:913 +0x357

goroutine 641 [chan send, 1 minutes]:
crypto/tls.localPipe.func1(0x801720, 0xc0005a4000, 0xc000182960)
        /home/tim/go/src/crypto/tls/handshake_test.go:245 +0x124
created by crypto/tls.localPipe
        /home/tim/go/src/crypto/tls/handshake_test.go:240 +0xde
FAIL    crypto/tls      120.066s
@agnivade agnivade added Testing An issue that has been verified to require only test changes, not just a test failure. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. help wanted labels Jan 6, 2019
@agnivade agnivade added this to the Unplanned milestone Jan 6, 2019
@bcmills
Copy link
Member

bcmills commented May 6, 2019

Still flaky (https://build.golang.org/log/09ba39e75f0d2358b18a04f51d5064e53c3796db):

--- FAIL: TestGetConfigForClient (0.00s)
    handshake_test.go:250: Failed to dial local connection: dial tcp 127.0.0.1:55944: connect: connection refused
panic: test timed out after 3m0s

goroutine 668 [running]:
testing.(*M).startAlarm.func1()
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:1380 +0xdf
created by time.goFunc
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/time/sleep.go:169 +0x44

goroutine 1 [chan receive, 2 minutes]:
testing.(*T).Run(0xc0001ac000, 0x79b7c2, 0x25, 0x7b02a0, 0x4b4b00)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:964 +0x377
testing.runTests.func1(0xc00012a000)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:1205 +0x78
testing.tRunner(0xc00012a000, 0xc0000f7da8)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:912 +0xbf
testing.runTests(0xc00009f3e0, 0x9f8600, 0x81, 0x81, 0x0)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:1203 +0x2a7
testing.(*M).Run(0xc000126000, 0x0)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:1120 +0x160
crypto/tls.TestMain(0xc000126000)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_test.go:266 +0x11f
main.main()
	_testmain.go:304 +0x135

goroutine 358 [chan receive, 2 minutes]:
testing.(*T).Parallel(0xc0004b4100)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:817 +0x1d5
crypto/tls.TestHandshakeRace(0xc0004b4100)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_client_test.go:1720 +0x32
testing.tRunner(0xc0004b4100, 0x7b04c8)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:912 +0xbf
created by testing.(*T).Run
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:963 +0x350

goroutine 676 [IO wait, 2 minutes]:
internal/poll.runtime_pollWait(0x800cd3128, 0x72, 0x4bb555)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc000126098, 0x72, 0x0, 0x0, 0x78ea91)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/internal/poll/fd_poll_runtime.go:87 +0x10b
internal/poll.(*pollDesc).waitRead(...)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000126080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/internal/poll/fd_unix.go:384 +0x1b6
net.(*netFD).accept(0xc000126080, 0xc00035d288, 0xc00035d338, 0xc0003bed18)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc00009f3c0, 0xc000394d20, 0xc0004e1fa8, 0x1)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/net/tcpsock_posix.go:140 +0x32
net.(*TCPListener).Accept(0xc00009f3c0, 0xc0004e1fa8, 0xc0000ac100, 0x0, 0x0)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/net/tcpsock.go:261 +0x47
crypto/tls.localPipe.func1(0x813a40, 0xc0001ac000, 0xc0000869c0)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_test.go:241 +0x41
created by crypto/tls.localPipe
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_test.go:240 +0xe5

goroutine 662 [chan receive, 2 minutes]:
testing.(*T).Parallel(0xc00032ce00)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:817 +0x1d5
crypto/tls.TestClientAuth(0xc00032ce00)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_server_test.go:1394 +0xaad
testing.tRunner(0xc00032ce00, 0x7b0260)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:912 +0xbf
created by testing.(*T).Run
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:963 +0x350

goroutine 645 [chan send, 2 minutes]:
crypto/tls.localPipe.func1(0x813a40, 0xc0001ad700, 0xc000182c60)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_test.go:245 +0x124
created by crypto/tls.localPipe
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_test.go:240 +0xe5

goroutine 675 [chan receive, 2 minutes]:
crypto/tls.localPipe(0x813a40, 0xc0001ac000, 0x0, 0x0, 0x0, 0x0)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_test.go:252 +0x260
crypto/tls.TestCloseServerConnectionOnIdleClient(0xc0001ac000)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/crypto/tls/handshake_server_test.go:1673 +0x4c
testing.tRunner(0xc0001ac000, 0x7b02a0)
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:912 +0xbf
created by testing.(*T).Run
	/tmp/workdir-host-dragonfly-amd64-tdfbsd/go/src/testing/testing.go:963 +0x350
FAIL	crypto/tls	180.058s

@bcmills
Copy link
Member

bcmills commented May 6, 2019

CC @FiloSottile

@bcmills
Copy link
Member

bcmills commented May 14, 2019

@bcmills
Copy link
Member

bcmills commented May 30, 2019

@bcmills
Copy link
Member

bcmills commented Jun 26, 2019

@bcmills bcmills modified the milestones: Unplanned, Go1.14 Jun 26, 2019
@gopherbot
Copy link

Change https://golang.org/cl/184157 mentions this issue: crypto/tls: deflake localPipe in tests

@bcmills bcmills reopened this Jul 3, 2019
@bcmills
Copy link
Member

bcmills commented Jul 3, 2019

@tdfbsd notes that there have been two more flakes after the attempted fix:
https://build.golang.org/log/29e7d70e8cbd4a8e8bc14c6308f0c7e138c5a834
https://build.golang.org/log/4c58fec3a432f4f3f5b49b819c32d2cfff46647f

@bcmills
Copy link
Member

bcmills commented Aug 13, 2019

@bcmills
Copy link
Member

bcmills commented Aug 22, 2019

@bcmills
Copy link
Member

bcmills commented Oct 21, 2019

https://build.golang.org/log/f558b293b29ffb96eeec7919c1e331433f5b8404

--- FAIL: TestHandshakeServerSNIGetCertificateError (0.00s)
    handshake_test.go:259: localPipe: dial tcp 127.0.0.1:62816: connect: connection refused
FAIL
FAIL	crypto/tls	1.459s

All of these flakes seem to feature a connection refused from localPipe.

@bcmills bcmills modified the milestones: Unplanned, Go1.14 Oct 21, 2019
@bcmills bcmills self-assigned this Oct 21, 2019
@bcmills
Copy link
Member

bcmills commented Oct 21, 2019

I'm fed up with this flake. I'll send a workaround. 😤

@gopherbot
Copy link

Change https://golang.org/cl/202557 mentions this issue: crypto/tls: retry net.Dial flakes on Dragonfly

@bcmills bcmills reopened this Nov 12, 2019
@gopherbot
Copy link

Change https://golang.org/cl/206759 mentions this issue: crypto/tls: retry ETIMEDOUT flakes in localPipe on dragonfly

@timdarbydotnet
Copy link
Author

Looping in @tuxillo on this

@golang golang locked and limited conversation to collaborators Nov 11, 2020
@rsc rsc unassigned bcmills Jun 23, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Dragonfly Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
None yet
Development

No branches or pull requests

5 participants