x/net/http2: return flow control when stream closes with buffered data

[wujieliulan]

I ran into a case where my http2 transport cannot send any data to my http2 server with the existing connection. The issue is client sent some data in a stream, when server receives it, there was a stream error (or stream closed) and the data received was discarded., server never got a chance to send windowupdate for this client connection, client can no longer send more data, even for new streams.

I did some simple changes and this issue is fixed, but I am not sure if this is the right way to fix. Could you advice? Is there a similar issue for server sending to client?

Here is the change I made:

diff --git a/http2/server.go b/http2/server.go
index f368738..b924c3d 100644
--- a/http2/server.go
+++ b/http2/server.go
@@ -1277,6 +1277,9 @@ func (sc *serverConn) processSettingInitialWindowSize(val uint32) error {

 func (sc *serverConn) processData(f *DataFrame) error {
        sc.serveG.check()
+       if len(f.Data()) > 0 {
+               sc.sendWindowUpdate(nil, len(f.Data())) // conn-level
+       }
        // "If a DATA frame is received whose stream is not in "open"
        // or "half closed (local)" state, the recipient MUST respond
        // with a stream error (Section 5.4.2) of type STREAM_CLOSED."
@@ -1764,7 +1767,7 @@ func (sc *serverConn) noteBodyReadFromHandler(st *stream, n int) {

 func (sc *serverConn) noteBodyRead(st *stream, n int) {
        sc.serveG.check()
-       sc.sendWindowUpdate(nil, n) // conn-level
+       //sc.sendWindowUpdate(nil, n) // conn-level
        if st.state != stateHalfClosedRemote && st.state != stateClosed {
                // Don't send this WINDOW_UPDATE if the stream is closed
                // remotely.

[bradfitz]

Your patch looks like you're just sending infinite flow control, giving them new tokens whenever they send new stuff, without any user acknowledgement.

Do you have a more complete repro or instructions?

[bradfitz]

Also, can you try Go 1.7? @adg changed some flow control stuff recently.

[wujieliulan]

The logic is this: when server receives a data frame, it should send WindowUpdate(len(data) ) for this client connection, even if the stream has error or closed and data can not be delivered to the handler. When data is read by handler, then it should send WindowUpdate for this stream.

I used the latest golang.org/x/net/http2.

[bradfitz]

The logic is this: when server receives a data frame, it should send WindowUpdate(len(data) ) for this client connection, even if the stream has error or closed and data can not be delivered to the handler.

But that doesn't look like what your patch does. You seem to be always sending flow control, not just for closed streams.

So would a better summary of the problem be: "the server doesn't refresh connection-level flow control when clients send DATA frames to closed streams" ?

[wujieliulan]

You summary is accurate. The patch does not always send flow control, it separates sending connection-level flow control and stream level:
when a data frame is received, send connection-level flow control of len(data)
when data is read by handler, send stream-level flow control of len(data)

That being said, I am not trying to propose a fix, just trying to provide more info to help find the issue.

[wujieliulan]

It seems transport has similar issue: the client (or transport) doesn't refresh connection-level flow control when server sends DATA frames to closed streams".

In transport.go, sending flow control for connection-level and stream-level are both in Read(). I think connection-level flow control should be sent whenever a data frame is received, stream-level flow control should be sent when data is read by handler.

[bradfitz]

I think connection-level flow control should be sent whenever a data frame is received, stream-level flow control should be sent when data is read by handler.

No, that doesn't sound right. If that were done, clients could repeatedly open new streams (which start with a default flow control) and write an unbounded amount.

I think we need to verify buffered flow control (from server-read but handler-unread bytes) is always returned on stream close, or when writing to a stream not accepting data.

I've been traveling the past 20 hours (to an HTTP workshop, as it happens) so I'll look at this after I've had some sleep and get a free moment.

If you or somebody else wants to write stand-alone repro unit tests in the x/net/http2 style, using its existing test framework, that would be helpful.

[bradfitz]

This is actually very easy to reproduce:

type funcReader func([]byte) (n int, err error)

func (f funcReader) Read(p []byte) (n int, err error) { return f(p) }

func TestUnreadFlowControlReturned(t *testing.T) {
        unblock := make(chan bool, 1)
        defer close(unblock)

        st := newServerTester(t, func(w http.ResponseWriter, r *http.Request) {
                <-unblock
        }, optOnlyServer)
        defer st.Close()

        tr := &Transport{TLSClientConfig: tlsConfigInsecure}
        defer tr.CloseIdleConnections()

        for i := 0; i < 10; i++ {
                println(i)
                body := io.MultiReader(
                        io.LimitReader(neverEnding('A'), 16<<10),
                        funcReader(func([]byte) (n int, err error) {
                                unblock <- true
                                return 0, io.EOF
                        }),
                )
                req, _ := http.NewRequest("POST", st.ts.URL, body)
                res, err := tr.RoundTrip(req)
                if err != nil {
                        t.Fatal(err)
                }
                res.Body.Close()
                println(i, "done")
        }

}

As feared, it hangs after 3 iterations, blocked on waiting for flow control to write the 4th body:

goroutine 37 [semacquire]:
sync.runtime_notifyListWait(0xc420014ed0, 0x0)
        /Users/bradfitz/go/src/runtime/sema.go:267 +0x122
sync.(*Cond).Wait(0xc420014ec0)
        /Users/bradfitz/go/src/sync/cond.go:57 +0x80
golang.org/x/net/http2.(*clientStream).awaitFlowControl(0xc4202ea280, 0x1, 0x0, 0x0, 0x0)
        /Users/bradfitz/src/golang.org/x/net/http2/transport.go:989 +0x11c
golang.org/x/net/http2.(*clientStream).writeRequestBody(0xc4202ea280, 0x507dc0, 0xc4202ec160, 0x12641e0, 0xc4202de150, 0x0, 0x0)
        /Users/bradfitz/src/golang.org/x/net/http2/transport.go:904 +0x23c
golang.org/x/net/http2.(*Transport).getBodyWriterState.func1()
        /Users/bradfitz/src/golang.org/x/net/http2/transport.go:1824 +0xa1
created by golang.org/x/net/http2.bodyWriterState.scheduleBodyWrite
        /Users/bradfitz/src/golang.org/x/net/http2/transport.go:1871 +0x8e

This is pretty bad and I'm surprised nobody has encountered this earlier. Thanks for reporting it.

@adg, @broady, this isn't a regression from Go 1.6, but it's pretty nasty and I think the fix will be easy.

[wujieliulan]

Thanks for the update and for finding the issue #16498. After fixing these issues, it would be nice to test the fair share of bandwidth both ways. For example, with a fix rate connection, open one stream, verify it utilizes all the bandwidth, then open another stream, each should use 1/2. Then keep 2 steams open and stop transferring on one steam, the other one should use the full bandwidth again. Then open more steams and so on so forth. Also verify no steam blocks the connection level frames. SSH implements streams with flow control, which could be referenced.

[bradfitz]

Sent https://golang.org/cl/25231

[gopherbot]

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

[broady]

Is that a regression from 1.5?

[bradfitz]

@broady, yes. The bug was introduced in Go 1.6, so arguably it's not Go 1.7 material since it's not a 1.6->1.7 regression, but it's a pretty bad case (things fail to work) and there's no real workaround. I'm surprised nobody has reported it previously. It would only take effect for certain traffic patterns where things were aborted without reading bodies.

[wujieliulan]

Thanks for your quick response (test and confirm the issue, find #16498,
and a fix).

With the fix, there are still uncovered cases. For example, if the
sender sends large chunk of data and use up all connection level flow quota, but the
receiver's handler never reads the data, the data will be buffered, but
the current implementation would not send windows update and thus the
whole connection is blocked. In this case, the data did arrive to the
server and the connection is wide open, it should not block other steams.

The basic idea of windows based flow control is: sender send n bytes of
data and closes the window by n bytes, receiver "consumes" m bytes of
data and opens by m bytes (by sending window update).

For connection level, whenever a data frame is processed, it is
"consumed" from connection level's point of view, we don't really care if
the data is delivered or discarded. Therefore, as soon as a data frame
is processed, we should immediately send window update to open up
connection level. Even if some crazy client send bogus data frame,
server should not try to enforce anything, as long as server receives
the data frame, it should immediately open connection level window by
the amount of data received, since from the connection point of view,
the data is delivered and the connection is open for more data, good or
bad. This applies to both server and client (transport).

For steam level, the data is "consumed" only when the handler read it,
so current implementation is correct. We should move sending connection
level flow control from there to processData()

[broady]

I'm +1 to get this into 1.7, since it's a regression. I don't think there necessarily needs to be a regression from the preceding major version to warrant inclusion at this point.

What do you think, @adg?

[bradfitz]

With the fix, there are still uncovered cases. For example, if the
sender sends large chunk of data and use up all connection level flow quota, but the
receiver's handler never reads the data, the data will be buffered, but
the current implementation would not send windows update and thus the
whole connection is blocked

No, with the CL I sent out, that's exactly one of the cases that's tested and fixed.

If you have a test program to demonstrate otherwise I'd be interested.

In this case, the data did arrive to the server and the connection is wide open, it should not block other steams.

I'm not sure what you mean by this. HTTP/2 defines both connection-level and stream-level flow control, and rules for each. Incoming DATA frame bytes deduct against both. What do you think we're doing wrong specifically?

[bradfitz]

Still need to bundle it in to std.

[gopherbot]

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

[wujieliulan]

Here is a test to show one stream can still block the whole connection:
h2test.tar.gz
My original patch fixes this but we need to fix inflow. Currently there is only one sc.inflow and all st.inflow links to it. I think we should separate sc and st level inflow, then we need to add
sc.inflow.take(int32(len(data))) before c.sendWindowUpdate(nil, len(data)).

[bradfitz]

@wujieliulan, the behavior for your h2test.tar.gz test program looks correct per the spec with the default of conn-level flow control and stream-level flow control being equal. You have one stream exhausting the conn-level flow control and blocking forever, so it makes sense that the other one can't proceed.

Maybe we could have different default flow control values, having more for the conn so a single bad stream can't have such impact. Can you file a separate bug for that? This one is now closed and we don't reuse bugs. Feel free to reference this one in your new bug report.

[wujieliulan]

From rfc7540:
5.2. Flow Control
"A flow-control scheme ensures that streams on the same connection do not destructively interfere with each other. "

The test is an extreme case, but in real world, a steam with a slow consumer (for example, the handler can't consume data fast enough), that steam will block all other steams in the same connection, even if the connection is wide open and have lots of available bandwidth.

Since this bug is closed, let me file another one. Thanks.

[gopherbot]

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

[gopherbot]

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