net: TestDialerDualStack fails with "i/o timeout" or "got 5.81849453s; want <= 95ms" #13324

mdempsky · 2015-11-19T08:23:37Z

TestDialerDualStack is commonly flaking on OpenBSD and Windows, albeit with different error messages:

https://www.google.com/search?q=TestDialerDualStack+openbsd+site%3Abuild.golang.org

--- FAIL: TestDialerDualStack (14.78s)
    dial_test.go:633: got 5.81849453s; want <= 95ms

https://www.google.com/search?q=TestDialerDualStack+windows+site%3Abuild.golang.org

--- FAIL: TestDialerDualStack (5.30s)
    dial_test.go:664: dial tcp 127.0.0.1:2651: i/o timeout

The text was updated successfully, but these errors were encountered:

mikioh · 2016-05-19T07:32:45Z

This looks different from #15316, #15574. It happened on active open side, and it took 5s for a simple dial call, strange.

mikioh · 2016-05-19T07:55:46Z

Funny, I got "PASS: TestDialerDualStack (5.99s)" when I ran TestDialerDualStack on openbsd59-vm like the following:

go test -run=TestDialerDualStack$ -v -count=100 net
=== RUN   TestDialerDualStack
--- PASS: TestDialerDualStack (0.00s)
(snip)
=== RUN   TestDialerDualStack
--- PASS: TestDialerDualStack (5.99s)
=== RUN   TestDialerDualStack
--- PASS: TestDialerDualStack (0.00s)
=== RUN   TestDialerDualStack
PASS
Socket statistical information:
(inet4, stream, default): opened=900 connected=200 listened=300 accepted=0 closed=900 openfailed=0 connectfailed=400 listenfailed=0 acceptfailed=0 closefailed=0
(inet6, stream, default): opened=400 connected=200 listened=200 accepted=50 closed=450 openfailed=0 connectfailed=0 listenfailed=0 acceptfailed=100 closefailed=0

and this is not related to runtime/GC stuff because I got the same result when GOGC=off.

mikioh · 2016-05-19T08:07:49Z

Hm,

openbsd-amd64:~/$ go test -run=DualStack$ -count=50 net
ok      net     6.042s
openbsd-amd64:~/$ go test -run=DualStack$ -count=100 net
ok      net     18.048s

dragonfly-amd64:~/$ go test -run=DualStack$ -count=50 net
ok      net 0.075s
dragonfly-amd64:~/$ go test -run=DualStack$ -count=100 net
ok      net 1.136s

bradfitz · 2016-05-20T17:09:55Z

Another on windows-386:
https://storage.googleapis.com/go-build-log/d93c922c/windows-386-gce_fb3d6a91.log

adg · 2016-06-27T22:21:36Z

cc @aclements, would you please run your failure analysis tool against this?

aclements · 2016-06-28T00:03:21Z

I'm not sure what I'm looking for. This test has been failing all over the place for a long time:

$ greplogs -dashboard -E "FAIL: TestDialerDualStack" -md -l
2015-04-10T04:08:10-cb6e9ec/freebsd-386-gce101
2015-04-11T19:36:19-75c0566/openbsd-386-gce56
2015-04-12T02:41:36-684473d/openbsd-386-gce56
2015-04-13T11:58:03-0a81d31/linux-amd64-race
2015-04-14T15:45:26-24f246c/openbsd-386-gce56
2015-04-16T13:31:16-8262a8f/linux-amd64-noopt
2015-04-20T20:46:06-e7ffafd/openbsd-386-gce56
...
2016-05-11T17:07:24-20e362d/dragonfly-amd64
2016-05-11T17:37:55-2ffb3e5/freebsd-amd64-gce101
2016-05-12T15:58:30-376e641/linux-amd64-sid
2016-05-14T17:21:52-094afe0/windows-386-gce
2016-05-15T05:21:03-0bc14f5/freebsd-amd64-race
2016-05-18T01:24:02-f962e6e/linux-386-387
2016-05-21T01:30:43-1f8d276/freebsd-arm-paulzhol
2016-06-02T00:22:03-3c6b668/darwin-386-10_10
2016-06-14T22:50:09-68697a3/freebsd-arm-paulzhol

This is scattered enough that findflakes doesn't know what to make of it. Limiting it to just "i/o timeout" or "want <=" doesn't help.

bradfitz · 2016-07-16T23:59:20Z

Sent https://go-review.googlesource.com/24985 to demote this to a flaky test for Go 1.7. Kicking this bug down the road to Go 1.8.

It would be great if somebody (@mikioh?) could investigate this.

gopherbot · 2016-07-17T00:00:16Z

CL https://golang.org/cl/24985 mentions this issue.

Only run TestDialerDualStack on the builders, as to not annoy or otherwise distract users when it's not their fault. Even though the intention is to only run this on the builders, very few of the builders have IPv6 support. Oh well. We'll get some coverage. Updates #13324 Change-Id: I13e7e3bca77ac990d290cabec88984cc3d24fb67 Reviewed-on: https://go-review.googlesource.com/24985 Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Mikio Hara <mikioh.mikioh@gmail.com>

mikioh · 2016-07-17T01:50:08Z

