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