x/net/http2: hung request to vision.googleapis.com (bad flow control?)

[broady]

I narrowed the issue to c558a53.
I suspect it's caused by https://golang.org/cl/25382.

$ GODEBUG=http2debug=2 GOLANG_SAMPLES_PROJECT_ID=<ELIDED> go test -v github.com/GoogleCloudPlatform/golang-samples/vision/label
=== RUN   TestLabel
2016/08/04 20:28:16 http2: Transport failed to get client conn for accounts.google.com:443: http2: no cached connection was available
2016/08/04 20:28:16 http2: Transport creating client conn to [2607:f8b0:4005:804::200d]:443
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2016/08/04 20:28:16 http2: Transport encoding header ":authority" = "accounts.google.com"
2016/08/04 20:28:16 http2: Transport encoding header ":method" = "POST"
2016/08/04 20:28:16 http2: Transport encoding header ":path" = "/o/oauth2/token"
2016/08/04 20:28:16 http2: Transport encoding header ":scheme" = "https"
2016/08/04 20:28:16 http2: Transport encoding header "content-type" = "application/x-www-form-urlencoded"
2016/08/04 20:28:16 http2: Transport encoding header "content-length" = "208"
2016/08/04 20:28:16 http2: Transport encoding header "accept-encoding" = "gzip"
2016/08/04 20:28:16 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote HEADERS flags=END_HEADERS stream=1 len=80
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote DATA stream=1 len=208 data="client_id=<ELIDED>&client_secret=<ELIDED>&grant_type=refresh_token&refresh_token=<ELIDED>"
2016/08/04 20:28:16 http2: Framer 0xc420208180: read SETTINGS len=24, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=16384
2016/08/04 20:28:16 http2: Transport received SETTINGS len=24, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=16384
2016/08/04 20:28:16 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote DATA flags=END_STREAM stream=1 len=0 data=""
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote SETTINGS flags=ACK len=0
2016/08/04 20:28:16 http2: Framer 0xc420208180: read WINDOW_UPDATE len=4 (conn) incr=983041
2016/08/04 20:28:16 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2016/08/04 20:28:16 http2: Framer 0xc420208180: read SETTINGS flags=ACK len=0
2016/08/04 20:28:16 http2: Transport received SETTINGS flags=ACK len=0
2016/08/04 20:28:16 http2: Framer 0xc420208180: read HEADERS flags=END_HEADERS stream=1 len=1429
2016/08/04 20:28:16 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=1429
2016/08/04 20:28:16 http2: Framer 0xc420208180: read DATA flags=PADDED stream=1 len=341 data="<ELIDED>"
2016/08/04 20:28:16 http2: Transport received DATA flags=PADDED stream=1 len=341 data="<ELIDED>"
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote WINDOW_UPDATE len=4 (conn) incr=192
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote WINDOW_UPDATE stream=1 len=4 incr=192
2016/08/04 20:28:16 http2: Framer 0xc420208180: read DATA flags=END_STREAM|PADDED stream=1 len=216 data="<ELIDED>"
2016/08/04 20:28:16 http2: Transport received DATA flags=END_STREAM|PADDED stream=1 len=216 data="<ELIDED>"
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote WINDOW_UPDATE len=4 (conn) incr=206
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote WINDOW_UPDATE stream=1 len=4 incr=206
2016/08/04 20:28:16 http2: Framer 0xc420208180: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2016/08/04 20:28:16 http2: Transport received PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2016/08/04 20:28:16 http2: Framer 0xc420208180: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2016/08/04 20:28:16 http2: Transport failed to get client conn for vision.googleapis.com:443: http2: no cached connection was available
2016/08/04 20:28:16 http2: Transport creating client conn to [2607:f8b0:4005:804::200a]:443
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
2016/08/04 20:28:16 http2: Transport encoding header ":authority" = "vision.googleapis.com"
2016/08/04 20:28:16 http2: Transport encoding header ":method" = "POST"
2016/08/04 20:28:16 http2: Transport encoding header ":path" = "https://vision.googleapis.com/v1/images:annotate?alt=json"
2016/08/04 20:28:16 http2: Transport encoding header ":scheme" = "https"
2016/08/04 20:28:16 http2: Transport encoding header "content-type" = "application/json"
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: read SETTINGS len=24, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=16384
2016/08/04 20:28:16 http2: Transport encoding header "authorization" = "Bearer <ELIDED>"
2016/08/04 20:28:16 http2: Transport encoding header "user-agent" = "google-api-go-client/0.5"
2016/08/04 20:28:16 http2: Transport encoding header "content-length" = "163636"
2016/08/04 20:28:16 http2: Transport received SETTINGS len=24, settings: MAX_CONCURRENT_STREAMS=100, INITIAL_WINDOW_SIZE=1048576, MAX_FRAME_SIZE=16384, MAX_HEADER_LIST_SIZE=16384
2016/08/04 20:28:16 http2: Transport encoding header "accept-encoding" = "gzip"
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote HEADERS flags=END_HEADERS stream=1 len=171
2016/08/04 20:28:16 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote SETTINGS flags=ACK len=0
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: read WINDOW_UPDATE len=4 (conn) incr=983041
2016/08/04 20:28:16 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote DATA stream=1 len=16384 data="{\"requests\":[{\"features\":[{\"type\":\"LABEL_DETECTION\"}],\"image\":{\"content\":\"/9j/2wCEAAMCAggICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgHBwcHBwcHCAcHBwoHBwcICQkJBwcLDQoIDQcICQgBAwQEBgUGCAYGCAgHBwcNCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICP" (16128 bytes omitted)
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote DATA stream=1 len=16384 data="<ELIDED>" (16128 bytes omitted)
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote DATA stream=1 len=16384 data="<ELIDED>" (16128 bytes omitted)
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: read SETTINGS flags=ACK len=0
2016/08/04 20:28:16 http2: Transport received SETTINGS flags=ACK len=0
2016/08/04 20:28:16 http2: Framer 0xc4200266c0: wrote DATA stream=1 len=16383 data="<ELIDED>" (16127 bytes omitted)