Not sure if I have a spare time for this issue. FWIW, the root cause of this bug probably may lie down on the protocol stack inside kernel (IP protocol control block bookkeepers and IO event notifiers), the runtime package (are we missing some important thing on epoll/kevent usage?), or the net package (are we testing it in the wrong direction?). The first analysis would just dissect the timeout TCP connection, by scraping the TCP information inside the kernel out.

bradfitz · 2017-03-23T03:55:13Z

And Darwin.

I'm going to disable the test. It's not proving its worth.

gopherbot · 2017-03-23T04:00:45Z

CL https://golang.org/cl/38459 mentions this issue.

It was already marked flaky for everything but the dashboard. Remove that restriction. It's just flaky overall. It's doing more harm than good. Updates #13324 Change-Id: I36feff32a1b8681e77700f74b9c70cb4073268eb Reviewed-on: https://go-review.googlesource.com/38459 Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Josh Bleecher Snyder <josharian@gmail.com>

aclements · 2017-10-30T17:25:47Z

TestDialerDualStackFDLeak also seems to have this problem. I've been getting flakes on linux-amd64-race trybots quite frequently:

https://storage.googleapis.com/go-build-log/3094b3f1/linux-amd64-race_18817780.log
https://storage.googleapis.com/go-build-log/df0c07ba/linux-amd64-race_3321a7c9.log
https://storage.googleapis.com/go-build-log/5b493727/linux-amd64-race_6fb1b8cf.log
https://storage.googleapis.com/go-build-log/31f48fb7/linux-amd64-race_22590734.log

gopherbot · 2017-12-08T15:09:49Z

Change https://golang.org/cl/82916 mentions this issue: net: increase timeout for TestDialerDualStackFDLeak

ianlancetaylor · 2017-12-08T15:10:07Z

Sent https://golang.org/cl/82916 for the TestDialerDualStackFDLeak failures. Dropping the releaseblocker label and moving to unplanned.

This test has been getting occasional timeouts on the race builder. The point of the test is whether a file descriptor leaks, not whether the connection occurs in a certain amount of time. So use a very large timeout. The connection is normally fast and the timeout doesn't matter. Updates #13324 Change-Id: Ie1051c4a0be1fca4e63b1277101770be0cdae512 Reviewed-on: https://go-review.googlesource.com/82916 Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

mdempsky added OS-OpenBSD OS-Windows labels Nov 19, 2015

mdempsky added this to the Go1.7 milestone Nov 19, 2015

mdempsky mentioned this issue Apr 12, 2016

net: TestDialerDualStackFDLeak i/o timeout #14717

Closed

mikioh added the Testing An issue that has been verified to require only test changes, not just a test failure. label May 11, 2016

mikioh changed the title ~~net: TestDialerDualStack flaky on OpenBSD and Windows~~ net: TestDialerDualStack fails with "i/o timeout" or "got 5.81849453s; want <= 95ms" May 19, 2016

mikioh modified the milestones: Go1.7Maybe, Go1.7 May 19, 2016

adg assigned mikioh and unassigned mikioh Jun 27, 2016

bradfitz modified the milestones: Go1.8, Go1.7Maybe Jul 16, 2016

quentinmit added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 7, 2016

rsc modified the milestones: Go1.9, Go1.8 Nov 11, 2016

broady modified the milestones: Go1.9Maybe, Go1.9 Jul 17, 2017

bradfitz modified the milestones: Go1.9Maybe, Go1.10 Jul 20, 2017

ianlancetaylor added the release-blocker label Oct 30, 2017

ianlancetaylor removed the release-blocker label Dec 8, 2017

ianlancetaylor modified the milestones: Go1.10, Unplanned Dec 8, 2017

net: TestDialerDualStack fails with "i/o timeout" or "got 5.81849453s; want <= 95ms" #13324

net: TestDialerDualStack fails with "i/o timeout" or "got 5.81849453s; want <= 95ms" #13324

mdempsky commented Nov 19, 2015

mikioh commented May 19, 2016

mikioh commented May 19, 2016

mikioh commented May 19, 2016

bradfitz commented May 20, 2016

adg commented Jun 27, 2016

aclements commented Jun 28, 2016 •

edited

bradfitz commented Jul 16, 2016

gopherbot commented Jul 17, 2016

mikioh commented Jul 17, 2016

bradfitz commented Mar 23, 2017

gopherbot commented Mar 23, 2017

aclements commented Oct 30, 2017

gopherbot commented Dec 8, 2017

ianlancetaylor commented Dec 8, 2017

net: TestDialerDualStack fails with "i/o timeout" or "got 5.81849453s; want <= 95ms" #13324

net: TestDialerDualStack fails with "i/o timeout" or "got 5.81849453s; want <= 95ms" #13324

Comments

mdempsky commented Nov 19, 2015

mikioh commented May 19, 2016

mikioh commented May 19, 2016

mikioh commented May 19, 2016

bradfitz commented May 20, 2016

adg commented Jun 27, 2016

aclements commented Jun 28, 2016 • edited

bradfitz commented Jul 16, 2016

gopherbot commented Jul 17, 2016

mikioh commented Jul 17, 2016

bradfitz commented Mar 23, 2017

gopherbot commented Mar 23, 2017

aclements commented Oct 30, 2017

gopherbot commented Dec 8, 2017

ianlancetaylor commented Dec 8, 2017

aclements commented Jun 28, 2016 •

edited