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/http: TestTransportAndServerSharedBodyRace_h2 flake #14061

Closed
bradfitz opened this issue Jan 21, 2016 · 12 comments
Closed

net/http: TestTransportAndServerSharedBodyRace_h2 flake #14061

bradfitz opened this issue Jan 21, 2016 · 12 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone

Comments

@bradfitz
Copy link
Contributor

http://build.golang.org/log/ee0d84292b89db841915ff25bd6807b2e6c4c536

2016/01/14 06:00:50 http2: server closing client connection; error reading frame from client 127.0.0.1:49824: read tcp 127.0.0.1:49821->127.0.0.1:49824: wsarecv: An established connection was aborted by the software in your host machine.
--- FAIL: TestTransportAndServerSharedBodyRace_h2 (0.16s)
    serve_test.go:3169: Original request: Post https://127.0.0.1:49822: stream error: stream ID 1; STREAM_CLOSED
FAIL
FAIL    net/http    21.824s
@bradfitz bradfitz self-assigned this Jan 21, 2016
@bradfitz bradfitz added this to the Go1.6Maybe milestone Jan 21, 2016
@alexbrainman
Copy link
Member

I cannot reproduce this failure here.

I can see similar "http2: server closing client connection; ..." message logged, but the test still PASSes. I can uses this:

diff --git a/src/net/http/h2_bundle.go b/src/net/http/h2_bundle.go
index bdbdadb..30b9ba6 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -3371,6 +3371,9 @@ func (sc *http2serverConn) processFrameFromReader(res http2readFrameResult) bool
            return true
        }
        clientGone := err == io.EOF || strings.Contains(err.Error(), "use of closed network connection")
+       if !clientGone && runtime.GOOS == "windows" {
+           clientGone = strings.Contains(err.Error(), "An existing connection was forcibly closed by the remote host")
+       }
        if clientGone {

            return false

to get rid of that message.

Alex

@bradfitz
Copy link
Contributor Author

I also can't reproduce, even with thousands of runs on Windows. Maybe it got fixed in the meanwhile.

But I fixed the log spam in https://go-review.googlesource.com/18932

@gopherbot
Copy link

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

@bradfitz
Copy link
Contributor Author

I got a different kind of flake now after hundreds of runs:

--- PASS: TestTransportAndServerSharedBodyRace_h2 (0.03s)
=== RUN   TestTransportAndServerSharedBodyRace_h2
--- PASS: TestTransportAndServerSharedBodyRace_h2 (0.03s)
=== RUN   TestTransportAndServerSharedBodyRace_h2
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
--- PASS: TestTransportAndServerSharedBodyRace_h2 (60.01s)
=== RUN   TestTransportAndServerSharedBodyRace_h2
--- PASS: TestTransportAndServerSharedBodyRace_h2 (0.02s)

It passed, but very slowly, after 60 seconds oddly. (What is 60 seconds?)

gopherbot pushed a commit to golang/net that referenced this issue Jan 26, 2016
Recognize connection aborted errors on Windows and don't log them by
default, like the Unix case.

Log frame reading errors only at verbose level, to match
net/http.Server.

Updates golang/go#13925
Updates golang/go#14061

Change-Id: I87998a924b11d4dad5512e010b29d2da6b4bf867
Reviewed-on: https://go-review.googlesource.com/18932
Reviewed-by: Ian Lance Taylor <iant@golang.org>
@gopherbot
Copy link

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

@bradfitz bradfitz modified the milestones: Go1.7, Go1.6Maybe Jan 26, 2016
@bradfitz
Copy link
Contributor Author

Reopening for Go 1.7 to track the 60 second timeout thing.

@bradfitz bradfitz reopened this Jan 26, 2016
@bradfitz
Copy link
Contributor Author

This same failure was reported in nacl, at: https://go-review.googlesource.com/#/c/18946/1

@bradfitz
Copy link
Contributor Author

/cc @evandbrown

@alexbrainman
Copy link
Member

I cannot see "http2: server closing client connection; ..." log messages anymore. And the test PASSes too.

Alex

@bradfitz
Copy link
Contributor Author

Same flake seen on nacl-386:

https://storage.googleapis.com/go-build-log/a2269145/nacl-386_3cd0dba2.log

ok      mime/quotedprintable    0.365s
ok      net 2.100s
--- FAIL: TestTransportAndServerSharedBodyRace_h2 (0.44s)
    serve_test.go:3221: Original request: Post https://127.0.0.1:384: stream error: stream ID 1; STREAM_CLOSED
FAIL
FAIL    net/http    14.733s
ok      net/http/cgi    0.628s

@bradfitz bradfitz changed the title net/http: TestTransportAndServerSharedBodyRace_h2 flaky on Windows net/http: TestTransportAndServerSharedBodyRace_h2 flake Mar 31, 2016
@pwaller
Copy link
Contributor

pwaller commented Apr 6, 2016

While browsing a shiny new HTTP2 go server with Google Chrome, I hit a grey Chrome background with SPDY_PROTOCOL_ERROR.

Looking in the server logs I saw these errors:

http: proxy error: stream error: stream ID 95; CANCEL
http: proxy error: stream error: stream ID 99; CANCEL
http: proxy error: stream error: stream ID 123; CANCEL
http: proxy error: client disconnected

I've seen ~75 of these "client disconnected" errors and ~200 "stream error" in something like ~100,000 requests from heterogeneous clients. So perhaps it is a rare bug case?

Since I've managed to hit it myself once, I thought I would try and reproduce it locally with Chrome, but I can't figure out a way of generating lots of requests from Chrome with keepalives disabled. I haven't been able to hit it again with normal use. Any smart ideas there? Otherwise I might try and do it generating the requests from a go client.

@bradfitz bradfitz added the Testing An issue that has been verified to require only test changes, not just a test failure. label May 10, 2016
@quentinmit quentinmit added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 19, 2016
@bradfitz
Copy link
Contributor Author

I think this is almost certainly the same as #15425 which is being fixed by https://golang.org/cl/23287

Closing as dup.

@golang golang locked and limited conversation to collaborators May 20, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
None yet
Development

No branches or pull requests

5 participants