GRPC: upstream rejected request with error while reading response header from upstream

[erebe@…]

Hello,

Reporting an issue with GRPC where nginx is not correctly forwarding to client the response and RST_STREAM
when server early abort the http2 stream.

My setup:

[client] === grpc stream (with ssl) ===> [nginx] === grpc stream (cleartext) ===> [backend]

Description:

When the client is establishing a grpc (client/unidirectional) stream, it may happen that the backend close/reset the http2 stream before exhausting the client input stream, for example due to a timeout.

In this case, the backend send back the response and reset the stream:

grpc-gateway DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
grpc-gateway DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1) }
grpc-gateway DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
grpc-gateway DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Reset { stream_id: StreamId(1), error_code: CANCEL }

My issue is that the client never receive the response nor the http2 RST_STREAM from nginx.
The client discover that the stream have been reset only after the next client side http2 PING frame, or after the client try to send some new data.

DEBUG Connection{peer=Client}: h2::codec::framed_write: send frame=Ping { ack: false, payload: [59, 124, 219, 122, 11, 135, 22, 180] }
DEBUG status_request{request_id=117db9f2-707c-4ccd-a824-f0f8d36c9fa3}:Connection{peer=Client}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
DEBUG status_request{request_id=117db9f2-707c-4ccd-a824-f0f8d36c9fa3}:Connection{peer=Client}: h2::codec::framed_read: received frame=Reset { stream_id: StreamId(1), error_code: INTERNAL_ERROR }
DEBUG hyper::proto::h2::client: client request body error: error writing a body to connection: send stream capacity unexpectedly closed

The only thing I see in the nginx log is those messages:
(error 8 is http2 CANCEL error code)

[error] 855#855: *73638 upstream rejected request with error 8 while reading response header from upstream, client: 10.0.33.7, server: grpc.qovery.com, request: "POST /agent.Agent/AgentResponsePublish HTTP/2.0", upstream: "grpc://10.0.20.240:8081", host: "grpc.qovery.com:443"
10.0.33.7 - - [10/Aug/2022:21:48:29 +0000] "POST /agent.Agent/AgentResponsePublish HTTP/2.0" 200 0 "-" "tonic/0.8.0" 566 60.024 [qovery-prod-grpc-gateway-grpc] [] 10.0.20.240:8081 68 60.025 200 e0ee79d5fd24a5bbf39556e159cb3840  

If I remove nginx from my setup everything is working as expected.

The issue seems a duplicate of this one https://trac.nginx.org/nginx/ticket/1792, but as the ticket has been closed, I opened a new one with detailed information.

[erebe@…]

Miss labeled the ticket as "documentation", if someone can change it for nginx-module

[Maxim Dounin]

gRPC seems to allow RST_STREAM due to framing errors, see ​specification. All such errors are interpreted by nginx as fatal errors on the particular connection.

In particular, when RST_STREAM is used on the connection between nginx and the upstream server before response headers are returned by the upstream, nginx will return 502 error to the client, as per HTTP specification.

I don't think we should do anything with this, as nginx behaviour looks perfectly correct. Probably a better way to cancel such requests in gRPC can be found, which is more compatible with HTTP protocol.

[erebe@…]

Hello @Maxim,

I am re-opening the ticket because I think you may have read the issue too quickly or that I haven't explained it clearly enough.

For me, there are 2 issues/phenoms described here:

1. The response is not forwarded to the client in presence of an RST_STREAM.

On this point, I think you responded that when receiving RST_STREAM nginx is in its right to abort the connection without propagating the response to the client

2. The RST_STREAM is not forwarded by nginx to the client.

I think you missed this point, in my case nginx do not forward actively the RST_STREAM to the client after received it from upstream.
The client has to try to send some data on the connection, or wait for a ping frame in order to discover by itself that nginx received a RST_STREAM and the stream is no longer valid.

While I won't discuss for point 1. , I think for point 2. it is a bug of nginx to not (pro)actively forward the RST_STREAM to the client.
If no ping frame is used, like in my case, the client maintains the connection open/idle without any notification from nginx.

Is there a reason for nginx to not propagate the RST_STREAM to the client ?

[Maxim Dounin]

1. The response is not forwarded to the client in presence of an RST_STREAM.

Nothing in your report suggests there is a response. In contrast, the error message "upstream rejected request with error 8 while reading response header from upstream" suggests that RST_STREAM was seen by nginx before response headers were received.

2. The RST_STREAM is not forwarded by nginx to the client.

The RST_STREAM corresponds to the particular connection between nginx and the backend. Once the error happens, nginx responds with 502 to the client. The 502 is then followed by RST_STREAM(NO_ERROR) if the request body is still being sent by the client, so this is what should happen in your case.

That is, while the particular RST_STREAM is not forwarded by nginx, it is believed that it shouldn't be forwarded, and another RST_STREAM is properly sent. If in doubt, check nginx ​debug log, it should have enough details on what happens on the wire.

[erebe@…]

Pcap of the issue

[erebe@…]

pcap_colorized

[erebe@…]

I managed to reproduce the issue locally, so I have attached a pcap of what I found + colorized image of the capture to help you.

Regarding who is who:
upstream/grpc server is on 127.0.0.3:50051
nginx is on 127.0.0.2:80 (but talk from 127.0.0.1)
client is on 127.0.0.1

On the image,
the purple color is the tcp stream between client and nginx
the red color is the tcp stream between nginx and upstream (grpc server)

