x/net/http2: TestServer_RejectsLargeFrames fails with "An existing connection was forcibly closed by the remote host" on windows #13434

alexbrainman · 2015-11-30T23:35:35Z

From windows-amd64-gce builder http://build.golang.org/log/a0906e4fa3713e6512cdff9af6662d1db0faad0d

--- FAIL: TestServer_RejectsLargeFrames (0.31s)
    http2_test.go:64: 2015/11/30 20:57:53 127.0.0.1:49238: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/11/30 20:57:53 127.0.0.1:49238: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/11/30 20:57:53 127.0.0.1:49238: connection error: PROTOCOL_ERROR
...
    http2_test.go:64: 2015/11/30 20:57:53 127.0.0.1:49238: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/11/30 20:57:53 127.0.0.1:49238: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/11/30 20:57:53 127.0.0.1:49238: connection error: PROTOCOL_ERROR
    server_test.go:413: Error while expecting a GOAWAY frame: read tcp 127.0.0.1:49238->127.0.0.1:49237: wsarecv: An existing connection was forcibly closed by the remote host.
FAIL
FAIL    golang.org/x/net/http2  2.668s

I can reproduce this here. I don't know what the problem is.

Alex

The text was updated successfully, but these errors were encountered:

bradfitz · 2015-11-30T23:38:47Z

The client sends too much data.

The server replies with a Write of GOAWAY + also closes the TCP connection.

The client tries to read, and sees "wsarecv: An existing connection was forcibly closed by the remote host" before the GOAWAY.

alexbrainman · 2015-11-30T23:42:38Z

I suspect you are correct. But why you can read last GOAWAY message on unix, but not on Windows? In fact I can make the test PASS on windows, if I adjust some timers in your code. Strange.

Alex

mattn · 2015-11-30T23:57:50Z

I could reproduce this.

--- FAIL: TestServer_RejectsLargeFrames (0.13s)
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR

    ...SNIP...

    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    server_test.go:413: Error while expecting a GOAWAY frame: read tcp 127.0.0.1:55389->127.0.0.1:55388: wsarecv: An existing connection was forcibly closed by the remote host.
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR

    ...SNIP...

    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
    http2_test.go:64: 2015/12/01 08:56:51 127.0.0.1:55389: connection error: PROTOCOL_ERROR
FAIL
exit status 1
FAIL    golang.org/x/net/http2  1.215s

mattn · 2015-12-01T00:02:47Z

diff --git a/http2/frame.go b/http2/frame.go
index 6b8a74f..0ef0f6c 100644
--- a/http2/frame.go
+++ b/http2/frame.go
@@ -133,6 +133,7 @@ var frameParsers = map[FrameType]frameParser{
 }

 func typeFrameParser(t FrameType) frameParser {
+   println("frame type is", t)
    if f := frameParsers[t]; f != nil {
        return f
    }

When modify frame.go like above.

frame type is 4
frame type is 4
frame type is 4
frame type is 4
frame type is 0
frame type is 0
frame type is 0
frame type is 0
frame type is 0
frame type is 0
frame type is 0
frame type is 0
frame type is 0
frame type is 0
frame type is 0

Some FrameSettings comes. After many FrameData comes.

alexbrainman · 2015-12-03T06:01:54Z

I had some time to play with this. I made this changes:

diff --git a/http2/http2_test.go b/http2/http2_test.go
index 0a4da46..20d0fae 100644
--- a/http2/http2_test.go
+++ b/http2/http2_test.go
@@ -61,7 +61,7 @@ func (w twriter) Write(p []byte) (n int, err error) {
            }
        }
    }
-   w.t.Logf("%s", p)
+   //w.t.Logf("%s", p)
    return len(p), nil
 }

