grpcwebproxy does not handle 'Connection: keep-alive' header properly

[stanley-cheung]

Issue summary:

• When the browser grpc-web request contains the header Connection: keep-alive, the grpcwebproxy does not seem to be able to handle it and returns an error stream terminated by RST_STREAM with error code: PROTOCOL_ERROR.
• Without the Connection: header at all, the basic curl request works.
• With the Connection: header, regardless of the value keep-alive or close, the grpcwebproxy returns the error. The grpc request never made it to the backend server.
• The Connection: keep-alive header seems to be automatically added by the browser (tested with Chrome and Firefox) - I didn't set that header explicitly myself from my web test app.

This is the error log being printed out by grpcwebproxy

ERRO[0077] finished streaming call with code Internal    error="rpc error: code = Internal 
desc = stream terminated by RST_STREAM with error code: PROTOCOL_ERROR" 
grpc.code=Internal grpc.method=Echo grpc.service=grpc.gateway.testing.EchoService 
grpc.start_time="2019-10-05T05:12:07Z" grpc.time_ms=0.513 span.kind=server system=grpc

To reproduce:

$ git clone https://github.com/grpc/grpc-web
$ cd grpc-web
$ docker-compose -f advanced.yml build common node-server grpcwebproxy

From one shell, start the backend gRPC server (this one written in Node, listening at :9090):

$ docker run -it --rm --name node-server -p 9090:9090 grpcweb/node-server

From another shell, start grpcwebproxy (listening at :8080):

$ docker run -it --rm --link node-server:node-server -p 8080:8080 grpcweb/grpcwebproxy

We need to write some bytes for the request first

$ echo -n -e '\x00\x00\x00\x00\x07\x0a\x05\x68\x65\x6c\x6c\x6f' >> request.bin

Now if you run this curl command, without the Connection: keep-alive header, it will return success. The grpc-web request made it all the way to the backend server and the response from grpcwebproxy were properly formatted:

$ curl 'http://localhost:8080/grpc.gateway.testing.EchoService/Echo' \
-H 'X-Grpc-Web: 1' -H 'Content-Type: application/grpc-web+proto' \
--data-binary '@request.bin' --verbose --compressed | xxd

* Connected to localhost (::1) port 8080 (#0)
> POST /grpc.gateway.testing.EchoService/Echo HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.64.0
> Accept: */*
> Accept-Encoding: deflate, gzip
> X-Grpc-Web: 1
> Content-Type: application/grpc-web+proto
> Content-Length: 12
> 
} [12 bytes data]
* upload completely sent off: 12 out of 12 bytes
< HTTP/1.1 200 OK
< Access-Control-Expose-Headers: Date, Content-Type, Grpc-Accept-Encoding, Vary, grpc-status, grpc-message
< Content-Type: application/grpc-web+proto
< Date: Sat, 05 Oct 2019 05:24:17 GMT
< Grpc-Accept-Encoding: identity
< Vary: Origin
< Transfer-Encoding: chunked
< 
{ [17 bytes data]
100    99    0    87  100    12  21750   3000 --:--:-- --:--:-- --:--:-- 33000
* Connection #0 to host localhost left intact
00000000: 0000 0000 070a 0568 656c 6c6f 8000 0000  .......hello....
00000010: 4661 6363 6570 743a 202a 2f2a 0d0a 6163  Faccept: */*..ac
00000020: 6365 7074 2d65 6e63 6f64 696e 673a 2064  cept-encoding: d
00000030: 6566 6c61 7465 0d0a 6772 7063 2d73 7461  eflate..grpc-sta
00000040: 7475 733a 2030 0d0a 782d 6772 7063 2d77  tus: 0..x-grpc-w
00000050: 6562 3a20 310d 0a                        eb: 1..

But now if you add the Connection: keep-alive header to the curl command, it will return an error:

$ curl 'http://localhost:8080/grpc.gateway.testing.EchoService/Echo' \
-H 'X-Grpc-Web: 1' -H 'Content-Type: application/grpc-web+proto' \
-H 'Connection: keep-alive' --data-binary '@request.bin' \
--verbose --compressed | xxd

* Connected to localhost (::1) port 8080 (#0)
> POST /grpc.gateway.testing.EchoService/Echo HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.64.0
> Accept: */*
> Accept-Encoding: deflate, gzip
> X-Grpc-Web: 1
> Content-Type: application/grpc-web+proto
> Connection: keep-alive
> Content-Length: 12
> 
} [12 bytes data]
* upload completely sent off: 12 out of 12 bytes
< HTTP/1.1 200 OK
< Access-Control-Expose-Headers: Vary, Date, Content-Type, Grpc-Status, Grpc-Message, grpc-status, grpc-message
< Content-Type: application/grpc-web+proto
< Grpc-Message: stream terminated by RST_STREAM with error code: PROTOCOL_ERROR
< Grpc-Status: 13
< Vary: Origin
< Transfer-Encoding: chunked
< 
{ [5 bytes data]
100    12    0     0  100    12      0   6000 --:--:-- --:--:-- --:--:--  6000
* Connection #0 to host localhost left intact

I am using the 0.11.0 version of grpcwebproxy.

This is how the grpcwebproxy was started (full dockerfile here):

/go/bin/grpcwebproxy \                                                     
  --backend_addr=node-server:9090 \                                                                            
  --run_tls_server=false \                                                                                     
  --allow_all_origins 

[johanbrandhorst]

Hi Stanley, thanks for the detailed bug report! I imagine we may need to just whitelist this header. Is it being passed through to the gRPC backend? Should it be?

[stanley-cheung]

I am not sure if that header semantically mean anything to the gRPC Backend. So I will leave it up to you. Thanks!

[johanbrandhorst]

What is the envoy proxy behaviour in this case?

[stanley-cheung]

I just tried. Interestingly, the Connection: header was not sent to the gRPC Backend.

[johanbrandhorst]

Thanks, I guess we'll want to duplicate that behaviour.

[mgkeeley]

See also #404 I think this is the same cause for that error

[crlssn]

We are experience the same issue in our build, although with a slighty different error message.

INFO[0000] listening for http on: [::]:8080             
INFO[0000] pickfirstBalancer: HandleSubConnStateChange: 0xc00015e200, READY  system=system
INFO[0075] transport: loopyWriter.run returning. connection error: desc = "transport is closing"  system=system
INFO[0075] pickfirstBalancer: HandleSubConnStateChange: 0xc00015e200, TRANSIENT_FAILURE  system=system
INFO[0075] pickfirstBalancer: HandleSubConnStateChange: 0xc00015e200, CONNECTING  system=system
WARN[0075] finished streaming call with code Unavailable  error="rpc error: code = Unavailable desc = transport is closing" grpc.code=Unavailable grpc.method=Method grpc.service=namespace.Service grpc.start_time="2019-10-28T11:56:35Z" grpc.time_ms=1052.424 span.kind=server system=grpc
INFO[0075] pickfirstBalancer: HandleSubConnStateChange: 0xc00015e200, READY  system=system

We are able to establish a connection if we update main.go:154 to

delete(mdCopy, "connection")

[johanbrandhorst]

@crlssn Would you be interested in contributing this fix? Sounds like we should just drop the connection header.

[crlssn]

@johanbrandhorst I've opened a PR here: #588.

[johanbrandhorst]

Closed by #588