client: does not respect server advertised max number of streams

[jared2501]

What version of gRPC are you using?

google.golang.org/grpc v1.33.2

What version of Go are you using (go version)?

1.15.0

What operating system (Linux, Windows, …) and version?

linux

What did you do? What did you expect to see? What did you see instead?

I have a server running the go stdlib HTTP2 that is serving a go gRPC client. The server is sending the client a bunch of PROTOCOL_ERRORs while under load. I annotated the server code with a bunch of print statements:

$ git diff 4bcb0159cc92457f2902e972b7e7a44372ed1a68 server/vendor/golang.org/x/net/http2/server.go | cat
diff --git a/server/vendor/golang.org/x/net/http2/server.go b/server/vendor/golang.org/x/net/http2/server.go
index 7c0559d..8f43dfc 100644
--- a/server/vendor/golang.org/x/net/http2/server.go
+++ b/server/vendor/golang.org/x/net/http2/server.go
@@ -1686,6 +1686,7 @@ func (sc *serverConn) processData(f *DataFrame) error {
 		// RFC 7540, sec 8.1.2.6: A request or response is also malformed if the
 		// value of a content-length header field does not equal the sum of the
 		// DATA frame payload lengths that form the body.
+		fmt.Println("here6")
 		return streamError(id, ErrCodeProtocol)
 	}
 	if f.Length > 0 {
@@ -1830,6 +1831,7 @@ func (sc *serverConn) processHeaders(f *MetaHeadersFrame) error {
 	if sc.curClientStreams+1 > sc.advMaxStreams {
 		if sc.unackedSettings == 0 {
 			// They should know better.
+			fmt.Println(fmt.Sprintf("here7 %d", sc.advMaxStreams))
 			return streamError(id, ErrCodeProtocol)
 		}
 		// Assume it's a network race, where they just haven't
@@ -1895,16 +1897,19 @@ func (st *stream) processTrailerHeaders(f *MetaHeadersFrame) error {
 	}
 	st.gotTrailerHeader = true
 	if !f.StreamEnded() {
+		fmt.Println("here8")
 		return streamError(st.id, ErrCodeProtocol)
 	}
 	if len(f.PseudoFields()) > 0 {
+		fmt.Println("here9")
 		return streamError(st.id, ErrCodeProtocol)
 	}
 	if st.trailer != nil {
 		for _, hf := range f.RegularFields() {
 			key := sc.canonicalHeader(hf.Name)
 			if !httpguts.ValidTrailerHeader(key) {
+				fmt.Println(fmt.Sprintf("here!!! %s", key))
 				// TODO: send more details to the peer somehow. But http2 has
 				// no way to send debug data at a stream level. Discuss with
 				// HTTP folk.
@@ -1923,6 +1928,7 @@ func checkPriority(streamID uint32, p PriorityParam) error {
 		// this as a stream error (Section 5.4.2) of type PROTOCOL_ERROR."
 		// Section 5.3.3 says that a stream can depend on one of its dependencies,
 		// so it's only self-dependencies that are forbidden.
+		fmt.Println("here2")
 		return streamError(streamID, ErrCodeProtocol)
 	}
 	return nil
@@ -1989,6 +1995,7 @@ func (sc *serverConn) newWriterAndRequest(st *stream, f *MetaHeadersFrame) (*res
 	isConnect := rp.method == "CONNECT"
 	if isConnect {
 		if rp.path != "" || rp.scheme != "" || rp.authority == "" {
+			fmt.Println("here3")
 			return nil, nil, streamError(f.StreamID, ErrCodeProtocol)
 		}
 	} else if rp.method == "" || rp.path == "" || (rp.scheme != "https" && rp.scheme != "http") {
@@ -2002,12 +2009,14 @@ func (sc *serverConn) newWriterAndRequest(st *stream, f *MetaHeadersFrame) (*res
 		// "All HTTP/2 requests MUST include exactly one valid
 		// value for the :method, :scheme, and :path
 		// pseudo-header fields"
+		fmt.Println("here3")
 		return nil, nil, streamError(f.StreamID, ErrCodeProtocol)
 	}
 	bodyOpen := !f.StreamEnded()
 	if rp.method == "HEAD" && bodyOpen {
 		// HEAD requests can't have bodies
+		fmt.Println("here4")
 		return nil, nil, streamError(f.StreamID, ErrCodeProtocol)
 	}
@@ -2091,6 +2100,7 @@ func (sc *serverConn) newWriterAndRequestNoBody(st *stream, rp requestParam) (*r
 		var err error
 		url_, err = url.ParseRequestURI(rp.path)
 		if err != nil {
+			fmt.Println("here5")
 			return nil, nil, streamError(st.id, ErrCodeProtocol)
 		}
 		requestURI = rp.path

And then I ran the gRPC client against it. The client creates one gRPC client for the entire process (constructed in the main function). I see the following log lines on the server:

here7 320
hello stream stream error: stream ID 167743; PROTOCOL_ERROR
here7 320
hello stream stream error: stream ID 167745; PROTOCOL_ERROR

This indicates that the grpc-go code is not respecting the maximum number of streams, and starting new streams before the server has been made aware of streams closing.

I'm still trying to track down whether this is the grpc-go client not following the server's orders, of the http2 server (in the go stdlib) incorrectly handling closed/opened streams.

[jared2501]

Looking over the code in http2_client.go, it looks like closeStream method increments the t.streamQuota before it guarantees the server has seen the RST_STREAM frame. Am I reading the code correctly? It would appear that this means the gRPC client can violate the maximum number of streams that the server sends in the SETTINGS frame.

(edit) Nevermind, I understand the grpc-go code now. I actually believe that it's a bug in the go http2/server.go code. I have a diff that I've applied that appears to have fixed the issue.

The quick summary is that the http2 serverConn sends a RST_FRAME when the server closes successfully, but it does not immediately decrement the sc.curClientStreams. This happens asynchronously in sc.wroteFrame which is called from sc.serve. The call to sc.wroteFrame happens in a giant select statement that races with reads from sc.readFrameCh - this means that it's entirely possible for the following sequence of actions:

1. The http.Handler closes the stream.
2. A RST_FRAME is enqueued & sent to the client. The call to decrement sc.curClientStreams is enqueued to be processed later.
3. The grpc-go client receives the RST_FRAME from the server and releases a new stream to the server.
4. The server receives the new stream frame from the client, and since the sc.curClientStreams hasn't been decremented from step 2 yet it rejects the new stream with a PROTCOL_ERROR.

This sequence events is highly possible in the setup that I'm testing since A) the two processes are on the same machine, and B) the server is under heavy load.

I will submit a bug to https://github.com/golang/go and link it here.

[dfawley]

Thank you for the report. I'll close this issue since it does look like a bug in the go http2 server.