Opened 4 months ago

Last modified 3 months ago

#1792 accepted defect

grpc module handles RST_STREAM(NO_ERROR) improperly on closed streams

Reported by: goffrie@… Owned by:
Priority: minor Milestone:
Component: nginx-module Version: 1.15.x
Keywords: grpc, http2 Cc:
uname -a: Linux goffrie-dbx 4.15.0-43-generic #46~16.04.1-Ubuntu SMP Fri Dec 7 13:31:08 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.15.6 built by Bazel built by gcc 4.9.4 (Ubuntu 4.9.4-2ubuntu1~12.04) built with OpenSSL 1.1.0 (compatible; BoringSSL) (running with BoringSSL) TLS SNI support enabled configure arguments: --prefix=/etc/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --pid-path=/var/run/nginx.pid --lock-path=/var/lock/nginx.lock --user=nginx --group=nginx --http-log-path=/var/log/nginx/access.log --http-client-body-temp-path=/var/lib/nginx/client_temp --http-fastcgi-temp-path=/var/lib/nginx/fastcgi_temp --http-proxy-temp-path=/var/lib/nginx/proxy_temp --http-scgi-temp-path=/var/lib/nginx/scgi_temp --http-uwsgi-temp-path=/var/lib/nginx/uwsgi_temp --with-compat --with-debug --with-file-aio --with-threads --add-module=@ngx_brotli//:http_brotli_filter --add-module=@ngx_brotli//:http_brotli_static --add-module=@ngx_http_headers_more_filter//:http_headers_more_filter --add-module=@ngx_http_ip_tos_filter//:http_ip_tos_filter --add-module=@ngx_http_lua//:http_lua --add-module=dbx_dials_module --add-module=modules/nginx_upstream_check_module --add-module=modules/ngx_http_upstream_dynamic_module --add-module=ngx_http_streaming_filter --with-http_auth_request_module --with-http_gzip_static_module --with-http_realip_module --with-http_ssl_module --with-http_v2_module --with-openssl=boringssl --with-stream

Description

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.

Change History (5)

comment:1 Changed 4 months ago by pluknet

  • Status changed from new to accepted

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) {

comment:2 Changed 4 months ago by goffrie@…

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

comment:3 follow-up: Changed 4 months ago by 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"

comment:4 in reply to: ↑ 3 Changed 3 months ago by pluknet

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?

comment:5 Changed 3 months ago by mdounin

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.

Note: See TracTickets for help on using tickets.