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: TestReadTimeout flake #14986

Closed
Thomasdezeeuw opened this issue Mar 27, 2016 · 14 comments
Closed

net: TestReadTimeout flake #14986

Thomasdezeeuw opened this issue Mar 27, 2016 · 14 comments
Labels
FrozenDueToAge
Milestone
Go1.7

Comments

@Thomasdezeeuw
Copy link
Contributor

Please answer these questions before submitting your issue. Thanks!

  1. What version of Go are you using (go version)?
    go version devel +4ffa5eb Sun Mar 27 05:31:54 2016 +0000 darwin/amd64.
  2. What operating system and processor architecture are you using (go env)?
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/thomas/go"
GORACE=""
GOROOT="/go/go"
GOTOOLDIR="/go/go/pkg/tool/darwin_amd64"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/lq/rzq0zxld0bb5mcy4jl1txrf00000gn/T/go-build726276125=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
  1. What did you do?
    ran all.bash.
  2. What did you expect to see?
    Successful build.
  3. What did you see instead?

Two build failures, a third build correctly.

First failed test.

--- FAIL: TestReadTimeout (0.18s)
    timeout_test.go:324: accept tcp4 127.0.0.1:55674: use of closed network connection
FAIL
FAIL    net 2.876s

Second build error, with even less information.

FAIL
FAIL    net 2.377s

See attached logs for the complete logs.

build.txt
build2.txt
@bradfitz bradfitz changed the title net: flake building go net: TestReadTimeout flake Mar 27, 2016
@bradfitz
Copy link
Contributor

/cc @mikioh

@mikioh
Copy link
Contributor

mikioh commented Mar 28, 2016

go version devel +4ffa5eb Sun Mar 27 05:31:54 2016 +0000 darwin/amd64

In general, when the runtime or compiler stuff is under heavy development, some tests in the net package usually become unstable because the net package heavily depends on fancy stuff provided by runtime such as read/write semaphores, timers and I/O event notification and scheduling mech. Please ping me when the failure happens after the Go 1.7 development cutoff day.

@bradfitz
Copy link
Contributor

On the contrary, now (earlier) is the time to de-flake tests, and to help find any runtime problems.

@mikioh
Copy link
Contributor

mikioh commented Mar 28, 2016

Well then, @Thomasdezeeuw, can you tell us a bit more details?

  • OS X version

  • of CPU cores on the node under test

If you have a spare time and the failure is reproducible, please run GOTRACEBACK=all go test -v -run=TestReadTimeout$ with the following patch and show us the stack trace.

