grpc module handles RST_STREAM(NO_ERROR) improperly on closed streams

[goffrie@…]

Per the code, we have:

            if (ctx->stream_id && ctx->done) {
                ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
                              "upstream sent frame for closed stream %ui",
                              ctx->stream_id);
                return NGX_ERROR;
            }

saying that if we ever receive any frame on a closed stream, the entire request is errored. However, per the HTTP/2 spec, section 8.1:

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.

So it is in fact legal for the upstream to send an RST_STREAM in such a scenario (which is also racy, since it depends on whether the upstream happens to have received the final END_STREAM frame from nginx). And indeed, gRPC server implementations do do this - see e.g. ​https://github.com/grpc/grpc/pull/1661. We are using the Go google.golang.org/grpc module and it too does this, and indeed we sometimes see spurious failures coupled with the log message:

2019/06/11 08:10:46 [error] 175#175: *6289 upstream sent frame for closed stream 1 while reading response header from upstream, client: [..], server: [..], request: "POST /[..] HTTP/2.0", upstream: "grpcs://127.0.0.1:6414", host: [..]

So it would be good to follow the spec and pass on the successful response in this scenario.

[Sergey Kandaurov]

Could you please try this patch.

# HG changeset patch
# User Sergey Kandaurov <pluknet@nginx.com>
# Date 1560264942 -10800
#      Tue Jun 11 17:55:42 2019 +0300
# Node ID bcfc208c037309eff5f823c3ece678968c99a2ee
# Parent  2db68852d6a04d974c6b90d6e5a975846449a9cc
gRPC: handling of RST_STREAM with NO_ERROR in half-closed (remote).

As per HTTP 7540, section 8.1, this is a valid stream state transition
used to hint a client to abort transmission of a request after sending
a complete response and to force the client into the closed state.
It also seems to be valid in gRPC.  Citing the "gRPC over HTTP2" spec:
"this might be used to aggressively lameduck in some scenarios".

