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

Comments

Projects
None yet
5 participants
@bradfitz
Copy link
Member

commented Jan 21, 2016

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

This comment has been minimized.

Copy link
Member

commented Jan 21, 2016

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

This comment has been minimized.

Copy link
Member Author

commented Jan 26, 2016

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

This comment has been minimized.

Copy link

commented Jan 26, 2016

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

@bradfitz

This comment has been minimized.

Copy link
Member Author

commented Jan 26, 2016

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

http2: reduce log spam, especially on Windows
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

This comment has been minimized.

Copy link

commented Jan 26, 2016

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

@gopherbot gopherbot closed this in aff6aa0 Jan 26, 2016

@bradfitz bradfitz modified the milestones: Go1.7, Go1.6Maybe Jan 26, 2016

@bradfitz

This comment has been minimized.

Copy link
Member Author

commented Jan 26, 2016

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

@bradfitz bradfitz reopened this Jan 26, 2016

@bradfitz

This comment has been minimized.

Copy link
Member Author

commented Jan 26, 2016

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

@bradfitz

This comment has been minimized.

Copy link
Member Author

commented Jan 26, 2016

@alexbrainman

This comment has been minimized.

Copy link
Member

commented Jan 31, 2016

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

Alex

@bradfitz

This comment has been minimized.

Copy link
Member Author

commented Mar 31, 2016

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

This comment has been minimized.

Copy link
Contributor

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

This comment has been minimized.

Copy link
Member Author

commented May 20, 2016

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

Closing as dup.

@bradfitz bradfitz closed this May 20, 2016

@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.
You can’t perform that action at this time.