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

Jump to bottom

net/http/httptest: Server blocked in Close after 5 seconds, waiting for connections #16555

Closed
fraenky8 opened this issue Jul 31, 2016 · 33 comments
Closed

net/http/httptest: Server blocked in Close after 5 seconds, waiting for connections #16555

fraenky8 opened this issue Jul 31, 2016 · 33 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-Windows
Milestone
Go1.9

Comments

@fraenky8
Copy link

1. What version of Go are you using (go version)?
go version go1.6 windows/amd64

2. What operating system and processor architecture are you using (go env)?
Windows 7/x64
git version 2.9.2.windows.1
mingw64 installed

set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=D:\Eigene Dateien\Coding\go
set GORACE=
set GOROOT=D:\go
set GOTOOLDIR=D:\go\pkg\tool\windows_amd64
set GO15VENDOREXPERIMENT=1
set CC=gcc
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0
set CXX=g++
set CGO_ENABLED=1

3. What did you do?
Take the simple server example from https://tip.golang.org/pkg/net/http/httptest/#example_Server and run it with go run main.go (https://play.golang.org/p/k9beXK-pA-)

4. What did you expect to see?
Hello Client

5. What did you see instead?
Hello, client
2016/07/31 16:30:13 httptest.Server blocked in Close after 5 seconds, waiting for connections:
*net.TCPConn 0xc08202c020 127.0.0.1:4401 in state idle

After 10mins i canceled execution wtih CTRL-C.
@bradfitz
Copy link
Contributor

Do you run any anti-virus products? If so, which?

@fraenky8
Copy link
Author

Yes: Microsoft Security Essentials.

@bradfitz
Copy link
Contributor

Any change in behavior if you disable it?

I ask because 9 times out of 10, bizarre behavior on Windows is caused by antivirus intercepting system calls and not being transparent. I would expect MSE to be better than most, though.

We have tests for this too (the example itself is even a test which the builders would test on Windows), so something seems different on your machine than on our testing machines.

@bradfitz bradfitz added OS-Windows NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Jul 31, 2016
@bradfitz bradfitz changed the title httptest.Server blocked in Close after 5 seconds, waiting for connections net/http/httptest: Server blocked in Close after 5 seconds, waiting for connections Jul 31, 2016
@fraenky8
Copy link
Author

I disabled the real time protection and also included the go firectory and go.exe file on the white list. Didn't helped. Further more i have a lot of network adapters due to vmware/virtualbox, so i disabled all of them, except my real network card. Didn't helped either. Between these investigations, i restartet my pc, also flushed dns.

Some more background info, of my pc & work process: starting up, i type in the password to decrypt my HDDs (TrueCrypt). Then i start the git shell (git-bash.exe on windows), there i have to type in the passphrase for my public key (so a ssh-Agent is initialized). After that, i chenge to my go-Coding Directory (in shell), and run the main.go as described.

Maybe i sould check some things like VPN Adapters? (Was not connected, but there are windows services in the background) Or general check Windows-Services..

Any suggestions/hints/ideas for further investigations are welcome :)

@bradfitz
Copy link
Contributor

Sorry, I'm out of ideas. @alexbrainman, can you reproduce on Windows?

@alexbrainman
Copy link
Member

I tried reproducing this on both current tip and go1.6, but everything works for me as expected. I also use Windows 7.

I have no great ideas, but to debug this. Just put fmt.Printf (or println) in the code that is failing. I would start by greping for 'blocked in Close' and see where it takes me. @fraenkel if you can reproduce this reliably, you should be able to see what is broken. Don't hesitate to ask for help.

Alex

@fraenkel
Copy link
Contributor

fraenkel commented Aug 1, 2016

I think you meant @fraenky8

@alexbrainman
Copy link
Member

I think you meant @fraenky8

I sure did. Sorry about that.

Alex

@fraenky8
Copy link
Author

fraenky8 commented Aug 1, 2016

I did further investigations, and i cant figure it out. Played with various network settings, installed latest go version. In a VM the example works (32bit tho). I have no clue, must be a weird composition of some configurations/registry|network settings by all the installed programms (including MS Network Monitor, Wireshark, TeamViewer, Nmap, ...) on my machine i guess.

I also tried to debug net/httptest (Intellij Webstorm works great), but i have no idea where to look at. Also i am confused about the connection states: in windows i got 2 connections with state "established" but the go program says, 1 idle connection, for me this are 2 different things.

@quentinmit quentinmit added this to the Go1.8Maybe milestone Aug 1, 2016
@alexbrainman
Copy link
Member

I did further investigations, and i cant figure it out. ...

I would try to get a stack trace. For example, I made these changes:

diff --git a/src/net/http/httptest/server.go b/src/net/http/httptest/server.go
index a2573df..12494c6 100644
--- a/src/net/http/httptest/server.go
+++ b/src/net/http/httptest/server.go
@@ -174,7 +174,7 @@ func (s *Server) Close() {
            }
        }
        // If this server doesn't shut down in 5 seconds, tell the user why.
-       t := time.AfterFunc(5*time.Second, s.logCloseHangDebugInfo)
+       t := time.AfterFunc(5*time.Nanosecond, s.logCloseHangDebugInfo)
        defer t.Stop()
    }
    s.mu.Unlock()
@@ -190,6 +190,7 @@ func (s *Server) Close() {
 }

 func (s *Server) logCloseHangDebugInfo() {
+   panic("AAAA")
    s.mu.Lock()
    defer s.mu.Unlock()
    var buf bytes.Buffer

You will not need to change t := time.AfterFunc(5*time.Second, s.logCloseHangDebugInfo) line, because your system is calling into Server.logCloseHangDebugInfo anyway.

I also set GOTRACEBACK to all so I can see all goroutines (including system and all). I get this:

C:\dev\src\issues\issue16555>set GOTRACEBACK=all

C:\dev\src\issues\issue16555>go run main.go
Hello, client
panic: AAAA

goroutine 5 [running]:
panic(0x62a480, 0x10a1a068)
        c:/dev/go1.6/src/runtime/panic.go:464 +0x326
net/http/httptest.(*Server).logCloseHangDebugInfo(0x10a2e380)
        c:/dev/go1.6/src/net/http/httptest/server.go:193 +0x58
net/http/httptest.(*Server).(net/http/httptest.logCloseHangDebugInfo)-fm()
        c:/dev/go1.6/src/net/http/httptest/server.go:177 +0x20
created by time.goFunc
        c:/dev/go1.6/src/time/sleep.go:129 +0x36

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0x10a2e3a4)
        c:/dev/go1.6/src/runtime/sema.go:47 +0x26
