SSL_shutdown() failed (SSL: ... bad write retry)
Maxim Dounin
mdounin at mdounin.ru
Fri Aug 21 22:30:52 UTC 2020
Hello!
On Thu, Aug 20, 2020 at 11:47:08PM +0300, Sergey Kandaurov wrote:
>
> > On 20 Aug 2020, at 22:16, Maxim Dounin <mdounin at 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 at 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 <mdounin at 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/
More information about the nginx
mailing list