Opened 5 years ago
Closed 4 years ago
#1792 closed defect (fixed)
grpc module handles RST_STREAM(NO_ERROR) improperly on closed streams
| Reported by: | 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 (7)
comment:1 by , 5 years ago
| Status: | new → accepted |
|---|
follow-up: 4 comment:3 by , 5 years ago
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 by , 5 years ago
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 by , 5 years ago
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.
comment:7 by , 4 years ago
| Resolution: | → fixed |
|---|---|
| Status: | accepted → closed |
Fixed in 2096b21fcd10, thanks!
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) {