We can see that upstream/backend is responding to nginx with

44	0.006983607	127.0.0.3	127.0.0.1	GRPC	164	HEADERS[1], DATA[1] (GRPC), HEADERS[1], RST_STREAM[1]

but nginx is responding to the client only by sending

46	0.007045107	127.0.0.2	127.0.0.1	HTTP2	125	HEADERS[3]: 200 OK

it is only 60 seconds later, after that the client send a PING frame that nginx respond by a RST_STREAM, and not before

51	60.010391137	127.0.0.1	127.0.0.2	HTTP2	83	PING[0]
53	60.010608655	127.0.0.2	127.0.0.1	HTTP2	96	RST_STREAM[3], PING[0]

.

If I am not mistaken, the HEADERS[3]: 200 OK, that nginx respond to the client should contain the flag END_STREAM to notify the client that the stream is reset ?

HyperText Transfer Protocol 2
    Stream: HEADERS, Stream ID: 3, Length 50, 200 OK
        Length: 50
        Type: HEADERS (1)
        Flags: 0x04, End Headers
        0... .... .... .... .... .... .... .... = Reserved: 0x0
        .000 0000 0000 0000 0000 0000 0000 0011 = Stream Identifier: 3
        [Pad Length: 0]
        Header Block Fragment: 88768aaa6355e580ae17d7083f6196df3dbf4a042a436cca080212820dc082e09953168d…
        [Header Length: 122]
        [Header Count: 4]
        Header: :status: 200 OK
        Header: server: nginx/1.19.10
        Header: date: Thu, 11 Aug 2022 21:10:23 GMT
        Header: content-type: application/grpc

[Maxim Dounin]

Thanks for the dump. It does not seem to match the original description, but probably explains the issue you are seeing. In the provided dump, the RST_STREAM from the upstream server follows gRPC response (headers + data + trailers), so the error message as logged by nginx should be ... while reading upstream in this case.

From what I can see, there are two things which happen here:

1. The RST_STREAM(8) following the response is interpreted by nginx as a fatal error, while upstream server properly use it as an attempt to let the server know that the stream is not needed. This seems to be something to address in the upstream server, as ​RFC 7540 quote as provided in the 2096b21fcd10 commit log suggests that the code should be RST_STREAM(NO_ERROR), and not RST_STREAM(CANCEL):

      ... A server can
      send a complete response prior to the client sending an entire
      request if the response does not depend on any portion of the request
      that has not been sent and received.  When this is true, a server MAY
      request that the client abort transmission of a request without error
      by sending a RST_STREAM with an error code of NO_ERROR after sending
      a complete response (i.e., a frame with the END_STREAM flag).
      Clients MUST NOT discard responses as a result of receiving such a
      RST_STREAM, though clients can always discard responses at their
      discretion for other reasons.
   

   It is not why in your case the upstream server uses RST_STREAM(CANCEL), this does not seem to be correct as per HTTP/2 specification and does not seem to be something used by common gRPC libraries.

2. The error results in RST_STREAM(INTERNAL_ERROR) generated by nginx, but this RST_STREAM is not sent to the wire before writing to the connection is triggered for a different reason. This looks like something to address/improve in nginx.

It looks like there is another active stream (/agent.Agent/AgentRequestSubscribe), and due to this ngx_http_v2_close_stream() does not try to initiate frame queue writing. Not sure why it behaves this way.

Hope this helps. Overall, this looks like an issue caused by improper use of RST_STREAM(CANCEL) instead of RST_STREAM(NO_ERROR) by the upstream server.

[erebe@…]

Thank you for having taken the time to look at the capture.

1. Thanks for the insight, I will try to see with the implementors if this behavior can be changed to be aligned with the RFC.

2. If this can be of any help to you, I have attached the nginx-debug log of the issue.

You are right regarding the other active stream, our app/agent is a simple pub/sub. It subscribes to a stream of events and after create a new stream to respond to those events.

Regarding RST_STREAM is not sent to the wire before writing to the connection ... something to address/improve in nginx. does this mean it qualify this ticket as a real issue to you ? What can be expected regarding this point ?

Thanks for your help

[erebe@…]

To keep the ticket updated, if some other people find it.
I contacted the maintainer of the library and provided a patch to fix the issue
​https://github.com/hyperium/h2/issues/633, hopefully the patch will be available in version v0.3.13 of h2.

@Maxim Dounin, I confirm you that changing the RST_STREAM(CANCEL) by RST_STREAM(NO_ERROR) make nginx work flawlessly !

[Maxim Dounin]

If this can be of any help to you, I have attached the nginx-debug log of the issue.

Thanks for the log. I was wrong assuming the log message should be ... while reading upstream: since the RST_STREAM is received in the same read() call as the headers, the log message contains ... while reading response header from upstream instead. Otherwise the log seems to match what I expected: nginx generates RST_STREAM, but does not send it immediately due to another stream being active.

Regarding RST_STREAM is not sent to the wire before writing to the connection ... something to address/improve in nginx. does this mean it qualify this ticket as a real issue to you ? What can be expected regarding this point ?

I'll take a look if it can be improved to send the RST_STREAM immediately. Keeping this ticket open for now to address this.

Thanks for reporting this, and thanks for the update. From the issue linked it looks like changing the code to NO_ERROR should also fix another related issue not involving nginx at all. Good to see this generally improves things.