<four minutes later>

2016/08/04 20:32:16 http2: Framer 0xc420208180: read GOAWAY len=25 LastStreamID=1 ErrCode=NO_ERROR Debug="session_timed_out"
2016/08/04 20:32:16 http2: Transport received GOAWAY len=25 LastStreamID=1 ErrCode=NO_ERROR Debug="session_timed_out"
2016/08/04 20:32:16 Transport readFrame error: (*errors.errorString) EOF
2016/08/04 20:32:17 http2: Framer 0xc4200266c0: read HEADERS flags=END_HEADERS stream=1 len=439
2016/08/04 20:32:17 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=439
2016/08/04 20:32:17 http2: Framer 0xc4200266c0: read DATA flags=END_STREAM stream=1 len=1613 data="<!DOCTYPE html>\n<html lang=en>\n  <meta charset=utf-8>\n  <meta name=viewport content=\"initial-scale=1, minimum-scale=1, width=device-width\">\n  <title>Error 502 (Server Error)!!1</title>\n  <style>\n    *{margin:0;padding:0}html,code{font:15px/22px arial,sans-" (1357 bytes omitted)
2016/08/04 20:32:17 http2: Transport received DATA flags=END_STREAM stream=1 len=1613 data="<!DOCTYPE html>\n<html lang=en>\n  <meta charset=utf-8>\n  <meta name=viewport content=\"initial-scale=1, minimum-scale=1, width=device-width\">\n  <title>Error 502 (Server Error)!!1</title>\n  <style>\n    *{margin:0;padding:0}html,code{font:15px/22px arial,sans-" (1357 bytes omitted)
2016/08/04 20:32:17 http2: Framer 0xc4200266c0: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2016/08/04 20:32:17 http2: Transport received PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2016/08/04 20:32:17 http2: Framer 0xc4200266c0: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"

Easiest way to reproduce... install Cloud SDK, do a gcloud auth login, then:

go get github.com/GoogleCloudPlatform/golang-samples/vision/label
$GOPATH/bin/label $GOROOT/doc/gopher/gophercolor.png

[bradfitz]

Okay, sorry, my fault. I see the problem.

It's a flow control issue, but it's not because of https://golang.org/cl/25382. It's actually because of the mod_h2 workaround https://golang.org/cl/25362 (#16519).

Google is advertising a 1MB initial window size for streams, but because we no longer wait to hear that, we start out assuming it's 64KB and never adjust our limit by (1MB-64KB) when we see the SETTINGS update by the peer.

There's actually a TODO to do this:

        err := f.ForeachSetting(func(s Setting) error {
                switch s.ID {
                case SettingMaxFrameSize:
                        cc.maxFrameSize = s.Val
                case SettingMaxConcurrentStreams:
                        cc.maxConcurrentStreams = s.Val
                case SettingInitialWindowSize:
                        // TODO: error if this is too large.                                                                                                                                                           

                        // TODO: adjust flow control of still-open                                                                                                                                                     
                        // frames by the difference of the old initial                                                                                                                                                 
                        // window size and this one.                                                                                                                                                                   
                        cc.initialWindowSize = s.Val

... but it was super low priority when we read the SETTINGS at start-up, because I've never seen a server change the initial flow control setting on a connection after the initial settings.

But it's super important to do that TODO if we're starting to do send requests (e.g. for Apache) before we wait for the initial SETTINGS from the peer.

It's easy enough to roll forward and fix this, which I understand people might object to, but rolling back is also not great (there have been a few h2 fixes), and cherry picking fixes is also something I don't think will be too great if a number of them are inter-dependent. I'd prefer x/net and std to match as much as possible.

I'll send out a fix tomorrow morning and people can evaluate it.

[dsnet]

Would this warrant another RC?

[bradfitz]

Well, we already have to do another RC for two other reasons, so...

[broady]

What's the most conservative route? My gut feeling is that we fix it, and delay Go 1.7.

I'd rather a solid but delayed 1.7 than to release with a flawed client that can't properly communicate with commonly used http2 servers (Google and Apache).

[bradfitz]

I have a fix. It's not scary. Will mail it out shortly.

[bradfitz]

See https://go-review.googlesource.com/25508

[gopherbot]

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

[gopherbot]

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