x/net/http2: the peer windows size not updated in processSettingInitialWindowSize()

[crowfrog]

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

golang:1.10.0 linux

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

container: rhel
kubenet:

What did you do?

In processSettingInitialWindowSize()
The code adjust the size of all stream flow control windows but not change the server connection flow's.
That makes all new steam will use 65535 as initial window size but not the value from InitialWindowSize in SETTINGS

What did you expect to see?

the window size could be updated if client send InitialWindowSize in SETTINGS

What did you see instead?

65535 will be cost out speedily in high load performance test and makes server pending response until clinet WINDOW_UPDATE comes.
It impacts latency of load test.

[bradfitz]

I don't remember the code to say without looking at it, but this isn't an area I knew of any problems.

Did you find this through reading the code alone, or do you have a repro? You say it impacts latency in a load test. Which client or tool are you using for load testing so we can see this behavior?

Can you post the output of the server running with environment variable GODEBUG=http2debug=2?

Thanks!

/cc @fraenkel

[bradfitz]

/cc @tombergan

[crowfrog]

hi @bradfitz ,

the load test tool is a private tool which be implemented by JAVA.
I change the tool's configuration to let it send SETTINGS with "INITIAL_WINDOW_SIZE = 10485760" when connection set up.
And I add a print in newStream() of server.go.

func (sc *serverConn) newStream(id, pusherID uint32, state streamState) *stream {
        sc.serveG.check()
        if id == 0 {
                panic("internal error: cannot create stream with id 0")
        }

        ctx, cancelCtx := contextWithCancel(sc.baseCtx)
        st := &stream{
                sc:        sc,
                id:        id,
                state:     state,
                ctx:       ctx,
                cancelCtx: cancelCtx,
        }
        st.cw.Init()
        st.flow.conn = &sc.flow // link to conn-level counter
        st.flow.add(sc.initialStreamSendWindowSize)
        sc.logf("newStream %v with %v. %v, %v", st.id, st.flow.available(), sc.initialStreamSendWindowSize, sc.flow)          //<=== new added code

        st.inflow.conn = &sc.inflow // link to conn-level counter

then I got following prints in my log:
2018/08/10 09:30:35 newStream 3 with 65535. 10485760, {65535 }
2018/08/10 09:30:35 newStream 5 with 65091. 10485760, {65091 }
2018/08/10 09:30:35 newStream 7 with 64647. 10485760, {64647 }
2018/08/10 09:30:35 newStream 9 with 64203. 10485760, {64203 }
2018/08/10 09:30:35 newStream 11 with 63759. 10485760, {63759 }
2018/08/10 09:30:35 newStream 13 with 63315. 10485760, {63315 }
2018/08/10 09:30:35 newStream 15 with 62871. 10485760, {62871 }
2018/08/10 09:30:35 newStream 17 with 62427. 10485760, {62427 }
2018/08/10 09:30:35 newStream 19 with 61983. 10485760, {61983 }
2018/08/10 09:30:35 newStream 21 with 61539. 10485760, {61539 }
2018/08/10 09:30:35 newStream 23 with 61095. 10485760, {61095 }
2018/08/10 09:30:35 newStream 25 with 60651. 10485760, {60651 }
2018/08/10 09:30:35 newStream 27 with 60207. 10485760, {60207 }
2018/08/10 09:30:35 newStream 29 with 59763. 10485760, {59763 }
2018/08/10 09:30:35 newStream 31 with 59319. 10485760, {59319 }
2018/08/10 09:30:35 newStream 33 with 58875. 10485760, {58875 }
2018/08/10 09:30:35 newStream 35 with 58431. 10485760, {58431 }
...

That means all new stream will use st.flow.conn.n(sc.flow.n) but not st.flow.n as window size initial value.
And the connection flow (sc.flow) not updated by SETTINGS in processSettingInitialWindowSize()

[bradfitz]

Can you post the output of the server running with environment variable GODEBUG=http2debug=2?

[crowfrog]

hi @bradfitz
It is difficult to get the output by your need in my enviroment.
But I think this issue can be found by checking codes.
in server.go:
processSettingInitialWindowSize(), processWindowUpdate(), newStream()
in flow.go:
add(), take(), available()

[bradfitz]

This is unlikely to get prioritized attention without GODEBUG=http2debug=2.

[fraenkel]

@crowfrog I think there is something else amiss. I modified a testcase LargeWrite_FlowControlled and added a similar printout. What I see is

newStream 1 flow=123 inflow=1048576 initialWS=123 srvRecv=1048576
newStream 3 flow=123 inflow=1048576 initialWS=123 srvRecv=1048576

The relevant http2debug shows:

    http2_test.go:66: 2018/09/16 18:59:32 http2: server connection from 127.0.0.1:33724 on 0xc00009f380
    http2_test.go:66: 2018/09/16 18:59:32 http2: Framer 0xc0001981c0: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
....
    http2_test.go:66: 2018/09/16 18:59:32 http2: Framer 0xc0001981c0: read SETTINGS len=6, settings: INITIAL_WINDOW_SIZE=123
    http2_test.go:66: 2018/09/16 18:59:32 http2: server processing setting [INITIAL_WINDOW_SIZE = 123]

Without more information it is hard to determine where if any a problem is.

[crowfrog]

hi Fraenkel & Bradfitz,

Sorry for relply so late!
I checked other tools's log (such as nghttp2) and websites which support http2 (https://www.wappalyzer.com/technologies/http-2, etc.)
I found the peer will send WINDOW_UPDATE to set connection window size after connection setup.
And after check RFC7540, I think this behavior should be correct.
So this issue should be invalid.

B.R