sync.(*WaitGroup).Wait(0x10a2e398)
        c:/dev/go1.6/src/sync/waitgroup.go:127 +0xa4
net/http/httptest.(*Server).Close(0x10a2e380)
        c:/dev/go1.6/src/net/http/httptest/server.go:189 +0x1e7
main.main()
        C:/dev/src/issues/issue16555/main.go:28 +0x2f9

goroutine 18 [runnable, locked to thread]:
syscall.Syscall(0x7c82f122, 0x1, 0x75c, 0x0, 0x0, 0x10a2e280, 0x10a13fbc, 0x554f01)
        c:/dev/go1.6/src/runtime/syscall_windows.go:128 +0x4a
syscall.CancelIo(0x75c, 0x0, 0x0)
        c:/dev/go1.6/src/syscall/zsyscall_windows.go:550 +0x5f
net.(*ioSrv).ProcessRemoteIO(0x10a30428)
        c:/dev/go1.6/src/net/fd_windows.go:143 +0x13f
created by net.startServer
        c:/dev/go1.6/src/net/fd_windows.go:239 +0xc9

goroutine 19 [chan receive, locked to thread]:
net.(*ioSrv).ProcessRemoteIO(0x10a30430)
        c:/dev/go1.6/src/net/fd_windows.go:139 +0xcc
created by net.startServer
        c:/dev/go1.6/src/net/fd_windows.go:241 +0x11e

goroutine 20 [chan receive]:
net.(*ioSrv).ExecIO(0x10a30428, 0x10a52738, 0x6c6cb0, 0x8, 0x10a020e0, 0x10aa22a0, 0x0, 0x0)
        c:/dev/go1.6/src/net/fd_windows.go:210 +0x422
net.(*netFD).acceptOne(0x10a52700, 0x10aa21c0, 0x2, 0x2, 0x10a52738, 0x10a15f0c, 0x0, 0x0)
        c:/dev/go1.6/src/net/fd_windows.go:583 +0x1d4