diff --git a/http2/logger.go b/http2/logger.go
new file mode 100644
index 0000000..6301e37
--- /dev/null
+++ b/http2/logger.go
@@ -0,0 +1,90 @@
+// Copyright 2015 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package http2
+
+import (
+   "fmt"
+   "net"
+   "time"
+)
+
+type ConnLogger struct {
+   title string
+   conn  net.Conn
+}
+
+func NewConnLogger(title string, c net.Conn) *ConnLogger {
+   return &ConnLogger{title: title, conn: c}
+}
+
+func sliceOfBytesWithManyElementsToString(b []byte) string {
+   if len(b) == 0 {
+       return ""
+   }
+   s := ""
+   for i, v := range b {
+       if i > 0 {
+           s += " "
+       }
+       s += fmt.Sprintf("%d", v)
+       if i > 40 {
+           s += " ..."
+           break
+       }
+   }
+   return s
+}
+
+func (cl *ConnLogger) Read(b []byte) (n int, err error) {
+   fmt.Printf("%s: about to read some data\n", cl.title)
+   n2, err2 := cl.conn.Read(b)
+   if err2 != nil {
+       fmt.Printf("%s: read error: %v\n", cl.title, err2)
+   } else {
+       fmt.Printf("%s: %d bytes read: [%s]\n", cl.title, n2, sliceOfBytesWithManyElementsToString(b[:n2]))
+   }
+   return n2, err2
+}
+
+func (cl *ConnLogger) Write(b []byte) (n int, err error) {
+   fmt.Printf("%s: about to write %d bytes: [%s]\n", cl.title, len(b), sliceOfBytesWithManyElementsToString(b))
+   n2, err2 := cl.conn.Write(b)
+   if err2 != nil {
+       fmt.Printf("%s: write error: %v\n", cl.title, err2)
+   } else {
+       fmt.Printf("%s: %d bytes written\n", cl.title, n2)
+   }
+   return n2, err2
+}
+
+func (cl *ConnLogger) Close() error {
+   err2 := cl.conn.Close()
+   if err2 != nil {
+       fmt.Printf("%s: close error: %v\n", cl.title, err2)
+   } else {
+       fmt.Printf("%s: close OK\n", cl.title)
+   }
+   return err2
+}
+
+func (cl *ConnLogger) LocalAddr() net.Addr {
+   return cl.conn.LocalAddr()
+}
+
+func (cl *ConnLogger) RemoteAddr() net.Addr {
+   return cl.conn.RemoteAddr()
+}
+
+func (cl *ConnLogger) SetDeadline(t time.Time) error {
+   return cl.conn.SetDeadline(t)
+}
+
+func (cl *ConnLogger) SetReadDeadline(t time.Time) error {
+   return cl.conn.SetReadDeadline(t)
+}
+
+func (cl *ConnLogger) SetWriteDeadline(t time.Time) error {
+   return cl.conn.SetWriteDeadline(t)
+}
diff --git a/http2/server.go b/http2/server.go
index 8ef9e24..99e4b32 100644
--- a/http2/server.go
+++ b/http2/server.go
@@ -198,6 +198,7 @@ func ConfigureServer(s *http.Server, conf *Server) error {
 }

 func (srv *Server) handleConn(hs *http.Server, c net.Conn, h http.Handler) {
+   c = NewConnLogger("server", c)
    sc := &serverConn{
        srv:              srv,
        hs:               hs,
diff --git a/http2/server_test.go b/http2/server_test.go
index 7a42051..de4a6a5 100644
--- a/http2/server_test.go
+++ b/http2/server_test.go
@@ -131,8 +131,9 @@ func newServerTester(t testing.TB, handler http.HandlerFunc, opts ...interface{}
        if err != nil {
            t.Fatal(err)
        }
-       st.cc = cc
-       st.fr = NewFramer(cc, cc)
+       cm := NewConnLogger("client", cc)
+       st.cc = cm
+       st.fr = NewFramer(cm, cm)
    }
    return st
 }

so I can log all tcp activity and compare what is different between my linux and windows programs. Here are https://gist.github.com/alexbrainman/5cef4b81f3a8ae2f9218#file-linux-txt and https://gist.github.com/alexbrainman/5cef4b81f3a8ae2f9218#file-windows-txt logs for linux and windows. It looks like the difference is in how client handles server closing connection in the middle of large client write. Windows client write fails immediately, followed by client read error. Linux client write fails too, but is followed by successfull read and read EOF after that.

I don't think you can expect this all to work reliably accross different OS and environments. I have changed the test this way:

diff --git a/http2/http2_test.go b/http2/http2_test.go
index 0a4da46..20d0fae 100644
--- a/http2/http2_test.go
+++ b/http2/http2_test.go
@@ -61,7 +61,7 @@ func (w twriter) Write(p []byte) (n int, err error) {
            }
        }
    }
