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

net: tests using timer fail on macOS High Sierra 10.13 / iOS 11 #22062

Closed
pavel-v-chernykh opened this issue Sep 27, 2017 · 18 comments

Comments

Projects
None yet
8 participants
@pavel-v-chernykh
Copy link

commented Sep 27, 2017

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

go version go1.9 darwin/amd64

Does this issue reproduce with the latest release?

yes

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/pavel/Projects/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.9/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.9/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/jr/3_2b1w35179bs1tn3q7_n90c0000gn/T/go-build741533368=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

What did you do?

Run

$ cd go/src
$ ./all.bash

What did you expect to see?

"ALL TESTS PASSED".

What did you see instead?

$ ./all.bash
...
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 100.514503ms; want <= 95ms
FAIL
FAIL	net	4.328s
...
2017/09/27 10:43:48 Failed: exit status 1

@mikioh mikioh changed the title TestDialerDualStackFDLeak fails on macOS High Sierra net: TestDialerDualStackFDLeak fails on macOS High Sierra Sep 27, 2017

@mikioh mikioh added the OS-Darwin label Sep 27, 2017

@mikioh

This comment has been minimized.

Copy link
Contributor

commented Sep 27, 2017

See https://github.com/golang/go/wiki/Darwin and #22037. I guess that "go test -v -short=false" shows more test failures.

@ianlancetaylor ianlancetaylor added this to the Go1.10 milestone Sep 27, 2017

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Sep 27, 2017

How repeatable is this problem?

@pavel-v-chernykh

This comment has been minimized.

Copy link
Author

commented Sep 27, 2017

Not a single success for this test since the update to High Sierra.
Have run it ten times in a row recently, no success.

P/g/s/g/go/src (master) $ for i in (seq 10); go tool dist test  -run=go_test:net\$; end


##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (1.11s)
	dial_test.go:90: got 100.711025ms; want <= 95ms
FAIL
FAIL	net	3.857s
2017/09/27 17:46:06 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 100.658145ms; want <= 95ms
FAIL
FAIL	net	2.339s
2017/09/27 17:46:12 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 100.309476ms; want <= 95ms
FAIL
FAIL	net	3.941s
2017/09/27 17:46:19 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 101.246644ms; want <= 95ms
FAIL
FAIL	net	4.513s
2017/09/27 17:46:27 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 101.112404ms; want <= 95ms
FAIL
FAIL	net	4.176s
2017/09/27 17:46:35 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (2.01s)
	dial_test.go:90: got 1.004516011s; want <= 95ms
FAIL
FAIL	net	5.929s
2017/09/27 17:46:45 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 100.524832ms; want <= 95ms
FAIL
FAIL	net	3.946s
2017/09/27 17:46:52 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (2.01s)
	dial_test.go:90: got 1.001501156s; want <= 95ms
FAIL
FAIL	net	5.953s
2017/09/27 17:47:02 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 100.817715ms; want <= 95ms
FAIL
FAIL	net	2.171s
2017/09/27 17:47:08 Failed: exit status 1

##### Testing packages.
--- FAIL: TestDialerDualStackFDLeak (0.20s)
	dial_test.go:90: got 101.123833ms; want <= 95ms
FAIL
FAIL	net	4.018s
2017/09/27 17:47:15 Failed: exit status 1

Kernel info

$ uname -a
Darwin mbp 17.0.0 Darwin Kernel Version 17.0.0: Thu Aug 24 21:48:19 PDT 2017; root:xnu-4570.1.46~2/RELEASE_X86_64 x86_64
@mikioh

This comment has been minimized.

Copy link
Contributor

commented Sep 28, 2017

Okay, my friend kindly sent me the result of "cd $GOROOT/src/net; go test -short=false -count=10" on macOS High Sierra 10.13.

--- FAIL: TestDialerDualStackFDLeak (0.42s)
	dial_test.go:90: got 211.099986ms; want <= 95ms
--- FAIL: TestDialParallel (1.83s)
	dial_test.go:201: got 211.118921ms; want <= 95ms
	dial_test.go:323: #6: got 101.872119ms; want >= 116.118921ms
	dial_test.go:323: #7: got 300.99846ms; want >= 316.118921ms
	dial_test.go:323: #9: got 101.785746ms; want >= 105ms
--- FAIL: TestDialerDualStackFDLeak (0.21s)
	dial_test.go:90: got 101.101089ms; want <= 95ms
--- FAIL: TestDialParallel (1.31s)
	dial_test.go:201: got 101.007812ms; want <= 95ms
--- FAIL: TestDialerDualStackFDLeak (0.21s)
	dial_test.go:90: got 100.969161ms; want <= 95ms
--- FAIL: TestDialParallel (1.30s)
	dial_test.go:201: got 100.228108ms; want <= 95ms
--- FAIL: TestDialerDualStackFDLeak (0.21s)
	dial_test.go:90: got 100.699773ms; want <= 95ms
--- FAIL: TestDialParallel (1.31s)
	dial_test.go:201: got 101.268161ms; want <= 95ms
--- FAIL: TestDialTimeout (1.20s)
	timeout_test.go:81: #7: Dial didn't return in an expected time
--- FAIL: TestDialerDualStackFDLeak (0.21s)
	dial_test.go:90: got 100.159207ms; want <= 95ms
--- FAIL: TestDialParallel (1.31s)
	dial_test.go:201: got 101.191819ms; want <= 95ms
--- FAIL: TestDialParallel (0.80s)
	dial_test.go:325: #6: got 102.484699ms; want <= 95.122372ms
	dial_test.go:325: #7: got 303.135013ms; want <= 295.122372ms
	dial_test.go:325: #9: got 101.71373ms; want <= 95.122372ms
