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

[alexbrainman]

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

[bradfitz]

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]

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]

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]

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]

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]

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]

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

[gopherbot]

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