-   w.t.Logf("%s", p)
+   //w.t.Logf("%s", p)
    return len(p), nil
 }

diff --git a/http2/server_test.go b/http2/server_test.go
index 7a42051..02e4186 100644
--- a/http2/server_test.go
+++ b/http2/server_test.go
@@ -918,7 +918,7 @@ func TestServer_RejectsLargeFrames(t *testing.T) {
    // Write too large of a frame (too large by one byte)
    // We ignore the return value because it's expected that the server
    // will only read the first 9 bytes (the headre) and then disconnect.
-   st.fr.WriteRawFrame(0xff, 0, 0, make([]byte, defaultMaxReadFrameSize+1))
+   st.fr.WriteRawFrame(0xff, 0, 0, make([]byte, 100000000))

    gf := st.wantGoAway()
    if gf.ErrCode != ErrCodeFrameSize {

and now it is failing on linux too with:

# go test -v -i && go test -run=sLa
--- FAIL: TestServer_RejectsLargeFrames (2.14s)
        server_test.go:413: Error while expecting a GOAWAY frame: timeout waiting for frame
FAIL
exit status 1
FAIL    golang.org/x/net/http2  2.327s
#

Alex

rsc · 2015-12-28T18:48:37Z

FWIW yes you cannot assume that write+close will result in the client seeing the write before the close, especially if the server does the write+close while the client is doing its own large write.
http://blog.netherlabs.nl/articles/2009/01/18/the-ultimate-so_linger-page-or-why-is-my-tcp-not-reliable

bradfitz · 2015-12-28T18:58:23Z

I forgot to update this bug with https://golang.org/cl/18105 which fixes the spinning error and log spam.

gopherbot · 2016-01-13T02:00:22Z

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

Updates golang/go#13434 Change-Id: Icc098d9a6e1af55d36e828fa21d88b967f2f0131 Reviewed-on: https://go-review.googlesource.com/18553 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

alexbrainman added the OS-Windows label Nov 30, 2015

rsc added this to the Unreleased milestone Dec 28, 2015

bcmills mentioned this issue Feb 20, 2020

x/net/http: TestServer_RejectsLargeFrames failure with "Error while expecting a GOAWAY frame: EOF" on plan9-arm builder #37321

Closed

rsc mentioned this issue May 22, 2020

x/build/cmd/gopherbot: released things get marked Unreleased #39213

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

x/net/http2: TestServer_RejectsLargeFrames fails with "An existing connection was forcibly closed by the remote host" on windows #13434

x/net/http2: TestServer_RejectsLargeFrames fails with "An existing connection was forcibly closed by the remote host" on windows #13434

alexbrainman commented Nov 30, 2015

bradfitz commented Nov 30, 2015

alexbrainman commented Nov 30, 2015

mattn commented Nov 30, 2015

mattn commented Dec 1, 2015

alexbrainman commented Dec 3, 2015

rsc commented Dec 28, 2015

bradfitz commented Dec 28, 2015

gopherbot commented Jan 13, 2016

x/net/http2: TestServer_RejectsLargeFrames fails with "An existing connection was forcibly closed by the remote host" on windows #13434

x/net/http2: TestServer_RejectsLargeFrames fails with "An existing connection was forcibly closed by the remote host" on windows #13434

Comments

alexbrainman commented Nov 30, 2015

bradfitz commented Nov 30, 2015

alexbrainman commented Nov 30, 2015

mattn commented Nov 30, 2015

mattn commented Dec 1, 2015

alexbrainman commented Dec 3, 2015

rsc commented Dec 28, 2015

bradfitz commented Dec 28, 2015

gopherbot commented Jan 13, 2016