> On 22 Aug 2020, at 01:30, Maxim Dounin <mdou...@mdounin.ru> wrote:
>
> 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?
Yes, I had to disable it.
>
>> 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);
>
Works for me.
--
Sergey Kandaurov
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
