Hello! On Thu, Aug 20, 2020 at 11:47:08PM +0300, Sergey Kandaurov wrote:
> > > On 20 Aug 2020, at 22:16, Maxim Dounin <mdou...@mdounin.ru> wrote: > > > > Hello! > > > > On Thu, Aug 20, 2020 at 09:30:37AM -0400, vergil wrote: > > > >> Maxim Dounin Wrote: > >> ------------------------------------------------------- > >>> Do you see any other errors on the same connection before the > >>> SSL_shutdown() error? As suggested previously, somethig relevant > >>> might be logged at the "info" level. Note that seeing info-level > >>> error messages will probably require error logging to be > >>> reconfigured, much like with debug. > >>> > >>> If there is nothing, I'm afraid the only solution would be to try > >>> to catch a debugging log related to these errors. As previously > >>> suggested, this can be done without too much load by using the > >>> debug_connection with relatively large CIDR blocks and waiting for > >>> the error to happen from with a client from one of these blocks. > >>> > >>> -- > >>> Maxim Dounin > >>> http://mdounin.ru/ > >>> _______________________________________________ > >>> nginx mailing list > >>> nginx@nginx.org > >>> http://mailman.nginx.org/mailman/listinfo/nginx > >> > >> > >> Good day. > >> > >> I've change log level from notice to info and there's indeed one new > >> message > >> related to HTTP/2 problem. > >> > >> 2020/08/20 15:59:31 [info] 32305#32305: *1982005 client timed out (110: > >> Connection timed out) while processing HTTP/2 connection, client: XXX, > >> server: XXX:443 > >> 2020/08/20 15:59:36 [crit] 32305#32305: *1982005 SSL_shutdown() failed > >> (SSL: > >> error:1409F07F:SSL routines:ssl3_write retry) while processing HTTP/2 > >> connection, client: XXX, server: XXX:443 > >> > >> I don't know if this will help. > > > > Thanks, I think I have an idea about what's going on here. Likely > > these are read timeouts, which can interfere with writes in > > HTTP/2, causing SSL_shutdown() errors. Please try the following > > patch: > > > > # HG changeset patch > > # User Maxim Dounin <mdou...@mdounin.ru> > > # Date 1597950898 -10800 > > # Thu Aug 20 22:14:58 2020 +0300 > > # Node ID f95e76e9144773a664271c3e91e4cb6df3bc774a > > # Parent 7015f26aef904e2ec17b4b6f6387fd3b8298f79d > > HTTP/2: connections with read timeouts marked as timed out. > > > > In HTTP/2, closing a connection because of a read timeout might happen > > when there are unfinished writes, resulting in SSL_shutdown() errors. > > Fix is to mark such connections with the c->timedout flag to avoid sending > > SSL shutdown. > > > > diff --git a/src/http/v2/ngx_http_v2.c b/src/http/v2/ngx_http_v2.c > > --- a/src/http/v2/ngx_http_v2.c > > +++ b/src/http/v2/ngx_http_v2.c > > @@ -346,6 +346,7 @@ ngx_http_v2_read_handler(ngx_event_t *re > > > > if (rev->timedout) { > > ngx_log_error(NGX_LOG_INFO, c->log, NGX_ETIMEDOUT, "client timed > > out"); > > + c->timedout = 1; > > ngx_http_v2_finalize_connection(h2c, NGX_HTTP_V2_PROTOCOL_ERROR); > > return; > > } > > FYI, I could reproduce this case, the patch fixes it for me. > A similar case exists in idle handler, it also needs love: > > diff --git a/src/http/v2/ngx_http_v2.c b/src/http/v2/ngx_http_v2.c > @@ -4584,6 +4585,7 @@ ngx_http_v2_idle_handler(ngx_event_t *re > ngx_log_debug0(NGX_LOG_DEBUG_HTTP, c->log, 0, "http2 idle handler"); > > if (rev->timedout || c->close) { > + c->timedout = 1; > ngx_http_v2_finalize_connection(h2c, NGX_HTTP_V2_NO_ERROR); > return; > } > > Traces from read handler: > > 2020/08/20 23:25:48 [debug] 1286#0: *1 http2 frame complete > pos:000000010E521838 end:000000010E52183A > 2020/08/20 23:25:48 [debug] 1286#0: *1 http2 frame state save > pos:000000010E521838 end:000000010E52183A handler:000000010A29B900 > 2020/08/20 23:25:48 [debug] 1286#0: *1 event timer: 7, old: 1931548335, new: > 1931548341 > 2020/08/20 23:25:48 [debug] 1286#0: timer delta: 1 > 2020/08/20 23:25:48 [debug] 1286#0: worker cycle > 2020/08/20 23:25:48 [debug] 1286#0: kevent timer: 994, changes: 0 > 2020/08/20 23:25:49 [debug] 1286#0: kevent events: 0 > 2020/08/20 23:25:49 [debug] 1286#0: timer delta: 999 > 2020/08/20 23:25:49 [debug] 1286#0: *1 event timer del: 7: 1931548335 > 2020/08/20 23:25:49 [info] 1286#0: *1 client timed out (60: Operation timed > out) while processing HTTP/2 connection, client: 127.0.0.1, server: > 127.0.0.1:8080 > 2020/08/20 23:25:49 [debug] 1286#0: *1 http2 send GOAWAY frame: last sid 1, > error 1 > 2020/08/20 23:25:49 [debug] 1286#0: *1 http2 frame out: 00006060000077C0 > sid:0 bl:0 len:8 > 2020/08/20 23:25:49 [debug] 1286#0: *1 SSL buf copy: 17 > 2020/08/20 23:25:49 [debug] 1286#0: *1 SSL to write: 17 > 2020/08/20 23:25:49 [debug] 1286#0: *1 SSL_write: -1 > 2020/08/20 23:25:49 [debug] 1286#0: *1 SSL_get_error: 3 > 2020/08/20 23:25:49 [debug] 1286#0: *1 kevent set event: 7: ft:-2 fl:0025 > 2020/08/20 23:25:49 [debug] 1286#0: *1 http2 frame sent: 00006060000077C0 > sid:0 bl:0 len:8 > 2020/08/20 23:25:49 [debug] 1286#0: *1 event timer add: 7: 8000:1931556340 > 2020/08/20 23:25:49 [debug] 1286#0: *1 close http connection: 7 > 2020/08/20 23:25:49 [debug] 1286#0: *1 SSL_shutdown: -1 > 2020/08/20 23:25:49 [debug] 1286#0: *1 SSL_get_error: 3 > 2020/08/20 23:25:49 [debug] 1286#0: *1 event timer add: 7: 3000:1931551340 > 2020/08/20 23:25:49 [debug] 1286#0: worker cycle > 2020/08/20 23:25:49 [debug] 1286#0: kevent timer: 3000, changes: 1 > 2020/08/20 23:25:51 [debug] 1286#0: kevent events: 1 > 2020/08/20 23:25:51 [debug] 1286#0: kevent: 7: ft:-2 fl:0025 ff:00000000 > d:49039 ud:000062F00000E538 > 2020/08/20 23:25:51 [debug] 1286#0: *1 SSL shutdown handler > 2020/08/20 23:25:51 [debug] 1286#0: *1 SSL_shutdown: -1 > 2020/08/20 23:25:51 [debug] 1286#0: *1 SSL_get_error: 1 > 2020/08/20 23:25:51 [crit] 1286#0: *1 SSL_shutdown() failed (SSL: > error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while > processing HTTP/2 connection, client: 127.0.0.1, server: 127.0.0.1:8080 > > And from idle handler: > > 2020/08/20 23:32:00 [debug] 1374#0: *1 http2 idle handler > 2020/08/20 23:32:00 [debug] 1374#0: *1 http2 send GOAWAY frame: last sid 1, > error 0 > 2020/08/20 23:32:00 [debug] 1374#0: *1 http2 frame out: 00006060000077C0 > sid:0 bl:0 len:8 > 2020/08/20 23:32:00 [debug] 1374#0: *1 SSL buf copy: 17 > 2020/08/20 23:32:00 [debug] 1374#0: *1 SSL to write: 17 > 2020/08/20 23:32:00 [debug] 1374#0: *1 SSL_write: -1 > 2020/08/20 23:32:00 [debug] 1374#0: *1 SSL_get_error: 3 > 2020/08/20 23:32:00 [debug] 1374#0: *1 kevent set event: 7: ft:-2 fl:0025 > 2020/08/20 23:32:00 [debug] 1374#0: *1 http2 frame sent: 00006060000077C0 > sid:0 bl:0 len:8 > 2020/08/20 23:32:00 [debug] 1374#0: *1 event timer add: 7: 8000:1931927860 > 2020/08/20 23:32:00 [debug] 1374#0: *1 close http connection: 7 > 2020/08/20 23:32:00 [debug] 1374#0: *1 SSL_shutdown: -1 > 2020/08/20 23:32:00 [debug] 1374#0: *1 SSL_get_error: 3 > 2020/08/20 23:32:00 [debug] 1374#0: *1 event timer add: 7: 3000:1931922860 It's with disabled lingering close, correct? > 2020/08/20 23:32:00 [debug] 1374#0: worker cycle > 2020/08/20 23:32:00 [debug] 1374#0: kevent timer: 3000, changes: 1 > 2020/08/20 23:32:02 [debug] 1374#0: kevent events: 1 > 2020/08/20 23:32:02 [debug] 1374#0: kevent: 7: ft:-2 fl:0025 ff:00000000 > d:49039 ud:000062F00000E538 > 2020/08/20 23:32:02 [debug] 1374#0: *1 SSL shutdown handler > 2020/08/20 23:32:02 [debug] 1374#0: *1 SSL_shutdown: -1 > 2020/08/20 23:32:02 [debug] 1374#0: *1 SSL_get_error: 1 > 2020/08/20 23:32:02 [crit] 1374#0: *1 SSL_shutdown() failed (SSL: > error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while > processing HTTP/2 connection, client: 127.0.0.1, server: 127.0.0.1:8080 I don't like the idea of disabling SSL shutdown after HTTP/2 idle timeout. This more or less means disabling it in all normal cases. We might either consider introducing a code to continue sending the blocked frame, or to find a different way to mitigate this. In particular, the following patch might be good enough (replaces both patches for read timeouts, as and incorporates initial c->error patch): diff --git a/src/event/ngx_event_openssl.c b/src/event/ngx_event_openssl.c --- a/src/event/ngx_event_openssl.c +++ b/src/event/ngx_event_openssl.c @@ -2793,7 +2793,7 @@ ngx_ssl_shutdown(ngx_connection_t *c) return NGX_OK; } - if (c->timedout) { + if (c->timedout || c->error || c->buffered) { mode = SSL_RECEIVED_SHUTDOWN|SSL_SENT_SHUTDOWN; SSL_set_quiet_shutdown(c->ssl->connection, 1); -- Maxim Dounin http://mdounin.ru/ _______________________________________________ nginx mailing list nginx@nginx.org http://mailman.nginx.org/mailman/listinfo/nginx