This fixes problems observed with modern grpc-c [1], as well as with
the Go gRPC module (ticket #1792).

[1] https://github.com/grpc/grpc/pull/1661

diff --git a/src/http/modules/ngx_http_grpc_module.c b/src/http/modules/ngx_http_grpc_module.c
--- a/src/http/modules/ngx_http_grpc_module.c
+++ b/src/http/modules/ngx_http_grpc_module.c
@@ -1972,7 +1972,9 @@ ngx_http_grpc_filter(void *data, ssize_t
                 return NGX_ERROR;
             }
 
-            if (ctx->stream_id && ctx->done) {
+            if (ctx->stream_id && ctx->done
+                && ctx->type != NGX_HTTP_V2_RST_STREAM_FRAME)
+            {
                 ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
                               "upstream sent frame for closed stream %ui",
                               ctx->stream_id);
@@ -2019,7 +2021,9 @@ ngx_http_grpc_filter(void *data, ssize_t
                           "upstream rejected request with error %ui",
                           ctx->error);
 
-            return NGX_ERROR;
+            if (ctx->error || !ctx->done) {
+                return NGX_ERROR;
+            }
         }
 
         if (ctx->type == NGX_HTTP_V2_GOAWAY_FRAME) {

[goffrie@…]

Yes, that patch appears to fix my issue. Thank you!

[oleg.dropbox.com@…]

It looks like there is another similar issue with RST_STREAM(NO_ERROR) handling (I suppose it shouldn't be logged in error.log):

2019/06/26 18:32:16 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.22.54.184:9911", host: "XXX:443"
2019/06/26 18:32:18 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.50.47.38:9911", host: "XXX:443"
2019/06/26 18:32:22 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.22.28.28:9911", host: "XXX:443"
2019/06/26 18:32:22 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.22.28.160:9911", host: "XXX:443"
2019/06/26 18:32:26 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.58.168.56:9911", host: "XXX:443"

[Sergey Kandaurov]

Replying to oleg.dropbox.com@…:

It looks like there is another similar issue with RST_STREAM(NO_ERROR) handling (I suppose it shouldn't be logged in error.log):

2019/06/26 18:32:16 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.22.54.184:9911", host: "XXX:443"
2019/06/26 18:32:18 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.50.47.38:9911", host: "XXX:443"
2019/06/26 18:32:22 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.22.28.28:9911", host: "XXX:443"
2019/06/26 18:32:22 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.22.28.160:9911", host: "XXX:443"
2019/06/26 18:32:26 [error] 67642#67642: *56314049 upstream rejected request with error 0 while reading response header from upstream, client: 1.2.3.4, server: XXX, request: "POST /ZZZ HTTP/2.0", upstream: "grpcs://10.58.168.56:9911", host: "XXX:443"

Why?

[Maxim Dounin]

From HTTP/2 specification point of view, RST_STREAM(NO_ERROR) is a signal that further request frames can be discarded. It is not an error, but an action which needs special handling - both in parsing logic, and in sending logic. And this is not something nginx gRPC proxy currently supports (and it is more or less normal to do not support this, see 8df664ebe037).

As for the patch, I don't think that just skipping RST_STREAM on closed stream is a good solution. First, we have to check if it's NO_ERROR. Second, we have to check if there is only one RST_STREAM, and not multiple ones. Third, we have to actually stop sending further request frames once it is received.

[Maxim Dounin]

See also #1797.

[Ruslan Ermilov]

Fixed in 2096b21fcd10, thanks!

[Pavel Pautov <p.pautov@…>]

In 7746:88eca63261c3/nginx:

gRPC: RST_STREAM(NO_ERROR) handling after "trailer only" responses.

Similarly to the problem fixed in 2096b21fcd10 (ticket #1792),
when a "trailer only" gRPC response (that is, a response with the
END_STREAM flag in the HEADERS frame) was immediately followed by
RST_STREAM(NO_ERROR) in the data preread along with the response
header, RST_STREAM wasn't properly skipped and caused "upstream
rejected request with error 0" errors.
Observed with "unknown service" gRPC errors returned by grpc-go.

Fix is to set ctx->done if we are going to parse additional data,
so the RST_STREAM(NO_ERROR) is properly skipped. Additionally, now
ngx_http_grpc_filter() will complain about frames sent for closed
stream if there are any.

[manuel.jurado.socialpoint.es@…]

Hi, related to logs upstream rejected request with error 0 I have a question:

I've updated the Nginx version to 1.19.4 to avoid false errors logs with error 0:

• upstream rejected request with error 0 while reading response header from upstream

but they keep showing up.

I've verified that the Nginx version 1.19.4, contains the changes in the ngx_http_grpc_module.c. And it seems correct.

• ​https://github.com/nginx/nginx/blob/release-1.19.4/src/http/modules/ngx_http_grpc_module.c#L2189

But I can see other entry related to this kind of log

• ​https://github.com/nginx/nginx/blob/release-1.19.4/src/http/modules/ngx_http_grpc_module.c#L1699

where if (ctx-> error ||! ctx-> done) is not checked before logging the error [1]:

        if (ctx->type == NGX_HTTP_V2_RST_STREAM_FRAME) {

            rc = ngx_http_grpc_parse_rst_stream(r, ctx, b);

            if (rc == NGX_AGAIN) {
                return NGX_AGAIN;
            }

            if (rc == NGX_ERROR) {
                return NGX_HTTP_UPSTREAM_INVALID_HEADER;
            }

            /**** [1] if (ctx-> error ||! ctx-> done) ??? ****/

            ngx_log_error(NGX_LOG_ERR, r->connection->log, 0,
                          "upstream rejected request with error %ui",
                          ctx->error);

            return NGX_HTTP_UPSTREAM_INVALID_HEADER;
        }

I'm unfamiliar with the Nginx source code due to I would like to ask if it is the expected behaviour or there could be some other issue or regression.

Updating to the latest version 1.19.5 (that contains the fix commented above https://trac.nginx.org/nginx/changeset/88eca63261c3dca2dcc6185cadc82ec9d549f9a0/nginx), would it fix the problem?

Thanks in advance.

[Maxim Dounin]

Replying to manuel.jurado.socialpoint.es@…:

But I can see other entry related to this kind of log

• ​https://github.com/nginx/nginx/blob/release-1.19.4/src/http/modules/ngx_http_grpc_module.c#L1699

where if (ctx-> error ||! ctx-> done) is not checked before logging the error [1]:

This code is only in effect before the HEADERS frame is got from the client. An RST_STREAM frame is always fatal at this point, so no checking is needed.

Updating to the latest version 1.19.5 (that contains the fix commented above https://trac.nginx.org/nginx/changeset/88eca63261c3dca2dcc6185cadc82ec9d549f9a0/nginx), would it fix the problem?

This commit fixes the only known case when "upstream rejected request with error 0" errors might appear incorrectly in nginx 1.19.4. If the errors you are seeing are reported incorrectly, upgrade to 1.19.5 should fix it.

[manuel.jurado.socialpoint.es@…]

Replying to Maxim Dounin:

Replying to manuel.jurado.socialpoint.es@…:

But I can see other entry related to this kind of log

• ​https://github.com/nginx/nginx/blob/release-1.19.4/src/http/modules/ngx_http_grpc_module.c#L1699

where if (ctx-> error ||! ctx-> done) is not checked before logging the error [1]:

This code is only in effect before the HEADERS frame is got from the client. An RST_STREAM frame is always fatal at this point, so no checking is needed.

Updating to the latest version 1.19.5 (that contains the fix commented above https://trac.nginx.org/nginx/changeset/88eca63261c3dca2dcc6185cadc82ec9d549f9a0/nginx), would it fix the problem?

This commit fixes the only known case when "upstream rejected request with error 0" errors might appear incorrectly in nginx 1.19.4. If the errors you are seeing are reported incorrectly, upgrade to 1.19.5 should fix it.

Thanks for the quick response Maxim, I'll proceed to upgrade nginx to v1.19.5 and check the fix.