> On 20 Aug 2020, at 22:16, Maxim Dounin <mdounin@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 <mdounin@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
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
--
Sergey Kandaurov
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
