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.

Sign up for GitHub

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: 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
Go1.14

Comments

@timdarbydotnet
Copy link

timdarbydotnet commented Jan 5, 2019 •
edited by bcmills

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 bcmills mentioned this issue Jan 9, 2019
Closed
@bcmills
Copy link
Contributor

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
Contributor

bcmills commented May 6, 2019

CC @FiloSottile

@bcmills
Copy link
Contributor

bcmills commented May 14, 2019

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

@bcmills
Copy link
Contributor

bcmills commented May 30, 2019

https://build.golang.org/log/32567fa096cc51f8e4462454909da8c26ef99277

@bcmills
Copy link
Contributor

bcmills commented May 30, 2019 •
edited

https://build.golang.org/log/5f96a0bf3c34f8dddc92f747a3885fac89a0aee3
https://build.golang.org/log/c88e908e85a03e3b3fadb2be7ee45b4135e47f46
https://build.golang.org/log/4233fb9e9319c06dd87fade3b16520d252d7a44f

@bradfitz bradfitz mentioned this issue May 30, 2019
Closed
@bcmills
Copy link
Contributor

bcmills commented Jun 26, 2019

https://build.golang.org/log/0f607d9eb2eeaaec920ebade2300b0aa5d97707d

@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
Contributor

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
Contributor

bcmills commented Aug 13, 2019

https://build.golang.org/log/14f922dabae71d627356edc98d16255b1dc33c37

@bcmills
Copy link
Contributor

bcmills commented Aug 22, 2019

https://build.golang.org/log/338eb5ff0972316e1c4edc7acc66594960798cee

@bcmills bcmills mentioned this issue Sep 3, 2019
Open
@FiloSottile FiloSottile modified the milestones: Go1.14, Unplanned Oct 1, 2019
@bcmills
Copy link
Contributor

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
Contributor

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

bcmills commented Nov 12, 2019 •
edited

Still flaky after my workaround:
2019-11-12T05:35:33-99957b6/dragonfly-amd64
2019-11-07T14:53:38-e8f01d5/dragonfly-amd64
2019-11-07T02:33:31-198f045/dragonfly-amd64
2019-11-05T03:27:26-a866b48/dragonfly-amd64
2019-11-05T00:16:41-4af639a/dragonfly-amd64
2019-11-04T22:50:43-54e6ba6/dragonfly-amd64
2019-10-31T21:47:15-6d02f95/dragonfly-amd64-5_6
2019-10-29T22:00:32-20d621d/dragonfly-amd64-5_6
2019-10-28T19:31:17-18e9cdc/dragonfly-amd64-5_6
2019-10-28T10:25:44-33e3983/dragonfly-amd64-5_6
2019-10-25T03:14:39-8f30d25/dragonfly-amd64
2019-10-24T15:22:31-df01b79/dragonfly-amd64-5_6
2019-10-23T15:04:59-b2df6bf/dragonfly-amd64-5_6
2019-10-23T03:08:00-0195a29/dragonfly-amd64
2019-10-22T20:00:03-8ba43ea/dragonfly-amd64-5_6
2019-10-22T19:35:04-48eb79e/dragonfly-amd64-5_6
2019-10-22T14:26:04-ea726d8/dragonfly-amd64

Probably we need to loosen the condition here to include timeouts:

go/src/crypto/tls/handshake_test.go

Line 278 in 03aca99

if runtime.GOOS == "dragonfly" && isConnRefused(err) {

@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.
Assignees
No one assigned
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
Milestone
Go1.14
Development

No branches or pull requests
5 participants
@FiloSottile @agnivade @bcmills @gopherbot @timdarbydotnet