--- FAIL: TestDialParallel (0.81s)
	dial_test.go:325: #6: got 102.653457ms; want <= 95.06071ms
	dial_test.go:325: #7: got 305.540876ms; want <= 295.06071ms
	dial_test.go:325: #9: got 103.048016ms; want <= 95.06071ms

(snip)

FAIL
exit status 1
FAIL	net	313.890s

@mikioh mikioh changed the title net: TestDialerDualStackFDLeak fails on macOS High Sierra net: tests using timer fail on macOS High Sierra Sep 28, 2017

@onehr

This comment has been minimized.

Copy link

commented Sep 28, 2017

got the same problem, using macOS High Sierra.

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Sep 28, 2017

As @mikioh suggested, I bet this is a dup of #22037. I don't think we need spend time investigating this until #22037 is fixed.

@pavel-v-chernykh

This comment has been minimized.

Copy link
Author

commented Sep 28, 2017

Look like on iOS there was the same issue 90fdc45

@mikioh mikioh changed the title net: tests using timer fail on macOS High Sierra net: tests using timer fail on macOS High Sierra 10.13 / iOS 11 Sep 29, 2017

@rasky

This comment has been minimized.

Copy link
Member

commented Sep 30, 2017

FWIW, my patch for #22037 doesn't fix this bug. Also, if my understanding of that bug is correct, High Sierra only broke Go's real timer, not monotonic timer; the failures in these tests look like results of measures that are computed using the monotonic timer (time.Now + time.Sub or time.Since).

@bmerrill42

This comment has been minimized.

Copy link
Contributor

commented Sep 30, 2017

the dial_test.go looks like it's not detecting the right architecture

	if runtime.GOOS == "windows" {
		expected = 1500 * time.Millisecond
	} else if runtime.GOOS == "darwin" && (runtime.GOARCH == "arm" || runtime.GOARCH == "arm64") {
		expected = 150 * time.Millisecond
	} else {
		expected = 95 * time.Millisecond
	}

when I add amd64 to the else if it works just fine since the response is never below 95ms

@gopherbot

This comment has been minimized.

Copy link

commented Sep 30, 2017

Change https://golang.org/cl/67350 mentions this issue: net: inside dial_test.go added amd64 architecture to the 150ms expected dialing closed port

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Oct 3, 2017

I guess everyone else is up to speed on this, but I'll note that we bumped the timeout on iOS in https://golang.org/cl/66491 because the test started failing on iOS 11. These failures do look very similar, so it appears that new versions of Darwin have introduced some sort of 100ms or 50ms timeout for some reason.

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Oct 13, 2017

Reopening to consider backporting CL 67350 to 1.9.2 to avoid unhelpful test failures on MacOS High Sierra.

CC @rsc

@ianlancetaylor ianlancetaylor modified the milestones: Go1.10, Go1.9.2 Oct 13, 2017

@ianlancetaylor ianlancetaylor added Testing and removed NeedsFix labels Oct 13, 2017

@rsc

This comment has been minimized.

Copy link
Contributor

commented Oct 13, 2017

CL 66491 OK for Go 1.9.2.
CL 67350 OK for Go 1.9.2.
Does this also need fixing in Go 1.8.5?

@rsc rsc added the release-blocker label Oct 13, 2017

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Oct 13, 2017

High Sierra hasn't been released yet, so I'm OK with telling people using an unreleased OS that they need to be using the newest Go release. And if we get Go 1.10 out before High Sierra is officially released then 1.8 will no longer be supported.

But the fix is simple and safe so it's fine with me if we put it into 1.8.5.

@rsc

This comment has been minimized.

Copy link
Contributor

commented Oct 15, 2017

The CL pair appears to apply to Go 1.8.4 cleanly and is restricted to the tests, so I will include it while we have the fix paged in.

@gopherbot

This comment has been minimized.

Copy link

commented Oct 15, 2017

Change https://golang.org/cl/70988 mentions this issue: [release-branch.go1.9] net: increase expected time to dial a closed port on all Darwin ports

@gopherbot

This comment has been minimized.

Copy link

commented Oct 17, 2017

Change https://golang.org/cl/71331 mentions this issue: [release-branch.go1.8] net: increase expected time to dial a closed port on all Darwin ports

gopherbot pushed a commit that referenced this issue Oct 25, 2017

[release-branch.go1.8] net: increase expected time to dial a closed p…
…ort on all Darwin ports

All current darwin architectures seem to take at least 100ms to dial a closed port,
and that was making the all.bash script fail.

Fixes #22062

Change-Id: Ib79c4b7a5db2373c95ce5d993cdcbee55cc0667f
Reviewed-on: https://go-review.googlesource.com/67350
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Reviewed-on: https://go-review.googlesource.com/71331
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>

gopherbot pushed a commit that referenced this issue Oct 25, 2017

[release-branch.go1.9] net: increase expected time to dial a closed p…
…ort on all Darwin ports

All current darwin architectures seem to take at least 100ms to dial a closed port,
and that was making the all.bash script fail.

Fixes #22062

Change-Id: Ib79c4b7a5db2373c95ce5d993cdcbee55cc0667f
Reviewed-on: https://go-review.googlesource.com/67350
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Reviewed-on: https://go-review.googlesource.com/70988
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@rsc

This comment has been minimized.

Copy link
Contributor

commented Oct 26, 2017

go1.9.2 has been packaged and includes:

The release is posted at golang.org/dl.

— golang.org/x/build/cmd/releasebot, Oct 26 21:09:19 UTC

@rsc rsc closed this Oct 26, 2017

@golang golang locked and limited conversation to collaborators Oct 26, 2018

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.