grpcurl doesn't respect GOAWAY frame from server

[owlwalks]

trafficstars

grpcurl retries forever even after server sends GOAWAY frame

I tried something like this:

gcurl -plaintext localhost:50051 describe

from server with GODEBUG="http2debug=2":

2019/08/10 22:56:11 connection is idle
2019/08/10 22:56:11 http2: Framer 0xc0002d9880: wrote GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2019/08/10 22:56:11 h2c: attempting h2c with prior knowledge.
2019/08/10 22:56:11 http2: server connection from [::1]:44508 on 0xc0001f95f0
2019/08/10 22:56:11 http2: Framer 0xc0002d9b20: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2019/08/10 22:56:11 http2: server: client [::1]:44508 said hello
2019/08/10 22:56:11 http2: Framer 0xc0002d9b20: read SETTINGS len=0
2019/08/10 22:56:11 http2: server read frame SETTINGS len=0
2019/08/10 22:56:11 http2: Framer 0xc0002d9b20: wrote SETTINGS flags=ACK len=0
2019/08/10 22:56:11 http2: Framer 0xc0002d9b20: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2019/08/10 22:56:11 http2: Framer 0xc0002d9b20: read SETTINGS flags=ACK len=0
2019/08/10 22:56:11 http2: server read frame SETTINGS flags=ACK len=0

2019/08/10 22:56:12 connection is idle
2019/08/10 22:56:12 http2: Framer 0xc000181ce0: wrote GOAWAY len=8 LastStreamID=0 ErrCode=NO_ERROR Debug=""
2019/08/10 22:56:12 h2c: attempting h2c with prior knowledge.
2019/08/10 22:56:12 http2: server connection from [::1]:44510 on 0xc000269a00
2019/08/10 22:56:12 http2: Framer 0xc000181ea0: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
2019/08/10 22:56:12 http2: server: client [::1]:44510 said hello
2019/08/10 22:56:12 http2: Framer 0xc000181ea0: read SETTINGS len=0
2019/08/10 22:56:12 http2: server read frame SETTINGS len=0
2019/08/10 22:56:12 http2: Framer 0xc000181ea0: wrote SETTINGS flags=ACK len=0
2019/08/10 22:56:12 http2: Framer 0xc000181ea0: wrote WINDOW_UPDATE len=4 (conn) incr=983041
2019/08/10 22:56:12 http2: Framer 0xc000181ea0: read SETTINGS flags=ACK len=0
2019/08/10 22:56:12 http2: server read frame SETTINGS flags=ACK len=0

... more GOAWAY frame from server and then new conn from grpcurl

[jhump]

grpcurl retries forever

Since I don't see any data or header frames in that trace, so I'm guessing grpcurl is just trying to reconnect. It will reconnect repeatedly, with some exponential backoff in between attempts, for up to 10 seconds (thought that is configurable via the -connect-timeout parameter). This is expected and is part of how a gRPC client works.

[owlwalks]

hi @jhump, I just had a quick look: connect-timeout only seems to affect dialing, https://github.com/fullstorydev/grpcurl/blob/5631bba11793e645e00d92882c543904426b098a/cmd/grpcurl/grpcurl.go#L276. In my case grpcurl and server was connected ok, but server wants to end the conn by GOAWAY frame but grpcurl still keeps reconnecting.

[jhump]

In my case grpcurl and server was connected ok

Hmm. That is strange since the Go gRPC client used by grpcurl does not default to "wait for ready" behavior. So it should not retry sending when a transport is unavailable (such as due to it being shutdown by the server with a GOAWAY message) but should instead fail with an "unavailable" error message. I'll look a little more into it.