--- a/src/net/timeout_test.go
+++ b/src/net/timeout_test.go
@@ -321,6 +321,7 @@ func TestReadTimeout(t *testing.T) {
        handler := func(ls *localServer, ln Listener) {
                c, err := ln.Accept()
                if err != nil {
+                       panic(err.Error())
                        t.Error(err)
                        return
                }

If you have more spare time, the trace of kevent by using dtrace would be a great help. See dtrace(1) on OS X. Thanks.

@Thomasdezeeuw
Copy link
Contributor Author

@mikioh OS X version 10.11.3, 4 cores. I'm currently running the test in a loop, but it's been a couple of minutes and no failures yet. I'll report back once it failed. I've never used dtrace before so I'm not sure how to use it. But if you have a simple dtrace command, I'm willing to run it.

@Thomasdezeeuw
Copy link
Contributor Author

An update, I ran GOTRACEBACK=all go test -v -run=TestReadTimeout -count 1000000 -timeout 120m to no avail. I haven't been able to reproduce the error anymore. Any ideas on how I can perhaps trigger it faster?

@Thomasdezeeuw
Copy link
Contributor Author

I updated go and build it from source again, running GOTRACEBACK=all ./all.bash, it failed but without an error again.

# ... (removed)
ok      mime/quotedprintable    0.132s
FAIL
FAIL    net 4.019s
ok      net/http    11.951s
# ... (removed)
ok      cmd/vet 2.100s
2016/04/02 13:13:54 Failed: exit status 1

Is there a reason why GOTRACEBACK doens't get passed to the test command?

The full build log: build3.txt.

@Thomasdezeeuw
Copy link
Contributor Author

I modified run.bash to include GOTRACEBACK=all and I got the following error message:

ok      mime/quotedprintable    0.114s
--- FAIL: TestDialTimeoutMaxDuration (0.10s)
    timeout_test.go:140: #0: Dial didn't return in an expected time
FAIL
FAIL    net 37.869s

@Thomasdezeeuw
Copy link
Contributor Author

Running go test -count 1000 -timeout 120m in go/src/net I got the following error:

panic: accept tcp4 127.0.0.1:52424: use of closed network connection

goroutine 21154 [running]:
panic(0x1f5660, 0xc8204de700)
    /go/go/src/runtime/panic.go:500 +0x18a
net.TestReadTimeout.func1(0xc8201824b0, 0x32eee0, 0xc82002e0e0)
    /go/go/src/net/timeout_test.go:324 +0x13d
net.(*localServer).buildup.func1(0xc82042fcb0, 0xc8201824b0)
    /go/go/src/net/mockserver_test.go:95 +0x38
created by net.(*localServer).buildup
    /go/go/src/net/mockserver_test.go:97 +0x3f
exit status 2
FAIL    net 27.644s

@mikioh
Copy link
Contributor

mikioh commented Apr 3, 2016

@Thomasdezeeuw,

Please let us know which rev. of Go you are using (git rev-parse HEAD). Otherwise, we need to play a guessing game. If you are not confident and have no evidence that the issues you encountered have the same root cause:

  • Please open a new issue for the TestDialTimeoutMaxDuration failure, like "net: TestDialTimeoutMaxDuration fails"
  • Please open a new issue for the "GOTRACEBACK=all ./all.bash, like "net: GOTRACEBACK=all ./all.bash fails without any error notification"

@mikioh
Copy link
Contributor

mikioh commented Apr 3, 2016

Running go test -count 1000 -timeout 120m in go/src/net I got the following error:

Please show us the entire stack trace. Also which rev. of Go?

@Thomasdezeeuw
Copy link
Contributor Author

@mikioh Sorry about that, I'm at ac8d97b6796aad8ca33db9d377064ddb3952a834.

GOTRACEBACK=all go test -count 1000 -timeout 120m
panic: accept tcp4 127.0.0.1:60199: use of closed network connection

goroutine 42062 [running]:
panic(0x1f5660, 0xc82025e0b0)
    /go/go/src/runtime/panic.go:500 +0x18a
net.TestReadTimeout.func1(0xc82026c150, 0x32eee0, 0xc82002e000)
    /go/go/src/net/timeout_test.go:324 +0x13d
net.(*localServer).buildup.func1(0xc820414020, 0xc82026c150)
    /go/go/src/net/mockserver_test.go:95 +0x38
created by net.(*localServer).buildup
    /go/go/src/net/mockserver_test.go:97 +0x3f

goroutine 1 [chan receive]:
testing.tRunner.func1(0xc8201b2e40)
    /go/go/src/testing/testing.go:530 +0x145
testing.tRunner(0xc8201b2e40, 0xc820230e30)
    /go/go/src/testing/testing.go:549 +0x84
testing.RunTests(0x2641d0, 0x34dc20, 0xb1, 0xb1, 0x1049a)
    /go/go/src/testing/testing.go:730 +0x2b6
testing.(*M).Run(0xc820230f08, 0x5a35)
    /go/go/src/testing/testing.go:675 +0x78
net.TestMain(0xc820230f08)
    /go/go/src/net/main_test.go:50 +0x2b
main.main()
    net/_test/_testmain.go:452 +0xb4

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /go/go/src/runtime/asm_amd64.s:2013 +0x1

goroutine 42045 [chan send]:
testing.tRunner.func1(0xc820304240)
    /go/go/src/testing/testing.go:543 +0x1b9
testing.tRunner(0xc820304240, 0x264bc8)
    /go/go/src/testing/testing.go:549 +0x84
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42066 [IO wait]:
net.runtime_pollWait(0x744fd0, 0x77, 0x350880)
    /go/go/src/runtime/netpoll.go:160 +0x4f
net.(*pollDesc).wait(0xc820526370, 0x77, 0x0, 0x0)
    /go/go/src/net/fd_poll_runtime.go:73 +0x2e
net.(*pollDesc).waitWrite(0xc820526370, 0x0, 0x0)
    /go/go/src/net/fd_poll_runtime.go:82 +0x2a
net.(*netFD).connect(0xc820526310, 0x0, 0x0, 0x32de20, 0xc8203ee2c0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /go/go/src/net/fd_unix.go:127 +0x139
net.(*netFD).dial(0xc820526310, 0x32f720, 0x0, 0x32f720, 0xc8201fe570, 0x0, 0x0, 0x0, 0x0, 0xc8204de270, ...)
    /go/go/src/net/sock_posix.go:137 +0x13f
net.socket(0x23375d, 0x3, 0x2, 0x1, 0x0, 0xc8201fe500, 0x32f720, 0x0, 0x32f720, 0xc8201fe570, ...)
    /go/go/src/net/sock_posix.go:89 +0x1fe
net.internetSocket(0x23375d, 0x3, 0x32f720, 0x0, 0x32f720, 0xc8201fe570, 0x0, 0x0, 0x0, 0x1, ...)
    /go/go/src/net/ipsock_posix.go:161 +0x13c
net.dialTCP(0x23375d, 0x3, 0x0, 0xc8201fe570, 0x0, 0x0, 0x0, 0x0, 0xeb14, 0x700960, ...)
    /go/go/src/net/tcpsock_posix.go:51 +0xc3
net.dialSingle(0xc8200dc090, 0x32e660, 0xc8201fe570, 0x0, 0x0, 0x0, 0x0, 0xe, 0x262e8e, 0x262e8f, ...)
    /go/go/src/net/dial.go:445 +0x37d
net.dialSerial.func1(0x0, 0x0, 0x0, 0x53fd5, 0x19f4f8, 0x57010869, 0x1687131)
    /go/go/src/net/dial.go:420 +0x5e
net.dial(0x23375d, 0x3, 0x32e660, 0xc8201fe570, 0xc82023d8e0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /go/go/src/net/fd_unix.go:40 +0x3b
net.dialSerial(0xc8200dc090, 0xc8204de280, 0x1, 0x1, 0x0, 0xf, 0x0, 0x0, 0x0)
    /go/go/src/net/dial.go:422 +0x1df
net.(*Dialer).Dial(0xc82023da40, 0x23375d, 0x3, 0xc8204de260, 0xf, 0x961a8, 0xc8204de250, 0x9, 0xc8204de259)
    /go/go/src/net/dial.go:294 +0x368
net.Dial(0x23375d, 0x3, 0xc8204de260, 0xf, 0xc8204de210, 0xc8204de203, 0xb, 0x0)
    /go/go/src/net/dial.go:246 +0x6e
net.testVariousDeadlines(0xc8203046c0)
    /go/go/src/net/timeout_test.go:913 +0x504
net.TestVariousDeadlines(0xc8203046c0)
    /go/go/src/net/timeout_test.go:810 +0x2f
testing.tRunner(0xc8203046c0, 0x264b98)
    /go/go/src/testing/testing.go:547 +0x7a
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42344 [IO wait]:
net.runtime_pollWait(0x785d00, 0x77, 0x350880)
    /go/go/src/runtime/netpoll.go:160 +0x4f
net.(*pollDesc).wait(0xc820018220, 0x77, 0x0, 0x0)
    /go/go/src/net/fd_poll_runtime.go:73 +0x2e
net.(*pollDesc).waitWrite(0xc820018220, 0x0, 0x0)
    /go/go/src/net/fd_poll_runtime.go:82 +0x2a
net.(*netFD).connect(0xc8200181c0, 0x0, 0x0, 0x32de20, 0xc8203bc060, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /go/go/src/net/fd_unix.go:127 +0x139
net.(*netFD).dial(0xc8200181c0, 0x32f720, 0x0, 0x32f720, 0xc8203aa1b0, 0x0, 0x0, 0x0, 0x0, 0xc82038e060, ...)
    /go/go/src/net/sock_posix.go:137 +0x13f
net.socket(0x23375d, 0x3, 0x2, 0x1, 0x0, 0xc8203aa100, 0x32f720, 0x0, 0x32f720, 0xc8203aa1b0, ...)
    /go/go/src/net/sock_posix.go:89 +0x1fe
net.internetSocket(0x23375d, 0x3, 0x32f720, 0x0, 0x32f720, 0xc8203aa1b0, 0x0, 0x0, 0x0, 0x1, ...)
    /go/go/src/net/ipsock_posix.go:161 +0x13c
net.dialTCP(0x23375d, 0x3, 0x0, 0xc8203aa1b0, 0x0, 0x0, 0x0, 0x0, 0xeb2d, 0x7004b0, ...)
    /go/go/src/net/tcpsock_posix.go:51 +0xc3
net.dialSingle(0xc82035a000, 0x32e660, 0xc8203aa1b0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x262e8e, 0x262e8f, ...)
    /go/go/src/net/dial.go:445 +0x37d
net.dialSerial.func1(0x0, 0x0, 0x0, 0x53fd5, 0x19f4f8, 0x57010869, 0x1af0014)
    /go/go/src/net/dial.go:420 +0x5e
net.dial(0x23375d, 0x3, 0x32e660, 0xc8203aa1b0, 0xc82016ed68, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /go/go/src/net/fd_unix.go:40 +0x3b
net.dialSerial(0xc82035a000, 0xc82038e070, 0x1, 0x1, 0x0, 0xf, 0x0, 0x0, 0x0)
    /go/go/src/net/dial.go:422 +0x1df
net.(*Dialer).Dial(0xc82016eec8, 0x23375d, 0x3, 0xc82038e050, 0xf, 0x961a8, 0xc82038e040, 0x9, 0xc82038e019)
    /go/go/src/net/dial.go:294 +0x368
net.Dial(0x23375d, 0x3, 0xc82038e050, 0xf, 0xc820180060, 0x0, 0x0, 0x0)
    /go/go/src/net/dial.go:246 +0x6e
net.TestAcceptTimeout.func1(0x32eee0, 0xc820490000, 0xc8201b2180)
    /go/go/src/net/timeout_test.go:180 +0xad
created by net.TestAcceptTimeout
    /go/go/src/net/timeout_test.go:188 +0x94e

goroutine 42044 [chan send]:
testing.tRunner.func1(0xc820304180)
    /go/go/src/testing/testing.go:543 +0x1b9
testing.tRunner(0xc820304180, 0x264bd0)
    /go/go/src/testing/testing.go:549 +0x84
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42315 [IO wait]:
net.runtime_pollWait(0x744550, 0x72, 0xc8204de2a8)
    /go/go/src/runtime/netpoll.go:160 +0x4f
net.(*pollDesc).wait(0xc82035e140, 0x72, 0xc820160e78, 0xc820010200)
    /go/go/src/net/fd_poll_runtime.go:73 +0x2e
net.(*pollDesc).waitRead(0xc82035e140, 0x32e0e0, 0xc820010200)
    /go/go/src/net/fd_poll_runtime.go:78 +0x2a
net.(*netFD).Read(0xc82035e0e0, 0xc8204de2a8, 0x1, 0x1, 0x0, 0x32e0e0, 0xc820010200)
    /go/go/src/net/fd_unix.go:259 +0x183
net.(*conn).Read(0xc82017e030, 0xc8204de2a8, 0x1, 0x1, 0x0, 0x0, 0x0)
    /go/go/src/net/net.go:172 +0x63
net.TestReadTimeoutMustNotReturn.func1(0x330200, 0xc82017e030, 0xc8201b2480, 0xc8200cc1e0)
    /go/go/src/net/timeout_test.go:409 +0x1eb
created by net.TestReadTimeoutMustNotReturn
    /go/go/src/net/timeout_test.go:411 +0x230

goroutine 42047 [chan send]:
testing.tRunner.func1(0xc820304480)
    /go/go/src/testing/testing.go:543 +0x1b9
testing.tRunner(0xc820304480, 0x264908)
    /go/go/src/testing/testing.go:549 +0x84
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42288 [runnable]:
syscall.Syscall(0x4, 0x18, 0xc8203bf970, 0x1, 0x1, 0x0, 0x0)
    /go/go/src/syscall/asm_darwin_amd64.s:16 +0x5
syscall.write(0x18, 0xc8203bf970, 0x1, 0x1, 0x77, 0x0, 0x0)
    /go/go/src/syscall/zsyscall_darwin_amd64.go:1360 +0x4b
syscall.Write(0x18, 0xc8203bf970, 0x1, 0x1, 0x34630b89fd8, 0x1441db7c4aadb677, 0x34630b89fd8)
    /go/go/src/syscall/syscall_unix.go:180 +0x3f
net.(*netFD).Write(0xc8201b1420, 0xc8203bf970, 0x1, 0x1, 0x0, 0x0, 0x0)
    /go/go/src/net/fd_unix.go:337 +0x11d
net.(*conn).Write(0xc820490270, 0xc8203bf970, 0x1, 0x1, 0x0, 0x0, 0x0)
    /go/go/src/net/net.go:184 +0x63
net.TestReadWriteProlongedTimeout.func1.2(0xc8203bf960, 0x330200, 0xc820490270, 0xc820404fc0)
    /go/go/src/net/timeout_test.go:1006 +0x14b
created by net.TestReadWriteProlongedTimeout.func1
    /go/go/src/net/timeout_test.go:1013 +0x1c2

goroutine 42305 [chan send]:
testing.tRunner.func1(0xc820405080)
    /go/go/src/testing/testing.go:543 +0x1b9
testing.tRunner(0xc820405080, 0x264960)
    /go/go/src/testing/testing.go:549 +0x84
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42304 [chan receive]:
net.(*localServer).teardown(0xc82014a0c0, 0x0, 0x0)
    /go/go/src/net/mockserver_test.go:107 +0x108
net.TestReadWriteProlongedTimeout(0xc820404fc0)
    /go/go/src/net/timeout_test.go:1036 +0x299
testing.tRunner(0xc820404fc0, 0x264978)
    /go/go/src/testing/testing.go:547 +0x7a
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42343 [chan receive]:
testing.RunTests.func1.1(0xc8201b2e40)
    /go/go/src/testing/testing.go:729 +0x3d
created by testing.RunTests.func1
    /go/go/src/testing/testing.go:729 +0xa7

goroutine 42023 [semacquire]:
sync.runtime_Semacquire(0xc8203bf96c)
    /go/go/src/runtime/sema.go:47 +0x26
sync.(*WaitGroup).Wait(0xc8203bf960)
    /go/go/src/sync/waitgroup.go:127 +0x8c
net.TestReadWriteProlongedTimeout.func1(0xc82014a0c0, 0x32eee0, 0xc82017e000)
    /go/go/src/net/timeout_test.go:1014 +0x1d0
net.(*localServer).buildup.func1(0xc8203bf860, 0xc82014a0c0)
    /go/go/src/net/mockserver_test.go:95 +0x38
created by net.(*localServer).buildup
    /go/go/src/net/mockserver_test.go:97 +0x3f

goroutine 42048 [select]:
net.TestReadFromTimeoutFluctuation(0xc820304540)
    /go/go/src/net/timeout_test.go:753 +0x62b
testing.tRunner(0xc820304540, 0x2648f0)
    /go/go/src/testing/testing.go:547 +0x7a
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42046 [chan send]:
testing.tRunner.func1(0xc8203043c0)
    /go/go/src/testing/testing.go:543 +0x1b9
testing.tRunner(0xc8203043c0, 0x264bd8)
    /go/go/src/testing/testing.go:549 +0x84
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42049 [IO wait]:
net.runtime_pollWait(0x744e50, 0x77, 0x350880)
    /go/go/src/runtime/netpoll.go:160 +0x4f
net.(*pollDesc).wait(0xc8205261b0, 0x77, 0x0, 0x0)
    /go/go/src/net/fd_poll_runtime.go:73 +0x2e
net.(*pollDesc).waitWrite(0xc8205261b0, 0x0, 0x0)
    /go/go/src/net/fd_poll_runtime.go:82 +0x2a
net.(*netFD).connect(0xc820526150, 0x0, 0x0, 0x32de20, 0xc8203ee1a0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /go/go/src/net/fd_unix.go:127 +0x139
net.(*netFD).dial(0xc820526150, 0x32f720, 0x0, 0x32f720, 0xc8201fe3f0, 0x0, 0x0, 0x0, 0x0, 0xc8204de0a0, ...)
    /go/go/src/net/sock_posix.go:137 +0x13f
net.socket(0x23375d, 0x3, 0x2, 0x1, 0x0, 0xc8201fe300, 0x32f720, 0x0, 0x32f720, 0xc8201fe3f0, ...)
    /go/go/src/net/sock_posix.go:89 +0x1fe
net.internetSocket(0x23375d, 0x3, 0x32f720, 0x0, 0x32f720, 0xc8201fe3f0, 0x0, 0x0, 0x0, 0x1, ...)
    /go/go/src/net/ipsock_posix.go:161 +0x13c
net.dialTCP(0x23375d, 0x3, 0x0, 0xc8201fe3f0, 0x0, 0x0, 0x0, 0x0, 0xeb2a, 0x700960, ...)
    /go/go/src/net/tcpsock_posix.go:51 +0xc3
net.dialSingle(0xc8200dc000, 0x32e660, 0xc8201fe3f0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x262e8e, 0x262e8f, ...)
    /go/go/src/net/dial.go:445 +0x37d
net.dialSerial.func1(0x0, 0x0, 0x0, 0x53fd5, 0x19f4f8, 0x57010869, 0x6e68e2)
    /go/go/src/net/dial.go:420 +0x5e
net.dial(0x23375d, 0x3, 0x32e660, 0xc8201fe3f0, 0xc82003cc30, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /go/go/src/net/fd_unix.go:40 +0x3b
net.dialSerial(0xc8200dc000, 0xc8204de0b0, 0x1, 0x1, 0x0, 0xf, 0x0, 0x0, 0x0)
    /go/go/src/net/dial.go:422 +0x1df
net.(*Dialer).Dial(0xc82003cd90, 0x23375d, 0x3, 0xc8204de090, 0xf, 0x961a8, 0xc8204de081, 0x9, 0xc8204de08a)
    /go/go/src/net/dial.go:294 +0x368
net.Dial(0x23375d, 0x3, 0xc8204de090, 0xf, 0x0, 0x0, 0x18, 0xe781)
    /go/go/src/net/dial.go:246 +0x6e
net.TestWriteTimeoutFluctuation(0xc820304600)
    /go/go/src/net/timeout_test.go:780 +0x138
testing.tRunner(0xc820304600, 0x264bb8)
    /go/go/src/testing/testing.go:547 +0x7a
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42055 [chan receive]:
net.(*localServer).teardown(0xc82026c150, 0x0, 0x0)
    /go/go/src/net/mockserver_test.go:107 +0x108
net.TestReadTimeout(0xc8201b23c0)
    /go/go/src/net/timeout_test.go:373 +0x4c5
testing.tRunner(0xc8201b23c0, 0x264920)
    /go/go/src/testing/testing.go:547 +0x7a
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42056 [select]:
net.TestReadTimeoutMustNotReturn(0xc8201b2480)
    /go/go/src/net/timeout_test.go:413 +0x774
testing.tRunner(0xc8201b2480, 0x264918)
    /go/go/src/testing/testing.go:547 +0x7a
created by testing.(*T).Run
    /go/go/src/testing/testing.go:578 +0x1f6

goroutine 42345 [IO wait]:
net.runtime_pollWait(0x744790, 0x72, 0x0)
    /go/go/src/runtime/netpoll.go:160 +0x4f
net.(*pollDesc).wait(0xc820018370, 0x72, 0xc820316d50, 0xc820010200)
    /go/go/src/net/fd_poll_runtime.go:73 +0x2e
net.(*pollDesc).waitRead(0xc820018370, 0x32e0e0, 0xc820010200)
    /go/go/src/net/fd_poll_runtime.go:78 +0x2a
net.(*netFD).readFrom(0xc820018310, 0xc8201be100, 0x100, 0x100, 0x0, 0x0, 0x0, 0x32e0e0, 0xc820010200)
    /go/go/src/net/fd_unix.go:286 +0x1dc
net.(*UDPConn).readFrom(0xc820490010, 0xc8201be100, 0x100, 0x100, 0x1f59c0, 0x100, 0xc8201be100, 0x3508e0)
    /go/go/src/net/udpsock_posix.go:43 +0x5a
net.(*UDPConn).ReadFrom(0xc820490010, 0xc8201be100, 0x100, 0x100, 0x100, 0x100, 0x376974e7, 0x3508e0, 0x5f8215f)
    /go/go/src/net/udpsock.go:94 +0x68
net.timeoutPacketReceiver(0x330080, 0xc820490010, 0x5f5e100, 0x2faf080, 0xee6b280, 0xc820062240)
    /go/go/src/net/mockserver_test.go:509 +0x1a3
created by net.TestReadFromTimeoutFluctuation
    /go/go/src/net/timeout_test.go:751 +0x289

goroutine 42310 [IO wait]:
net.runtime_pollWait(0x744490, 0x72, 0x32e0e0)
    /go/go/src/runtime/netpoll.go:160 +0x4f
net.(*pollDesc).wait(0xc8201b1250, 0x72, 0xc820234e60, 0xc820010200)
    /go/go/src/net/fd_poll_runtime.go:73 +0x2e
net.(*pollDesc).waitRead(0xc8201b1250, 0x32e0e0, 0xc820010200)
    /go/go/src/net/fd_poll_runtime.go:78 +0x2a
net.(*netFD).accept(0xc8201b11f0, 0x0, 0x32db60, 0xc8203ee0a0)
    /go/go/src/net/fd_unix.go:435 +0x220
net.(*TCPListener).accept(0xc8203ca120, 0x30c34, 0xc820234f00, 0x1378f2)
    /go/go/src/net/tcpsock_posix.go:125 +0x24
net.(*TCPListener).Accept(0xc8203ca120, 0x264db8, 0x330200, 0xc82017e018, 0xc820451c80)
    /go/go/src/net/tcpsock.go:221 +0x3f
net.testVariousDeadlines.func1(0xc8200a9c50, 0x32eee0, 0xc8203ca120)
    /go/go/src/net/timeout_test.go:856 +0x3d
net.(*localServer).buildup.func1(0xc820446400, 0xc8200a9c50)
    /go/go/src/net/mockserver_test.go:95 +0x38
created by net.(*localServer).buildup
    /go/go/src/net/mockserver_test.go:97 +0x3f
exit status 2
FAIL    net 65.776s

@Thomasdezeeuw Thomasdezeeuw mentioned this issue Apr 5, 2016
Closed
@mikioh
Copy link
Contributor

mikioh commented Apr 8, 2016

@Thomasdezeeuw,

Thanks for the information. My guess is that:

  • You probably see issues caused by two different root causes
  • One comes from tip
    • It looks like tip has changed/improved runtime stuff related to goroutine and defer block scheduling
    • At present, we see many intermittent build failures of runtime/trace, net, net/http, testing packages which depend on such stuff and testing.Parallel
  • Another comes from latest darwin kernels, 10.11.x

I guess that the following patch might mitigate the failures.

--- a/src/net/timeout_test.go
+++ b/src/net/timeout_test.go
@@ -315,7 +315,7 @@ var readTimeoutTests = []struct {
 }

 func TestReadTimeout(t *testing.T) {
-       t.Parallel()
+       //t.Parallel()

        switch runtime.GOOS {
        case "plan9":

Just tried go test -v -run=Timeout --parallel 10 -count=100 and had no failure.

@mikioh mikioh modified the milestones: Unplanned, Go1.7 Apr 8, 2016
@Thomasdezeeuw
Copy link
Contributor Author

@mikioh I ran the tests for 2 hours and had no failure's, that change seems to work.

@golang golang locked and limited conversation to collaborators Apr 13, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.7
Development

No branches or pull requests
4 participants
@bradfitz @mikioh @Thomasdezeeuw @gopherbot