net.(*netFD).accept(0x10a52700, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/fd_windows.go:613 +0x11f
net.(*TCPListener).AcceptTCP(0x10a30438, 0x10a15f44, 0x0, 0x0)
        c:/dev/go1.6/src/net/tcpsock_posix.go:254 +0x47
net.(*TCPListener).Accept(0x10a30438, 0x0, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/tcpsock_posix.go:264 +0x39
net/http.(*Server).Serve(0x10a4e140, 0x8b43a8, 0x10a30438, 0x0, 0x0)
        c:/dev/go1.6/src/net/http/server.go:2117 +0x100
net/http/httptest.(*Server).goServe.func1(0x10a2e380)
        c:/dev/go1.6/src/net/http/httptest/server.go:238 +0x66
created by net/http/httptest.(*Server).goServe
        c:/dev/go1.6/src/net/http/httptest/server.go:239 +0x50

goroutine 23 [chan send]:
net.(*ioSrv).ExecIO(0x10a30428, 0x10a52818, 0x6b2368, 0x7, 0x737108, 0x140, 0x0, 0x0)
        c:/dev/go1.6/src/net/fd_windows.go:209 +0x403
net.(*netFD).Read(0x10a527e0, 0x10a59000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/fd_windows.go:482 +0x129
net.(*conn).Read(0x10a30470, 0x10a59000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/net.go:172 +0xb9
net/http.noteEOFReader.Read(0x8b5430, 0x10a30470, 0x10a50a44, 0x10a59000, 0x1000, 0x1000, 0x10a25dbc, 0x0, 0x0)
        c:/dev/go1.6/src/net/http/transport.go:1683 +0x55
net/http.(*noteEOFReader).Read(0x10a8b8a0, 0x10a59000, 0x1000, 0x1000, 0x10a10000, 0x0, 0x0)
        <autogenerated>:284 +0xae
bufio.(*Reader).fill(0x10a48360)
        c:/dev/go1.6/src/bufio/bufio.go:97 +0x172
bufio.(*Reader).Peek(0x10a48360, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/bufio/bufio.go:132 +0xad
net/http.(*persistConn).readLoop(0x10a50a10)
        c:/dev/go1.6/src/net/http/transport.go:1069 +0x13e
created by net/http.(*Transport).dialConn
        c:/dev/go1.6/src/net/http/transport.go:853 +0xe21

goroutine 4 [chan send]:
net.(*ioSrv).ExecIO(0x10a30428, 0x10aa2118, 0x6b2368, 0x7, 0x737108, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/fd_windows.go:209 +0x403
net.(*netFD).Read(0x10aa20e0, 0x10aa6000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/fd_windows.go:482 +0x129
net.(*conn).Read(0x10a1a048, 0x10aa6000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/net.go:172 +0xb9
net/http.(*connReader).Read(0x10a064c0, 0x10aa6000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/http/server.go:526 +0x189
bufio.(*Reader).fill(0x10a042d0)
        c:/dev/go1.6/src/bufio/bufio.go:97 +0x172
bufio.(*Reader).ReadSlice(0x10a042d0, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/bufio/bufio.go:328 +0x1b4
bufio.(*Reader).ReadLine(0x10a042d0, 0x0, 0x0, 0x0, 0x6a4100, 0x0, 0x0)
        c:/dev/go1.6/src/bufio/bufio.go:357 +0x4b
net/textproto.(*Reader).readLineSlice(0x10a06520, 0x0, 0x0, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/textproto/reader.go:55 +0x59
net/textproto.(*Reader).ReadLine(0x10a06520, 0x0, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/textproto/reader.go:36 +0x39
net/http.readRequest(0x10a042d0, 0x0, 0x10aa01c0, 0x0, 0x0)
        c:/dev/go1.6/src/net/http/request.go:721 +0x9a
net/http.(*conn).readRequest(0x10a08280, 0x0, 0x0, 0x0)
        c:/dev/go1.6/src/net/http/server.go:705 +0x3b7
net/http.(*conn).serve(0x10a08280)
        c:/dev/go1.6/src/net/http/server.go:1425 +0x985
created by net/http.(*Server).Serve
        c:/dev/go1.6/src/net/http/server.go:2137 +0x394
exit status 2

C:\dev\src\issues\issue16555>

What do you see, if you just add panic("AAAA") in Server.logCloseHangDebugInfo?

Alex

@fraenky8
Copy link
Author

fraenky8 commented Aug 8, 2016

I put the panic-call in it and got this output:

$ go run -a main.go
Hello, client
panic: AAAA

goroutine 49 [running]:
panic(0x6d5f80, 0xc08211a060)
        D:/go/go163/src/runtime/panic.go:481 +0x3f4
net/http/httptest.(*Server).logCloseHangDebugInfo(0xc0820043c0)
        D:/go/go163/src/net/http/httptest/server.go:193 +0x6c
net/http/httptest.(*Server).(net/http/httptest.logCloseHangDebugInfo)-fm()
        D:/go/go163/src/net/http/httptest/server.go:177 +0x27
created by time.goFunc
        D:/go/go163/src/time/sleep.go:129 +0x41

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc0820043fc)
        D:/go/go163/src/runtime/sema.go:47 +0x2d
sync.(*WaitGroup).Wait(0xc0820043f0)
        D:/go/go163/src/sync/waitgroup.go:127 +0xbb
net/http/httptest.(*Server).Close(0xc0820043c0)
        D:/go/go163/src/net/http/httptest/server.go:189 +0x264
_local/playground/packages.HttpTestServer()
        D:/Eigene Dateien/Coding/go/src/_local/playground/packages/http.go:124 +0x431
main.main()
        D:/Eigene Dateien/Coding/go/src/_local/playground/main.go:19 +0x1b

goroutine 5 [IO wait]:
net.runtime_pollWaitCanceled(0x205638, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc082022d70, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc08202c028, 0xc082022c60, 0x7d74b0, 0x8, 0xc0820f0080, 0xc0820ec300, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).acceptOne(0xc082022c00, 0xc0820fa000, 0x2, 0x2, 0xc082022c60, 0xd0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc082022c00, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc08202c038, 0xc082027e90, 0x0, 0x0)
        D:/go/go163/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc08202c038, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/tcpsock_posix.go:264 +0x44
net/http.(*Server).Serve(0xc082008100, 0x204690, 0xc08202c038, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:2117 +0x130
net/http/httptest.(*Server).goServe.func1(0xc0820043c0)
        D:/go/go163/src/net/http/httptest/server.go:238 +0x7c
created by net/http/httptest.(*Server).goServe
        D:/go/go163/src/net/http/httptest/server.go:239 +0x5f

goroutine 17 [IO wait]:
net.runtime_pollWaitCanceled(0x2054b8, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc0820e6170, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc08202c028, 0xc0820e6060, 0x7d1d30, 0x7, 0x874c60, 0xc0820ee000, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).Read(0xc0820e6000, 0xc082102000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:482 +0x17e
net.(*conn).Read(0xc0820f4000, 0xc082102000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/net.go:172 +0xeb
net/http.(*connReader).Read(0xc0820f00a0, 0xc082102000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:526 +0x19d
bufio.(*Reader).fill(0xc082100000)
        D:/go/go163/src/bufio/bufio.go:97 +0x1f0
bufio.(*Reader).ReadSlice(0xc082100000, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:328 +0x221
bufio.(*Reader).ReadLine(0xc082100000, 0x0, 0x0, 0x0, 0x7b6300, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:357 +0x5a
net/textproto.(*Reader).readLineSlice(0xc0820f2090, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/textproto/reader.go:55 +0x88
net/textproto.(*Reader).ReadLine(0xc0820f2090, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/textproto/reader.go:36 +0x47
net/http.readRequest(0xc082100000, 0x0, 0xc08212c000, 0x0, 0x0)
        D:/go/go163/src/net/http/request.go:721 +0xbd
net/http.(*conn).readRequest(0xc0820f6000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:705 +0x360
net/http.(*conn).serve(0xc0820f6000)
        D:/go/go163/src/net/http/server.go:1425 +0x94e
created by net/http.(*Server).Serve
        D:/go/go163/src/net/http/server.go:2137 +0x455

goroutine 33 [IO wait]:
net.runtime_pollWaitCanceled(0x205578, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc0820231f0, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc08202c028, 0xc0820230e0, 0x7d1d30, 0x7, 0x874c60, 0x410d28, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).Read(0xc082023080, 0xc082108000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:482 +0x17e
net.(*conn).Read(0xc082104000, 0xc082108000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/net.go:172 +0xeb
net/http.noteEOFReader.Read(0x2a90000, 0xc082104000, 0xc08203bcd8, 0xc082108000, 0x1000, 0x1000, 0x403cda, 0x0, 0x0)
        D:/go/go163/src/net/http/transport.go:1690 +0x6e
net/http.(*noteEOFReader).Read(0xc0820de120, 0xc082108000, 0x1000, 0x1000, 0xc08210fd0d, 0x0, 0x0)
        <autogenerated>:284 +0xd7
bufio.(*Reader).fill(0xc082106000)
        D:/go/go163/src/bufio/bufio.go:97 +0x1f0
bufio.(*Reader).Peek(0xc082106000, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:132 +0xd3
net/http.(*persistConn).readLoop(0xc08203bc70)
        D:/go/go163/src/net/http/transport.go:1076 +0x17e
created by net/http.(*Transport).dialConn
        D:/go/go163/src/net/http/transport.go:860 +0x10ad
exit status 2

Moreover i played aorund last week with some test-cased where the httptest-Server is used (https://github.com/parnurzeal/gorequest/blob/develop/request_test.go) and i realized, if i send a request, lets say GET, because the testServer is waiting for it, on the localhost:port with nc, the test passes and goes on runnning until the next test with httptest-Server runs into the issue. Just a side info here.

Hope that ouput helps?

@alexbrainman
Copy link
Member

I compared our stack traces. And you are running:

_local/playground/packages.HttpTestServer()
D:/Eigene Dateien/Coding/go/src/_local/playground/packages/http.go:124 +0x431
main.main()
D:/Eigene Dateien/Coding/go/src/_local/playground/main.go:19 +0x1b

which is different from what I am running:

https://play.golang.org/p/k9beXK-pA-

(I don't have _local/playground/packages package. And my main.go line 19 has log.Fatal(err), so it cannot be listed on this stack trace)

I suspect your code does something different then mine. I need to see your real code to be able to debug it.

Alex

@fraenky8
Copy link
Author

Sorry!! I encapsulated the httptest-Server in my own function & didn't realized at this moment that this affects the stack trace, my fault m(

I put the code from here in https://play.golang.org/p/k9beXK-pA- in main.go with package /issues/issue16555/ and run it using the windows cmd instead if git-bash to avoid unecassary effects on environment etc...

D:\Eigene Dateien\Coding\go\src\issues\issue16555>set GOTRACEBACK=all

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go run -a main.go
Hello, client
panic: AAAA

goroutine 17 [running]:
panic(0x6a2e40, 0xc0820be000)
        D:/go/go163/src/runtime/panic.go:481 +0x3f4
net/http/httptest.(*Server).logCloseHangDebugInfo(0xc08202e360)
        D:/go/go163/src/net/http/httptest/server.go:193 +0x6c
net/http/httptest.(*Server).(net/http/httptest.logCloseHangDebugInfo)-fm()
        D:/go/go163/src/net/http/httptest/server.go:177 +0x27
created by time.goFunc
        D:/go/go163/src/time/sleep.go:129 +0x41

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc08202e39c)
        D:/go/go163/src/runtime/sema.go:47 +0x2d
sync.(*WaitGroup).Wait(0xc08202e390)
        D:/go/go163/src/sync/waitgroup.go:127 +0xbb
net/http/httptest.(*Server).Close(0xc08202e360)
        D:/go/go163/src/net/http/httptest/server.go:189 +0x264
main.main()
        D:/Eigene Dateien/Coding/go/src/issues/issue16555/main.go:28 +0x431

goroutine 5 [IO wait]:
net.runtime_pollWaitCanceled(0x1855e0, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc082018d70, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc082022028, 0xc082018c60, 0x793fb0, 0x8, 0xc0820992c0, 0xc082019980, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).acceptOne(0xc082018c00, 0xc0820a21c0, 0x2, 0x2, 0xc082018c60, 0xd0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc082018c00, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082022038, 0xc08201de90, 0x0, 0x0)
        D:/go/go163/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082022038, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/tcpsock_posix.go:264 +0x44
net/http.(*Server).Serve(0xc08200a100, 0x184638, 0xc082022038, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:2117 +0x130
net/http/httptest.(*Server).goServe.func1(0xc08202e360)
        D:/go/go163/src/net/http/httptest/server.go:238 +0x7c
created by net/http/httptest.(*Server).goServe
        D:/go/go163/src/net/http/httptest/server.go:239 +0x5f

goroutine 10 [IO wait]:
net.runtime_pollWaitCanceled(0x185460, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc082019670, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc082022028, 0xc082019560, 0x78f948, 0x7, 0x827918, 0xc082006780, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).Read(0xc082019500, 0xc0820b0000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:482 +0x17e
net.(*conn).Read(0xc082022050, 0xc0820b0000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/net.go:172 +0xeb
net/http.(*connReader).Read(0xc0820992e0, 0xc0820b0000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:526 +0x19d
bufio.(*Reader).fill(0xc08202e8a0)
        D:/go/go163/src/bufio/bufio.go:97 +0x1f0
bufio.(*Reader).ReadSlice(0xc08202e8a0, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:328 +0x221
bufio.(*Reader).ReadLine(0xc08202e8a0, 0x0, 0x0, 0x0, 0x775700, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:357 +0x5a
net/textproto.(*Reader).readLineSlice(0xc08204ced0, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/textproto/reader.go:55 +0x88
net/textproto.(*Reader).ReadLine(0xc08204ced0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/textproto/reader.go:36 +0x47
net/http.readRequest(0xc08202e8a0, 0x0, 0xc0820a2380, 0x0, 0x0)
        D:/go/go163/src/net/http/request.go:721 +0xbd
net/http.(*conn).readRequest(0xc08200a280, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:705 +0x360
net/http.(*conn).serve(0xc08200a280)
        D:/go/go163/src/net/http/server.go:1425 +0x94e
created by net/http.(*Server).Serve
        D:/go/go163/src/net/http/server.go:2137 +0x455

goroutine 8 [IO wait]:
net.runtime_pollWaitCanceled(0x185520, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc0820191f0, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc082022028, 0xc0820190e0, 0x78f948, 0x7, 0x827918, 0x4114e8, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).Read(0xc082019080, 0xc0820ae000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:482 +0x17e
net.(*conn).Read(0xc082022048, 0xc0820ae000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/net.go:172 +0xeb
net/http.noteEOFReader.Read(0x185758, 0xc082022048, 0xc0820357f8, 0xc0820ae000, 0x1000, 0x1000, 0x40449a, 0x0, 0x0)
        D:/go/go163/src/net/http/transport.go:1690 +0x6e
net/http.(*noteEOFReader).Read(0xc0820991a0, 0xc0820ae000, 0x1000, 0x1000, 0xc0820abd0d, 0x0, 0x0)
        <autogenerated>:284 +0xd7
bufio.(*Reader).fill(0xc08202e6c0)
        D:/go/go163/src/bufio/bufio.go:97 +0x1f0
bufio.(*Reader).Peek(0xc08202e6c0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:132 +0xd3
net/http.(*persistConn).readLoop(0xc082035790)
        D:/go/go163/src/net/http/transport.go:1076 +0x17e
created by net/http.(*Transport).dialConn
        D:/go/go163/src/net/http/transport.go:860 +0x10ad
exit status 2

D:\Eigene Dateien\Coding\go\src\issues\issue16555>

@alexbrainman
Copy link
Member

Thank you for stack trace.

What go version do you use? I assumed you use go1.6, but your some line numbers on your stack trace are wrong. What does go version outputs?

Also have you tried running this program using later version of Go (like go1.7rc6 or any recent version)? Could you?

Thank you.

Alex

@fraenky8
Copy link
Author

I did a fresh install of go1.6.3 with the provided installer, here is the output of the stacktrace:

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go version
go version go1.6.3 windows/amd64

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go env
set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=D:\Eigene Dateien\Coding\go
set GORACE=
set GOROOT=D:\go\go163
set GOTOOLDIR=D:\go\go163\pkg\tool\windows_amd64
set GO15VENDOREXPERIMENT=1
set CC=gcc
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0
set CXX=g++
set CGO_ENABLED=1

D:\Eigene Dateien\Coding\go\src\issues\issue16555>set GOTRACEBACK=all

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go run -a main.go
Hello, client
panic: AAAA

goroutine 17 [running]:
panic(0x6a2e40, 0xc0820c2000)
        D:/go/go163/src/runtime/panic.go:481 +0x3f4
net/http/httptest.(*Server).logCloseHangDebugInfo(0xc082032360)
        D:/go/go163/src/net/http/httptest/server.go:193 +0x6c
net/http/httptest.(*Server).(net/http/httptest.logCloseHangDebugInfo)-fm()
        D:/go/go163/src/net/http/httptest/server.go:177 +0x27
created by time.goFunc
        D:/go/go163/src/time/sleep.go:129 +0x41

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc08203239c)
        D:/go/go163/src/runtime/sema.go:47 +0x2d
sync.(*WaitGroup).Wait(0xc082032390)
        D:/go/go163/src/sync/waitgroup.go:127 +0xbb
net/http/httptest.(*Server).Close(0xc082032360)
        D:/go/go163/src/net/http/httptest/server.go:189 +0x264
main.main()
        D:/Eigene Dateien/Coding/go/src/issues/issue16555/main.go:28 +0x431

goroutine 5 [IO wait]:
net.runtime_pollWaitCanceled(0x3855e0, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc082018d70, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc082022028, 0xc082018c60, 0x793fb0, 0x8, 0xc08209d2e0, 0xc082019800, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).acceptOne(0xc082018c00, 0xc0820a61c0, 0x2, 0x2, 0xc082018c60, 0xd0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:583 +0x26c
net.(*netFD).accept(0xc082018c00, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:613 +0x173
net.(*TCPListener).AcceptTCP(0xc082022038, 0xc08201de90, 0x0, 0x0)
        D:/go/go163/src/net/tcpsock_posix.go:254 +0x54
net.(*TCPListener).Accept(0xc082022038, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/tcpsock_posix.go:264 +0x44
net/http.(*Server).Serve(0xc082008100, 0x384638, 0xc082022038, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:2117 +0x130
net/http/httptest.(*Server).goServe.func1(0xc082032360)
        D:/go/go163/src/net/http/httptest/server.go:238 +0x7c
created by net/http/httptest.(*Server).goServe
        D:/go/go163/src/net/http/httptest/server.go:239 +0x5f

goroutine 10 [IO wait]:
net.runtime_pollWaitCanceled(0x385460, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc0820194f0, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc082022028, 0xc0820193e0, 0x78f948, 0x7, 0x827918, 0xc082004780, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).Read(0xc082019380, 0xc0820b4000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:482 +0x17e
net.(*conn).Read(0xc082022050, 0xc0820b4000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/net.go:172 +0xeb
net/http.(*connReader).Read(0xc08209d300, 0xc0820b4000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:526 +0x19d
bufio.(*Reader).fill(0xc0820328a0)
        D:/go/go163/src/bufio/bufio.go:97 +0x1f0
bufio.(*Reader).ReadSlice(0xc0820328a0, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:328 +0x221
bufio.(*Reader).ReadLine(0xc0820328a0, 0x0, 0x0, 0x0, 0x775700, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:357 +0x5a
net/textproto.(*Reader).readLineSlice(0xc082050ed0, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/textproto/reader.go:55 +0x88
net/textproto.(*Reader).ReadLine(0xc082050ed0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/textproto/reader.go:36 +0x47
net/http.readRequest(0xc0820328a0, 0x0, 0xc0820a6380, 0x0, 0x0)
        D:/go/go163/src/net/http/request.go:721 +0xbd
net/http.(*conn).readRequest(0xc082008280, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/http/server.go:705 +0x360
net/http.(*conn).serve(0xc082008280)
        D:/go/go163/src/net/http/server.go:1425 +0x94e
created by net/http.(*Server).Serve
        D:/go/go163/src/net/http/server.go:2137 +0x455

goroutine 8 [IO wait]:
net.runtime_pollWaitCanceled(0x385520, 0x72)
        D:/go/go163/src/runtime/netpoll.go:176 +0x38
net.(*pollDesc).WaitCanceled(0xc0820191f0, 0x72)
        D:/go/go163/src/net/fd_poll_runtime.go:86 +0x35
net.(*ioSrv).ExecIO(0xc082022028, 0xc0820190e0, 0x78f948, 0x7, 0x827918, 0x4114e8, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:213 +0x37f
net.(*netFD).Read(0xc082019080, 0xc0820b2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/fd_windows.go:482 +0x17e
net.(*conn).Read(0xc082022048, 0xc0820b2000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go163/src/net/net.go:172 +0xeb
net/http.noteEOFReader.Read(0x385758, 0xc082022048, 0xc082039728, 0xc0820b2000, 0x1000, 0x1000, 0x40449a, 0x0, 0x0)
        D:/go/go163/src/net/http/transport.go:1690 +0x6e
net/http.(*noteEOFReader).Read(0xc08209d1c0, 0xc0820b2000, 0x1000, 0x1000, 0xc0820afd0d, 0x0, 0x0)
        <autogenerated>:284 +0xd7
bufio.(*Reader).fill(0xc0820326c0)
        D:/go/go163/src/bufio/bufio.go:97 +0x1f0
bufio.(*Reader).Peek(0xc0820326c0, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
        D:/go/go163/src/bufio/bufio.go:132 +0xd3
net/http.(*persistConn).readLoop(0xc0820396c0)
        D:/go/go163/src/net/http/transport.go:1076 +0x17e
created by net/http.(*Transport).dialConn
        D:/go/go163/src/net/http/transport.go:860 +0x10ad
exit status 2

D:\Eigene Dateien\Coding\go\src\issues\issue16555>

Next i installed go1.7rc6 with the provided installer. I ran it without the modification in server.go file (panic(...)). After that i put the panic call in function logCloseHangDebugInfo at line 193. I canceled the running programm wit CTRL-C, therefore exit status 2 occurs.

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go version
go version go1.7rc6 windows/amd64

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go env
set GOARCH=amd64
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=D:\Eigene Dateien\Coding\go
set GORACE=
set GOROOT=D:\go\go17rc6
set GOTOOLDIR=D:\go\go17rc6\pkg\tool\windows_amd64
set CC=gcc
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\Frank\AppData\Local\Temp\go-build585817646=/tmp/go-build -gno-record-gcc-switches
set CXX=g++
set CGO_ENABLED=1

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go run -a main.go
Hello, client
2016/08/11 10:05:51 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *net.TCPConn 0xc042066050 127.0.0.1:1270 in state idle
exit status 2

D:\Eigene Dateien\Coding\go\src\issues\issue16555>set GOTRACEBACK=all

D:\Eigene Dateien\Coding\go\src\issues\issue16555>go run -a main.go
Hello, client
panic: AAAA

goroutine 8 [running]:
panic(0x605ca0, 0xc04200c2b0)
        D:/go/go17rc6/src/runtime/panic.go:500 +0x1af
net/http/httptest.(*Server).logCloseHangDebugInfo(0xc042036360)
        D:/go/go17rc6/src/net/http/httptest/server.go:193 +0x74
net/http/httptest.(*Server).(net/http/httptest.logCloseHangDebugInfo)-fm()
        D:/go/go17rc6/src/net/http/httptest/server.go:177 +0x31
created by time.goFunc
        D:/go/go17rc6/src/time/sleep.go:154 +0x4b

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc04203639c)
        D:/go/go17rc6/src/runtime/sema.go:47 +0x37
sync.(*WaitGroup).Wait(0xc042036390)
        D:/go/go17rc6/src/sync/waitgroup.go:131 +0x9e
net/http/httptest.(*Server).Close(0xc042036360)
        D:/go/go17rc6/src/net/http/httptest/server.go:189 +0x234
main.main()
        D:/Eigene Dateien/Coding/go/src/issues/issue16555/main.go:28 +0x219

goroutine 18 [IO wait]:
net.runtime_pollWaitCanceled(0x809060, 0x72)
        D:/go/go17rc6/src/runtime/netpoll.go:176 +0x40
net.(*pollDesc).waitCanceled(0xc0420682f0, 0x72)
        D:/go/go17rc6/src/net/fd_poll_runtime.go:86 +0x3f
net.(*ioSrv).ExecIO(0xc042064020, 0xc0420681e0, 0x65c889, 0x8, 0xc0420d2140, 0xc0420e4180, 0x0, 0x0)
        D:/go/go17rc6/src/net/fd_windows.go:201 +0x2a3
net.(*netFD).acceptOne(0xc042068180, 0xc0420d80e0, 0x2, 0x2, 0xc0420681e0, 0x4cd437, 0xc0420363a0, 0xc0420d60f0)
        D:/go/go17rc6/src/net/fd_windows.go:529 +0x1f8
net.(*netFD).accept(0xc042068180, 0x0, 0x0, 0x0)
        D:/go/go17rc6/src/net/fd_windows.go:559 +0x131
net.(*TCPListener).accept(0xc042064030, 0x43381e, 0xc04201fe70, 0x4a5654)
        D:/go/go17rc6/src/net/tcpsock_posix.go:132 +0x35
net.(*TCPListener).Accept(0xc042064030, 0x67c4d8, 0xc0420f6000, 0x752700, 0xc0420d6060)
        D:/go/go17rc6/src/net/tcpsock.go:222 +0x50
net/http.(*Server).Serve(0xc042074200, 0x752140, 0xc042064030, 0x0, 0x0)
        D:/go/go17rc6/src/net/http/server.go:2273 +0x1d5
net/http/httptest.(*Server).goServe.func1(0xc042036360)
        D:/go/go17rc6/src/net/http/httptest/server.go:236 +0x74
created by net/http/httptest.(*Server).goServe
        D:/go/go17rc6/src/net/http/httptest/server.go:237 +0x63

goroutine 6 [IO wait]:
net.runtime_pollWaitCanceled(0x808ee0, 0x72)
        D:/go/go17rc6/src/runtime/netpoll.go:176 +0x40
net.(*pollDesc).waitCanceled(0xc0420e8170, 0x72)
        D:/go/go17rc6/src/net/fd_poll_runtime.go:86 +0x3f
net.(*ioSrv).ExecIO(0xc042064020, 0xc0420e8060, 0x65c6c4, 0x7, 0x67c368, 0xc04200c290, 0x404671, 0xc0420c4020)
        D:/go/go17rc6/src/net/fd_windows.go:201 +0x2a3
net.(*netFD).Read(0xc0420e8000, 0xc0420ec000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go17rc6/src/net/fd_windows.go:426 +0x14a
net.(*conn).Read(0xc042024010, 0xc0420ec000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go17rc6/src/net/net.go:173 +0x77
net/http.(*persistConn).Read(0xc042000500, 0xc0420ec000, 0x1000, 0x1000, 0x4bb257, 0xc0420ddb48, 0x4038ad)
        D:/go/go17rc6/src/net/http/transport.go:1256 +0x15b
bufio.(*Reader).fill(0xc0420e6360)
        D:/go/go17rc6/src/bufio/bufio.go:97 +0x113
bufio.(*Reader).Peek(0xc0420e6360, 0x1, 0xc0420ddbad, 0x1, 0x0, 0xc0420e63c0, 0x0)
        D:/go/go17rc6/src/bufio/bufio.go:129 +0x69
net/http.(*persistConn).readLoop(0xc042000500)
        D:/go/go17rc6/src/net/http/transport.go:1413 +0x1a8
created by net/http.(*Transport).dialConn
        D:/go/go17rc6/src/net/http/transport.go:1057 +0x4f0

goroutine 33 [IO wait]:
net.runtime_pollWaitCanceled(0x808fa0, 0x72)
        D:/go/go17rc6/src/runtime/netpoll.go:176 +0x40
net.(*pollDesc).waitCanceled(0xc0420e4170, 0x72)
        D:/go/go17rc6/src/net/fd_poll_runtime.go:86 +0x3f
net.(*ioSrv).ExecIO(0xc042064020, 0xc0420e4060, 0x65c6c4, 0x7, 0x67c368, 0x0, 0x0, 0xc0420ef8c8)
        D:/go/go17rc6/src/net/fd_windows.go:201 +0x2a3
net.(*netFD).Read(0xc0420e4000, 0xc04210c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go17rc6/src/net/fd_windows.go:426 +0x14a
net.(*conn).Read(0xc0420ea000, 0xc04210c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        D:/go/go17rc6/src/net/net.go:173 +0x77
net/http.(*connReader).Read(0xc0420c0c00, 0xc04210c000, 0x1000, 0x1000, 0xc04200c260, 0xc0420ef9b0, 0x8)
        D:/go/go17rc6/src/net/http/server.go:586 +0x14b
bufio.(*Reader).fill(0xc0420364e0)
        D:/go/go17rc6/src/bufio/bufio.go:97 +0x113
bufio.(*Reader).ReadSlice(0xc0420364e0, 0xa, 0x0, 0x1e, 0x6, 0x0, 0x0)
        D:/go/go17rc6/src/bufio/bufio.go:330 +0xbc
bufio.(*Reader).ReadLine(0xc0420364e0, 0xc0420c42d0, 0xf0, 0xf0, 0x652980, 0xc0420c2b00, 0x120490)
        D:/go/go17rc6/src/bufio/bufio.go:359 +0x3e
net/textproto.(*Reader).readLineSlice(0xc042080a80, 0xc0420efa98, 0xc0420efa98, 0x40f72f, 0xf0, 0x652980)
        D:/go/go17rc6/src/net/textproto/reader.go:55 +0x65
net/textproto.(*Reader).ReadLine(0xc042080a80, 0xc0420c42d0, 0xc, 0x401a7a, 0xc0420efc68)
        D:/go/go17rc6/src/net/textproto/reader.go:36 +0x36
net/http.readRequest(0xc0420364e0, 0xc0420efc00, 0xc0420c42d0, 0x0, 0x0)
        D:/go/go17rc6/src/net/http/request.go:793 +0xac
net/http.(*conn).readRequest(0xc0420f6000, 0x752640, 0xc042040380, 0x0, 0x0, 0x0)
        D:/go/go17rc6/src/net/http/server.go:765 +0x114
net/http.(*conn).serve(0xc0420f6000, 0x752640, 0xc042040380)
        D:/go/go17rc6/src/net/http/server.go:1532 +0x3da
created by net/http.(*Server).Serve
        D:/go/go17rc6/src/net/http/server.go:2293 +0x454
exit status 2

D:\Eigene Dateien\Coding\go\src\issues\issue16555>

Is there a difference to install go from installer or from zip-Package? Maybe the lines changed because i installed go previously by zip...?

@mheinz67
Copy link

Please try the command "netsh winsock reset" in a admin cmd shell and reboot the computer.
It fixed the very same issue for me (on a win7/x64 dell Latitude E5430 notebook), that was not reproducible on my colleagues notebooks.

Markus

@fraenky8
Copy link
Author

Actually this worked for me! 👍 But the main reason for this issue is still unclear. I tried to a to create the resetlog.txt like described in https://support.microsoft.com/en-us/kb/299357 with the commands below but i got no file. Maybe this file would have had some advices to track down the error. Thanks anyway!

C:\Users\Frank>netsh
netsh>winsock
netsh winsock>reset c:\resetlog.txt

@rsc
Copy link
Contributor

rsc commented Oct 20, 2016

OK, so it sounds like "netsh winsock reset" cleaned out some bad registry values that something had set?

In that case I am not sure there's anything left for Go to do here. Nice bug though.

@rsc rsc closed this as completed Oct 20, 2016
@jeanbza
Copy link
Member

jeanbza commented Jan 5, 2017 •
edited

We're seeing this intermittently on ubuntu 14.04 containers @rsc @bradfitz

Any idea how we can debug?

@rsc
Copy link
Contributor

rsc commented Jan 5, 2017

What program are you running? Can you point us at it?

@rsc
Copy link
Contributor

rsc commented Jan 5, 2017

Also how often does it happen? If we fixed the bug could you tell? It's possible this is a dup of #17007 (different failure mode, same cause).

@rsc rsc reopened this Jan 5, 2017
@jeanbza
Copy link
Member

jeanbza commented Jan 5, 2017 •
edited

@rsc

What program are you running? Can you point us at it?

Unfortunately not, but I can point you to our environment pivotalcf/metrics-ci

The program is a simple *ghttp.Server that we are starting and Close-ing before and after a test. This error has occurred twice in 24 runs, and both times were a similar situation but different tests, files, and servers.

If you provide a fix we may be able to infer by running our test suite ~50 times or some other high amount and seeing if it pops up.

edit: It might be of note that our tests tend to start/stop this server at quite a high rate.

edit2: Happy to provide any other info.

@jeanbza
Copy link
Member

jeanbza commented Jan 5, 2017

@rsc Apologies, debian:jessie is the OS

@bradfitz
Copy link
Contributor

bradfitz commented Jan 6, 2017

@jadekler, if you can reproduce it, send a SIGQUIT to it when it's in that state, and capture all the goroutines and post it here.

@rsc
Copy link
Contributor

rsc commented Jan 6, 2017

I no longer think this could be caused by #17007.

@jeanbza
Copy link
Member

jeanbza commented Jan 6, 2017

@bradfitz Done! It occurred again this morning. See below:

[1483723682] Ingestor - Integration Test Suite - 18/18 specs 2017/01/06 17:32:00 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *net.TCPConn 0xc420462078 127.0.0.1:49472 in state active

Received interrupt.  Emitting contents of GinkgoWriter...
---------------------------------------------------------
2017-01-06T17:31:53.189610Z 11298 main INFO: Starting Mock Loggregator
2017-01-06T17:31:55.484375Z 11363 func2 INFO: Adding LogQueue forwarder for ws://127.0.0.1:38448
2017-01-06T17:31:55.484518Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.485195Z 11363 Print DEBUG: WEBSOCKET REQUEST:: GET /firehose/test-subscription-id HTTP/1.1
Host: ws://127.0.0.1:38179
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: [HIDDEN]
Origin: http://localhost
Authorization: bearer [redacted]
2017-01-06T17:31:55.492616Z 11363 Print DEBUG: WEBSOCKET RESPONSE:: HTTP/1.1 101 Switching Protocols
Connection: Upgrade
Sec-Websocket-Accept: 9aRb8n8p72EDh+tVPhDcr3jyl4I=
Upgrade: websocket
2017-01-06T17:31:55.493620Z 11363 func1 DEBUG: Established websocket to logqueue ws://127.0.0.1:38448
2017-01-06T17:31:55.493816Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.500041Z 11363 func1 DEBUG: Established websocket to logqueue ws://127.0.0.1:38448
2017-01-06T17:31:55.500323Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.503808Z 11363 func1 DEBUG: Established websocket to logqueue ws://127.0.0.1:38448
2017-01-06T17:31:55.504051Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.512093Z 11363 reconn DEBUG: Failed to get websocket connection: unexpected EOF
2017-01-06T17:31:55.522611Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.528677Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.529428Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.539936Z 11363 func2 INFO: Adding LogQueue forwarder for ws://127.0.0.1:43523
2017-01-06T17:31:55.540138Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.545525Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.545840Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.546172Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.564546Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.559903Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.574431Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.592869Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.593094Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.594512Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.595335Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.603775Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.607974Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.608328Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.614374Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.614470Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.614731Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.618457Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.622402Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.622817Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.623224Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.624714Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.627965Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.627953Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:38448: getsockopt: connection refused
2017-01-06T17:31:55.633624Z 11363 func1 DEBUG: Opening new connection for pool
2017-01-06T17:31:55.637659Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.638226Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.653511Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.653747Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.654241Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.654495Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.654931Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.663029Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.663905Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.664226Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.670617Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.674336Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.674675Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.677942Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.681817Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.681840Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.683622Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.693528Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.693812Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.694500Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.695129Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.700102Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.701109Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.701485Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.703989Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.704164Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.706235Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.711946Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.712592Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.714393Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.721483Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.716552Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.723762Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.723601Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.730570Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.731764Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.731861Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.731811Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.732216Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.734111Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.739811Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.742059Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.744512Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.744454Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.742309Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.745466Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.745792Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.750138Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.752455Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.754922Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.755210Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.754816Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.756078Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.759835Z 11363 reconn DEBUG: Failed to get websocket connection: dial tcp 127.0.0.1:43523: getsockopt: connection refused
2017-01-06T17:31:55.760543Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.762899Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.765488Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.765691Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:38448' is open
2017-01-06T17:31:55.765855Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.766421Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open
2017-01-06T17:31:55.770245Z 11363 reconn DEBUG: Failed to get websocket connection: circuit breaker 'ws-conn-ws://127.0.0.1:43523' is open

@bradfitz
Copy link
Contributor

bradfitz commented Jan 6, 2017

@jadekler, that's not a goroutine dump.

I want to see the stacks of all active goroutines. A program will dump that on SIGQUIT, but maybe your program overrides SIGQUIT.

You might have to arrange to get the stacks some other way. (See https://golang.org/pkg/runtime/#Stack ... and set all to true)

I can't really help until I see what's happening.

@jeanbza
Copy link
Member

jeanbza commented Jan 6, 2017

@bradfitz 👍 Will try that next time it blows up

@bradfitz
Copy link
Contributor

Any update here?

I guess I'll kick it to Go 1.9, since there's nothing actionable here yet.

@bradfitz bradfitz modified the milestones: Go1.9, Go1.8Maybe Jan 23, 2017
@mjeri
Copy link

mjeri commented May 16, 2017 •
edited

I am currently experiencing the problem for the last 50 tries of my test run.. I wanted to provide you with more context information, but it does not reach my panic and therefore I can not provide you the stack trace. This is how my code looks like:

	select {
	case <-receivedEvent:
		fmt.Println("Now I haz event!")
		panic("Alarm!")
	case <-time.After(250 * time.Millisecond):
		t.Error("Timed out waiting for an event")
	}

The Println is still evaluated but not the panic..

Now I haz event!
2017/05/16 16:22:03 httptest.Server blocked in Close after 5 seconds, waiting for connections:
  *net.TCPConn 0xc420138000 127.0.0.1:58876 in state active

And there it hangs forever.

go version
go version go1.8.1 darwin/amd64

Let me know if I can help you somehow or how I can provide you better information. BTW I have no antivirus software installed on the Mac (because you were asking others..). I am executing my tests from IntelliJ, but if I execute them on the CLI I just don't get output.

PS: I am working on OSS here, so I could provide you an version where it fails for me with a quick guide how to get there. Just don't know if you do such things :)

@bradfitz
Copy link
Contributor

@marco-jantke, that code snippet alone is not super helpful. See my question #16555 (comment) above: can you post a goroutine dump?

@mjeri
Copy link

mjeri commented May 17, 2017

Sorry for the interruption, it was basically a programming error in my test case. Fixed it. I was testing a SSE subscription and the client connection to the server was not closed, therefore the server blocked until I would close it. Makes sense.

@bradfitz
Copy link
Contributor

Timeout.

@golang golang locked and limited conversation to collaborators Jun 14, 2018
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-Windows
Projects
None yet
Milestone
Go1.9
Development

No branches or pull requests
10 participants
@bradfitz @rsc @quentinmit @fraenkel @jeanbza @fraenky8 @mjeri @gopherbot @alexbrainman @mheinz67