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

net/nettest: TestPipeTimeout occasional failure on Windows #873

Closed
bradfitz opened this issue Oct 29, 2020 · 8 comments
Closed

net/nettest: TestPipeTimeout occasional failure on Windows #873

bradfitz opened this issue Oct 29, 2020 · 8 comments
Assignees
@peske
Labels
L2 Few Likelihood OS-windows P2 Aggravating Priority level T7 Build/test failure Issue type

Comments

@bradfitz
Copy link
Member

@crawshaw, any idea?

panic: test timed out after 10m0s

goroutine 5 [running]:
testing.(*M).startAlarm.func1()
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1618 +0xe6
created by time.goFunc
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/time/sleep.go:167 +0x4b

goroutine 1 [chan receive]:
testing.(*T).Run(0xc0000c0600, 0x10f0b7a, 0xf, 0x10fa3b0, 0x101d401)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1169 +0x2da
testing.runTests.func1(0xc0000c0180)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1439 +0x7f
testing.tRunner(0xc0000c0180, 0xc0000b9de0)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1123 +0xef
testing.runTests(0xc00008a4a0, 0x11d8980, 0x3, 0x3, 0xbfdee7ca89b87870, 0x8bb352e705, 0x11dc700, 0xf9e010)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1437 +0x310
testing.(*M).Run(0xc0000e8000, 0x0)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1345 +0x1f5
main.main()
	_testmain.go:47 +0x145

goroutine 20 [chan receive]:
testing.(*T).Run(0xc0000c0c00, 0x10efc16, 0xb, 0x10fa3a0, 0x49f0d4fc01)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1169 +0x2da
tailscale.com/net/nettest.TestPipeTimeout(0xc0000c0600)
	D:/a/tailscale/tailscale/net/nettest/pipe_test.go:59 +0xb5
testing.tRunner(0xc0000c0600, 0x10fa3b0)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1123 +0xef
created by testing.(*T).Run
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1168 +0x2b3

goroutine 23 [chan receive]:
tailscale.com/net/nettest.(*Pipe).Write(0xc0000f21b0, 0xc00003bf37, 0x0, 0x0, 0x1, 0x0, 0x0)
	D:/a/tailscale/tailscale/net/nettest/pipe.go:122 +0x231
tailscale.com/net/nettest.TestPipeTimeout.func3(0xc0000c0c00)
	D:/a/tailscale/tailscale/net/nettest/pipe_test.go:68 +0x229
testing.tRunner(0xc0000c0c00, 0x10fa3a0)
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1123 +0xef
created by testing.(*T).Run
	C:/hostedtoolcache/windows/go/1.15.3/x64/src/testing/testing.go:1168 +0x2b3
FAIL	tailscale.com/net/nettest	600.032s
@bradfitz bradfitz added the T7 Build/test failure Issue type label Oct 29, 2020
@bradfitz bradfitz added L2 Few Likelihood P2 Aggravating Priority level labels Dec 1, 2020
@bradfitz bradfitz mentioned this issue Dec 19, 2020
Closed
@bradfitz
Copy link
Member Author

/cc @josharian

@josharian
Copy link
Contributor

I can't reproduce here after 50k runs, so it does seem to be Windows-only.

But there's no Windows-specific code (or OS-specific code) I see anywhere in that package. That's quite disconcerting.

Can anyone running Windows reproduce locally, or is this GitHub-only?

@alexbrainman
Copy link
Contributor

Can anyone running Windows reproduce locally, or is this GitHub-only?

@josharian I just run this:

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test tailscale.com/net/netstat
ok      tailscale.com/net/netstat       0.097s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=10 tailscale.com/net/netstat
ok      tailscale.com/net/netstat       0.083s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=100 tailscale.com/net/netstat
ok      tailscale.com/net/netstat       0.137s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=1000 tailscale.com/net/netstat
ok      tailscale.com/net/netstat       0.879s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=5000 tailscale.com/net/netstat
ok      tailscale.com/net/netstat       3.921s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=50000 tailscale.com/net/netstat
ok      tailscale.com/net/netstat       32.000s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>

Am I doing it correctly?

Alex

@josharian
Copy link
Contributor

Thanks, @alexbrainman. Would you test tailscale.com/net/nettest (instead of tailscale.com/net/netstat)? (I'm also debugging indirectly over at #1141.)

@alexbrainman
Copy link
Contributor

Would you test tailscale.com/net/nettest (instead of tailscale.com/net/netstat)?

Oops.

Still passes here against your #1141

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=1000 -timeout=45s tailscale.com/net/nettest
ok      tailscale.com/net/nettest       21.520s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=1000 -timeout=45s tailscale.com/net/nettest
ok      tailscale.com/net/nettest       21.797s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=1000 -timeout=45s tailscale.com/net/nettest
ok      tailscale.com/net/nettest       21.800s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>go test -count=10000 -timeout=450s tailscale.com/net/nettest
ok      tailscale.com/net/nettest       244.228s

c:\Users\Alex\dev\src\github.com\tailscale\tailscale>

@josharian
Copy link
Contributor

Thanks, Alex. Sadly, my #1141 also keeps passing. :(

@josharian
Copy link
Contributor

I have a theory: Windows has low resolution timers. We expect a timeout here:

		timedout := !p.writeTimeout.IsZero() && time.Now().After(p.writeTimeout)

but we don't get it, because time.Now == p.writeTimeout. Fix is !time.Now().Before(p.writeTimeout).

Testing out that theory...

josharian added a commit that referenced this issue Jan 16, 2021
@josharian
net/nettest: de-flake tests on Windows
1813816 
Windows has a low resolution timer.
Some of the tests assumed that unblock takes effect immediately.

Consider:

t := time.Now()
elapsed := time.Now().After(t)

It seems plausible that elapsed should always be true.
However, with a low resolution timer, that might fail.

Change time.Now().After to !time.Now().Before,
so that unblocking always takes effect immediately.

Fixes #873.
@josharian
Copy link
Contributor

That was it. Fix and details (and other improvements) in #1141.

@bradfitz bradfitz mentioned this issue Jul 13, 2021
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@peske peske

Labels
L2 Few Likelihood OS-windows P2 Aggravating Priority level T7 Build/test failure Issue type
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@bradfitz @josharian @peske @alexbrainman