#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 (11)
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!
follow-up: 10 comment:9 by , 4 years ago
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.
But I can see other entry related to this kind of log
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.
follow-up: 11 comment:10 by , 4 years ago
Replying to manuel.jurado.socialpoint.es@…:
But I can see other entry related to this kind of log
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.
comment:11 by , 4 years ago
Replying to Maxim Dounin:
Replying to manuel.jurado.socialpoint.es@…:
But I can see other entry related to this kind of log
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.
Could you please try this patch.