SSL_shutdown() failed (SSL: ... bad write retry)

classic Classic list List threaded Threaded
24 messages Options
12
Reply | Threaded
Open this post in threaded view
|

SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
Good day.

Todays morning we've updated one of our nginx servers to the latest version
(1.19.2 from 1.19.1).

Since then our log contains "SSL_shutdown() failed (SSL: ... bad write
retry)" messages which i think you'd fixed in this version (i didn't seen
this messages before as far as i remember).

Should i create a proper bug report with more info or you know about this?

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289087#msg-289087

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Maxim Dounin
Hello!

On Thu, Aug 13, 2020 at 09:10:22AM -0400, vergil wrote:

> Good day.
>
> Todays morning we've updated one of our nginx servers to the latest version
> (1.19.2 from 1.19.1).
>
> Since then our log contains "SSL_shutdown() failed (SSL: ... bad write
> retry)" messages which i think you'd fixed in this version (i didn't seen
> this messages before as far as i remember).
>
> Should i create a proper bug report with more info or you know about this?

Your report is the first one.  It would be helpful if you'll be
able to provide more details, including "nginx -V" output, full
error log messages seen and relevant configuration details.  A
debugging log would be ideal
(http://nginx.org/en/docs/debugging_log.html).

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
Of course!

nginx version: nginx/1.19.2
built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.12)
built with OpenSSL 1.0.2g  1 Mar 2016
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx
--modules-path=/usr/lib/nginx/modules --conf-path=/etc/nginx/nginx.conf
--error-log-path=/var/log/nginx/error.log
--http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid
--lock-path=/var/run/nginx.lock
--http-client-body-temp-path=/var/cache/nginx/client_temp
--http-proxy-temp-path=/var/cache/nginx/proxy_temp
--http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp
--http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp
--http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx
--with-compat --with-file-aio --with-threads --with-http_addition_module
--with-http_auth_request_module --with-http_dav_module
--with-http_flv_module --with-http_gunzip_module
--with-http_gzip_static_module --with-http_mp4_module
--with-http_random_index_module --with-http_realip_module
--with-http_secure_link_module --with-http_slice_module
--with-http_ssl_module --with-http_stub_status_module --with-http_sub_module
--with-http_v2_module --with-mail --with-mail_ssl_module --with-stream
--with-stream_realip_module --with-stream_ssl_module
--with-stream_ssl_preread_module --with-cc-opt='-g -O2 -fPIE
-fstack-protector-strong -Wformat -Werror=format-security
-Wp,-D_FORTIFY_SOURCE=2 -fPIC' --with-ld-opt='-Wl,-Bsymbolic-functions -fPIE
-pie -Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie'


There's two different messages in the logs (http/2 are more rare):

2020/08/13 16:53:27 [crit] 2466#2466: *743603 SSL_shutdown() failed (SSL:
error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while
closing request, client: XXX.XXX.XXX.XXX, server: XXX.XXX.XXX.XXX:443

2020/08/13 16:34:31 [crit] 2459#2459: *421699 SSL_shutdown() failed (SSL:
error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while
processing HTTP/2 connection, client: XXX.XXX.XXX.XXX, server:
XXX.XXX.XXX.XXX:443

I'll try to gather debug log with corresponding errors and update this topic
(i'll also gather configuration settings)

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289092#msg-289092

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
In reply to this post by Maxim Dounin
This one was hard to catch.

I've captured one error with 30 seconds delta before and after the event.
Where can i attach log file for you? There's 400K messages, so i cannot
simple put it here.

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289093#msg-289093

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Maxim Dounin
In reply to this post by zakirenish
Hello!

On Thu, Aug 13, 2020 at 10:01:38AM -0400, vergil wrote:

> Of course!
>
> nginx version: nginx/1.19.2
> built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.12)
> built with OpenSSL 1.0.2g  1 Mar 2016
> TLS SNI support enabled
> configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx
> --modules-path=/usr/lib/nginx/modules --conf-path=/etc/nginx/nginx.conf
> --error-log-path=/var/log/nginx/error.log
> --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid
> --lock-path=/var/run/nginx.lock
> --http-client-body-temp-path=/var/cache/nginx/client_temp
> --http-proxy-temp-path=/var/cache/nginx/proxy_temp
> --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp
> --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp
> --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx
> --with-compat --with-file-aio --with-threads --with-http_addition_module
> --with-http_auth_request_module --with-http_dav_module
> --with-http_flv_module --with-http_gunzip_module
> --with-http_gzip_static_module --with-http_mp4_module
> --with-http_random_index_module --with-http_realip_module
> --with-http_secure_link_module --with-http_slice_module
> --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module
> --with-http_v2_module --with-mail --with-mail_ssl_module --with-stream
> --with-stream_realip_module --with-stream_ssl_module
> --with-stream_ssl_preread_module --with-cc-opt='-g -O2 -fPIE
> -fstack-protector-strong -Wformat -Werror=format-security
> -Wp,-D_FORTIFY_SOURCE=2 -fPIC' --with-ld-opt='-Wl,-Bsymbolic-functions -fPIE
> -pie -Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie'
>
>
> There's two different messages in the logs (http/2 are more rare):
>
> 2020/08/13 16:53:27 [crit] 2466#2466: *743603 SSL_shutdown() failed (SSL:
> error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while
> closing request, client: XXX.XXX.XXX.XXX, server: XXX.XXX.XXX.XXX:443
>
> 2020/08/13 16:34:31 [crit] 2459#2459: *421699 SSL_shutdown() failed (SSL:
> error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while
> processing HTTP/2 connection, client: XXX.XXX.XXX.XXX, server:
> XXX.XXX.XXX.XXX:443

Thanks.  Is there anything related to these connections on other
logging levels, such as "info"?

(Just in case, connection identifiers are "*743603" and "*421699"
in the above log messages).

> I'll try to gather debug log with corresponding errors and update this topic
> (i'll also gather configuration settings)

Yes, please, debug log would be really helpful.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Maxim Dounin
In reply to this post by zakirenish
Hello!

On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:

> This one was hard to catch.
>
> I've captured one error with 30 seconds delta before and after the event.
> Where can i attach log file for you? There's 400K messages, so i cannot
> simple put it here.

Attaching the log to the message into the mailing list should
work, but I'm not sure it's supported by the (obsolete) forum
interface you are using.  If not, you may put the log at a
convinient place and provide a link here, or attach it to a
ticket on trac.nginx.org, or email to me privetely.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
Maxim Dounin Wrote:
-------------------------------------------------------

> Hello!
>
> On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:
>
> > This one was hard to catch.
> >
> > I've captured one error with 30 seconds delta before and after the
> event.
> > Where can i attach log file for you? There's 400K messages, so i
> cannot
> > simple put it here.
>
> Attaching the log to the message into the mailing list should
> work, but I'm not sure it's supported by the (obsolete) forum
> interface you are using.  If not, you may put the log at a
> convinient place and provide a link here, or attach it to a
> ticket on trac.nginx.org, or email to me privetely.
>
> --
> Maxim Dounin
> http://mdounin.ru/
> _______________________________________________
> nginx mailing list
> [hidden email]
> http://mailman.nginx.org/mailman/listinfo/nginx

I've attached log file to our S3 public storage. You can download it through
this link:
https://drive-public-eu.s3.eu-central-1.amazonaws.com/nginx/nginx-debug.csv

A note: this is a CSV format from our logging system. I can try to extract
logs in original format if you need.

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289096#msg-289096

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Maxim Dounin
Hello!

On Thu, Aug 13, 2020 at 12:11:54PM -0400, vergil wrote:

> Maxim Dounin Wrote:
> -------------------------------------------------------
> > Hello!
> >
> > On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:
> >
> > > This one was hard to catch.
> > >
> > > I've captured one error with 30 seconds delta before and after the
> > event.
> > > Where can i attach log file for you? There's 400K messages, so i
> > cannot
> > > simple put it here.
> >
> > Attaching the log to the message into the mailing list should
> > work, but I'm not sure it's supported by the (obsolete) forum
> > interface you are using.  If not, you may put the log at a
> > convinient place and provide a link here, or attach it to a
> > ticket on trac.nginx.org, or email to me privetely.
>
> I've attached log file to our S3 public storage. You can download it through
> this link:
> https://drive-public-eu.s3.eu-central-1.amazonaws.com/nginx/nginx-debug.csv
>
> A note: this is a CSV format from our logging system. I can try to extract
> logs in original format if you need.

Thanks, but this doesn't seem to contain anything related to the
SSL_shutdown() except the message itself:

"2020-08-13T15:19:03.279Z","7","shmtx lock",
"2020-08-13T15:19:03.279Z","7","shmtx lock",
"2020-08-13T15:19:03.279Z","7","timer delta: 0",
"2020-08-13T15:19:03.280Z","2","SSL_shutdown() failed (SSL: error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while closing request, client: XXX.XXX.XXX.XXX, server: XXX.XXX.XXX.XXX:443","9140"
"2020-08-13T15:19:03.280Z","7","epoll: fd:322 ev:0005 d:00007F0A0FCDDEB0",
"2020-08-13T15:19:03.280Z","7","epoll: fd:54 ev:0004 d:00007F0A0FCDFAC9",

And nothing else in the log saying "SSL_shutdow()", while there
should be a debug messages like "SSL_shutdown: -1" and
"SSL_get_error: ..." right before the message, and nothing at all
related to the connection 9140.

It looks like the debug logging is only enabled on the global
level, but disabled at http or server level.  Please see the part
starting at "Note that redefining the log without also specifying
the debug level will disable the debugging log" in the "A
debugging log" article
(http://nginx.org/en/docs/debugging_log.html).

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
Maxim Dounin Wrote:
-------------------------------------------------------

> Hello!
>
> On Thu, Aug 13, 2020 at 12:11:54PM -0400, vergil wrote:
>
> > Maxim Dounin Wrote:
> > -------------------------------------------------------
> > > Hello!
> > >
> > > On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:
> > >
> > > > This one was hard to catch.
> > > >
> > > > I've captured one error with 30 seconds delta before and after
> the
> > > event.
> > > > Where can i attach log file for you? There's 400K messages, so i
> > > cannot
> > > > simple put it here.
> > >
> > > Attaching the log to the message into the mailing list should
> > > work, but I'm not sure it's supported by the (obsolete) forum
> > > interface you are using.  If not, you may put the log at a
> > > convinient place and provide a link here, or attach it to a
> > > ticket on trac.nginx.org, or email to me privetely.
> >
> > I've attached log file to our S3 public storage. You can download it
> through
> > this link:
> >
> https://drive-public-eu.s3.eu-central-1.amazonaws.com/nginx/nginx-debu
> g.csv
> >
> > A note: this is a CSV format from our logging system. I can try to
> extract
> > logs in original format if you need.
>
> Thanks, but this doesn't seem to contain anything related to the
> SSL_shutdown() except the message itself:
>
> "2020-08-13T15:19:03.279Z","7","shmtx lock",
> "2020-08-13T15:19:03.279Z","7","shmtx lock",
> "2020-08-13T15:19:03.279Z","7","timer delta: 0",
> "2020-08-13T15:19:03.280Z","2","SSL_shutdown() failed (SSL:
> error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while
> closing request, client: XXX.XXX.XXX.XXX, server:
> XXX.XXX.XXX.XXX:443","9140"
> "2020-08-13T15:19:03.280Z","7","epoll: fd:322 ev:0005
> d:00007F0A0FCDDEB0",
> "2020-08-13T15:19:03.280Z","7","epoll: fd:54 ev:0004
> d:00007F0A0FCDFAC9",
>
> And nothing else in the log saying "SSL_shutdow()", while there
> should be a debug messages like "SSL_shutdown: -1" and
> "SSL_get_error: ..." right before the message, and nothing at all
> related to the connection 9140.
>
> It looks like the debug logging is only enabled on the global
> level, but disabled at http or server level.  Please see the part
> starting at "Note that redefining the log without also specifying
> the debug level will disable the debugging log" in the "A
> debugging log" article
> (http://nginx.org/en/docs/debugging_log.html).
>
> --
> Maxim Dounin
> http://mdounin.ru/
> _______________________________________________
> nginx mailing list
> [hidden email]
> http://mailman.nginx.org/mailman/listinfo/nginx

Oh, good catch. I completely forgot about this. My bad.

I will re-upload the logs when i'd gather new information.

Sorry for this.

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289098#msg-289098

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
In reply to this post by Maxim Dounin
Maxim Dounin Wrote:
-------------------------------------------------------

> Hello!
>
> On Thu, Aug 13, 2020 at 12:11:54PM -0400, vergil wrote:
>
> > Maxim Dounin Wrote:
> > -------------------------------------------------------
> > > Hello!
> > >
> > > On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:
> > >
> > > > This one was hard to catch.
> > > >
> > > > I've captured one error with 30 seconds delta before and after
> the
> > > event.
> > > > Where can i attach log file for you? There's 400K messages, so i
> > > cannot
> > > > simple put it here.
> > >
> > > Attaching the log to the message into the mailing list should
> > > work, but I'm not sure it's supported by the (obsolete) forum
> > > interface you are using.  If not, you may put the log at a
> > > convinient place and provide a link here, or attach it to a
> > > ticket on trac.nginx.org, or email to me privetely.
> >
> > I've attached log file to our S3 public storage. You can download it
> through
> > this link:
> >
> https://drive-public-eu.s3.eu-central-1.amazonaws.com/nginx/nginx-debu
> g.csv
> >
> > A note: this is a CSV format from our logging system. I can try to
> extract
> > logs in original format if you need.
>
> Thanks, but this doesn't seem to contain anything related to the
> SSL_shutdown() except the message itself:
>
> "2020-08-13T15:19:03.279Z","7","shmtx lock",
> "2020-08-13T15:19:03.279Z","7","shmtx lock",
> "2020-08-13T15:19:03.279Z","7","timer delta: 0",
> "2020-08-13T15:19:03.280Z","2","SSL_shutdown() failed (SSL:
> error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while
> closing request, client: XXX.XXX.XXX.XXX, server:
> XXX.XXX.XXX.XXX:443","9140"
> "2020-08-13T15:19:03.280Z","7","epoll: fd:322 ev:0005
> d:00007F0A0FCDDEB0",
> "2020-08-13T15:19:03.280Z","7","epoll: fd:54 ev:0004
> d:00007F0A0FCDFAC9",
>
> And nothing else in the log saying "SSL_shutdow()", while there
> should be a debug messages like "SSL_shutdown: -1" and
> "SSL_get_error: ..." right before the message, and nothing at all
> related to the connection 9140.
>
> It looks like the debug logging is only enabled on the global
> level, but disabled at http or server level.  Please see the part
> starting at "Note that redefining the log without also specifying
> the debug level will disable the debugging log" in the "A
> debugging log" article
> (http://nginx.org/en/docs/debugging_log.html).
>
> --
> Maxim Dounin
> http://mdounin.ru/
> _______________________________________________
> nginx mailing list
> [hidden email]
> http://mailman.nginx.org/mailman/listinfo/nginx

So... Bad news: i cannot capture the event when full debug enabled. Server
cannot handle the load and our service partially down at that time.

What can i say is that this problem reveal itself on all servers with new
nginx version.

I'll send you the link privately where you can get our (some-redacted)
config files.

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289112#msg-289112

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Maxim Dounin
Hello!

On Fri, Aug 14, 2020 at 10:34:49AM -0400, vergil wrote:

> Maxim Dounin Wrote:
> -------------------------------------------------------
> > Hello!
> >
> > On Thu, Aug 13, 2020 at 12:11:54PM -0400, vergil wrote:
> >
> > > Maxim Dounin Wrote:
> > > -------------------------------------------------------
> > > > Hello!
> > > >
> > > > On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:
> > > >
> > > > > This one was hard to catch.
> > > > >
> > > > > I've captured one error with 30 seconds delta before and after
> > the
> > > > event.
> > > > > Where can i attach log file for you? There's 400K messages, so i
> > > > cannot
> > > > > simple put it here.
> > > >
> > > > Attaching the log to the message into the mailing list should
> > > > work, but I'm not sure it's supported by the (obsolete) forum
> > > > interface you are using.  If not, you may put the log at a
> > > > convinient place and provide a link here, or attach it to a
> > > > ticket on trac.nginx.org, or email to me privetely.
> > >
> > > I've attached log file to our S3 public storage. You can download it
> > through
> > > this link:
> > >
> > https://drive-public-eu.s3.eu-central-1.amazonaws.com/nginx/nginx-debu
> > g.csv
> > >
> > > A note: this is a CSV format from our logging system. I can try to
> > extract
> > > logs in original format if you need.
> >
> > Thanks, but this doesn't seem to contain anything related to the
> > SSL_shutdown() except the message itself:
> >
> > "2020-08-13T15:19:03.279Z","7","shmtx lock",
> > "2020-08-13T15:19:03.279Z","7","shmtx lock",
> > "2020-08-13T15:19:03.279Z","7","timer delta: 0",
> > "2020-08-13T15:19:03.280Z","2","SSL_shutdown() failed (SSL:
> > error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while
> > closing request, client: XXX.XXX.XXX.XXX, server:
> > XXX.XXX.XXX.XXX:443","9140"
> > "2020-08-13T15:19:03.280Z","7","epoll: fd:322 ev:0005
> > d:00007F0A0FCDDEB0",
> > "2020-08-13T15:19:03.280Z","7","epoll: fd:54 ev:0004
> > d:00007F0A0FCDFAC9",
> >
> > And nothing else in the log saying "SSL_shutdow()", while there
> > should be a debug messages like "SSL_shutdown: -1" and
> > "SSL_get_error: ..." right before the message, and nothing at all
> > related to the connection 9140.
> >
> > It looks like the debug logging is only enabled on the global
> > level, but disabled at http or server level.  Please see the part
> > starting at "Note that redefining the log without also specifying
> > the debug level will disable the debugging log" in the "A
> > debugging log" article
> > (http://nginx.org/en/docs/debugging_log.html).
>
> So... Bad news: i cannot capture the event when full debug enabled. Server
> cannot handle the load and our service partially down at that time.
>
> What can i say is that this problem reveal itself on all servers with new
> nginx version.
>
> I'll send you the link privately where you can get our (some-redacted)
> config files.

Thank you for your efforts.  Just in case, it is possible to
configure debug logging only for parts of the load - using the
debug_connection directive with large networks in CIDR notation
(http://nginx.org/r/debug_connection).  It's probably not needed
in this particular case, see below.

I was able to reporoduce an "SSL_shutdown() failed (SSL: ... bad
write retry)" error at least in one case, similar to the one
previously observed with SSL_write() in
https://trac.nginx.org/nginx/ticket/1194.  Previously, this case
wasn't causing SSL_shutdown() errors, but SSL shutdown fix
introduced in nginx 1.19.2 revealed the problem.

The following patch should fix this.  It was discussed previously
as a possible fix for other SSL_shutdown() errors fixed in 1.19.2,
but wasn't commited as there were concerns it will effectively
disable SSL shutdown in some unrelated cases where c->error flag
is misused.  Now it is more or less clear that the change is
needed.

Patch (it would be great if you'll be able to test if it fixes the
problem for you):

# HG changeset patch
# User Maxim Dounin <[hidden email]>
# Date 1597531639 -10800
#      Sun Aug 16 01:47:19 2020 +0300
# Node ID be7a3155e00161baf7359ffa73a3a226f1e487c9
# Parent  7d46c9f56c9afe34a38bb3aea99550a2fd884280
SSL: disabled shutdown after connection errors.

This fixes ""SSL_shutdown() failed (SSL: ... bad write retry)" errors
as observed on the second SSL_shutdown() call after SSL shutdown fixes in
09fb2135a589 (1.19.2), notably when sending fails in ngx_http_test_expect(),
similarly to ticket 1194.

Note that there are some places where c->error is misused to prevent
further output, such as ngx_http_v2_finalize_connection() if there
are pending streams, or in filter finalization.  These places seem
to be extreme enough to don't care about missing shutdown though.
For example, filter finalization currently prevents keepalive from
being used.

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) {
         mode = SSL_RECEIVED_SHUTDOWN|SSL_SENT_SHUTDOWN;
         SSL_set_quiet_shutdown(c->ssl->connection, 1);
 



--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
Great to hear.

I knew about debug_connection but thought it would be too difficult to tune.
We'll see how patch helps in that regard.

I'll try to test it tomorrow.

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289115#msg-289115

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
In reply to this post by Maxim Dounin
Maxim Dounin Wrote:
-------------------------------------------------------

> Hello!
>
> On Fri, Aug 14, 2020 at 10:34:49AM -0400, vergil wrote:
>
> > Maxim Dounin Wrote:
> > -------------------------------------------------------
> > > Hello!
> > >
> > > On Thu, Aug 13, 2020 at 12:11:54PM -0400, vergil wrote:
> > >
> > > > Maxim Dounin Wrote:
> > > > -------------------------------------------------------
> > > > > Hello!
> > > > >
> > > > > On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:
> > > > >
> > > > > > This one was hard to catch.
> > > > > >
> > > > > > I've captured one error with 30 seconds delta before and
> after
> > > the
> > > > > event.
> > > > > > Where can i attach log file for you? There's 400K messages,
> so i
> > > > > cannot
> > > > > > simple put it here.
> > > > >
> > > > > Attaching the log to the message into the mailing list should
> > > > > work, but I'm not sure it's supported by the (obsolete) forum
> > > > > interface you are using.  If not, you may put the log at a
> > > > > convinient place and provide a link here, or attach it to a
> > > > > ticket on trac.nginx.org, or email to me privetely.
> > > >
> > > > I've attached log file to our S3 public storage. You can
> download it
> > > through
> > > > this link:
> > > >
> > >
> https://drive-public-eu.s3.eu-central-1.amazonaws.com/nginx/nginx-debu
> > > g.csv
> > > >
> > > > A note: this is a CSV format from our logging system. I can try
> to
> > > extract
> > > > logs in original format if you need.
> > >
> > > Thanks, but this doesn't seem to contain anything related to the
> > > SSL_shutdown() except the message itself:
> > >
> > > "2020-08-13T15:19:03.279Z","7","shmtx lock",
> > > "2020-08-13T15:19:03.279Z","7","shmtx lock",
> > > "2020-08-13T15:19:03.279Z","7","timer delta: 0",
> > > "2020-08-13T15:19:03.280Z","2","SSL_shutdown() failed (SSL:
> > > error:1409F07F:SSL routines:ssl3_write_pending:bad write retry)
> while
> > > closing request, client: XXX.XXX.XXX.XXX, server:
> > > XXX.XXX.XXX.XXX:443","9140"
> > > "2020-08-13T15:19:03.280Z","7","epoll: fd:322 ev:0005
> > > d:00007F0A0FCDDEB0",
> > > "2020-08-13T15:19:03.280Z","7","epoll: fd:54 ev:0004
> > > d:00007F0A0FCDFAC9",
> > >
> > > And nothing else in the log saying "SSL_shutdow()", while there
> > > should be a debug messages like "SSL_shutdown: -1" and
> > > "SSL_get_error: ..." right before the message, and nothing at all
> > > related to the connection 9140.
> > >
> > > It looks like the debug logging is only enabled on the global
> > > level, but disabled at http or server level.  Please see the part
> > > starting at "Note that redefining the log without also specifying
> > > the debug level will disable the debugging log" in the "A
> > > debugging log" article
> > > (http://nginx.org/en/docs/debugging_log.html).
> >
> > So... Bad news: i cannot capture the event when full debug enabled.
> Server
> > cannot handle the load and our service partially down at that time.
> >
> > What can i say is that this problem reveal itself on all servers
> with new
> > nginx version.
> >
> > I'll send you the link privately where you can get our
> (some-redacted)
> > config files.
>
> Thank you for your efforts.  Just in case, it is possible to
> configure debug logging only for parts of the load - using the
> debug_connection directive with large networks in CIDR notation
> (http://nginx.org/r/debug_connection).  It's probably not needed
> in this particular case, see below.
>
> I was able to reporoduce an "SSL_shutdown() failed (SSL: ... bad
> write retry)" error at least in one case, similar to the one
> previously observed with SSL_write() in
> https://trac.nginx.org/nginx/ticket/1194.  Previously, this case
> wasn't causing SSL_shutdown() errors, but SSL shutdown fix
> introduced in nginx 1.19.2 revealed the problem.
>
> The following patch should fix this.  It was discussed previously
> as a possible fix for other SSL_shutdown() errors fixed in 1.19.2,
> but wasn't commited as there were concerns it will effectively
> disable SSL shutdown in some unrelated cases where c->error flag
> is misused.  Now it is more or less clear that the change is
> needed.
>
> Patch (it would be great if you'll be able to test if it fixes the
> problem for you):
>
> # HG changeset patch
> # User Maxim Dounin <[hidden email]>
> # Date 1597531639 -10800
> #      Sun Aug 16 01:47:19 2020 +0300
> # Node ID be7a3155e00161baf7359ffa73a3a226f1e487c9
> # Parent  7d46c9f56c9afe34a38bb3aea99550a2fd884280
> SSL: disabled shutdown after connection errors.
>
> This fixes ""SSL_shutdown() failed (SSL: ... bad write retry)" errors
> as observed on the second SSL_shutdown() call after SSL shutdown fixes
> in
> 09fb2135a589 (1.19.2), notably when sending fails in
> ngx_http_test_expect(),
> similarly to ticket 1194.
>
> Note that there are some places where c->error is misused to prevent
> further output, such as ngx_http_v2_finalize_connection() if there
> are pending streams, or in filter finalization.  These places seem
> to be extreme enough to don't care about missing shutdown though.
> For example, filter finalization currently prevents keepalive from
> being used.
>
> 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) {
>          mode = SSL_RECEIVED_SHUTDOWN|SSL_SENT_SHUTDOWN;
>          SSL_set_quiet_shutdown(c->ssl->connection, 1);
>  
>
>
>
> --
> Maxim Dounin
> http://mdounin.ru/
> _______________________________________________
> nginx mailing list
> [hidden email]
> http://mailman.nginx.org/mailman/listinfo/nginx

Good day.

Patch mentioned above solved half the problems.

SSL_shutdown() failed (SSL: error:1409F07F:SSL
routines:ssl3_write_pending:bad write retry) while processing HTTP/2
connection

Still remains in the logs.

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289130#msg-289130

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Maxim Dounin
Hello!

On Tue, Aug 18, 2020 at 05:35:16AM -0400, vergil wrote:

> Maxim Dounin Wrote:
> -------------------------------------------------------
> > Hello!
> >
> > On Fri, Aug 14, 2020 at 10:34:49AM -0400, vergil wrote:
> >
> > > Maxim Dounin Wrote:
> > > -------------------------------------------------------
> > > > Hello!
> > > >
> > > > On Thu, Aug 13, 2020 at 12:11:54PM -0400, vergil wrote:
> > > >
> > > > > Maxim Dounin Wrote:
> > > > > -------------------------------------------------------
> > > > > > Hello!
> > > > > >
> > > > > > On Thu, Aug 13, 2020 at 11:39:36AM -0400, vergil wrote:
> > > > > >
> > > > > > > This one was hard to catch.
> > > > > > >
> > > > > > > I've captured one error with 30 seconds delta before and
> > after
> > > > the
> > > > > > event.
> > > > > > > Where can i attach log file for you? There's 400K messages,
> > so i
> > > > > > cannot
> > > > > > > simple put it here.
> > > > > >
> > > > > > Attaching the log to the message into the mailing list should
> > > > > > work, but I'm not sure it's supported by the (obsolete) forum
> > > > > > interface you are using.  If not, you may put the log at a
> > > > > > convinient place and provide a link here, or attach it to a
> > > > > > ticket on trac.nginx.org, or email to me privetely.
> > > > >
> > > > > I've attached log file to our S3 public storage. You can
> > download it
> > > > through
> > > > > this link:
> > > > >
> > > >
> > https://drive-public-eu.s3.eu-central-1.amazonaws.com/nginx/nginx-debu
> > > > g.csv
> > > > >
> > > > > A note: this is a CSV format from our logging system. I can try
> > to
> > > > extract
> > > > > logs in original format if you need.
> > > >
> > > > Thanks, but this doesn't seem to contain anything related to the
> > > > SSL_shutdown() except the message itself:
> > > >
> > > > "2020-08-13T15:19:03.279Z","7","shmtx lock",
> > > > "2020-08-13T15:19:03.279Z","7","shmtx lock",
> > > > "2020-08-13T15:19:03.279Z","7","timer delta: 0",
> > > > "2020-08-13T15:19:03.280Z","2","SSL_shutdown() failed (SSL:
> > > > error:1409F07F:SSL routines:ssl3_write_pending:bad write retry)
> > while
> > > > closing request, client: XXX.XXX.XXX.XXX, server:
> > > > XXX.XXX.XXX.XXX:443","9140"
> > > > "2020-08-13T15:19:03.280Z","7","epoll: fd:322 ev:0005
> > > > d:00007F0A0FCDDEB0",
> > > > "2020-08-13T15:19:03.280Z","7","epoll: fd:54 ev:0004
> > > > d:00007F0A0FCDFAC9",
> > > >
> > > > And nothing else in the log saying "SSL_shutdow()", while there
> > > > should be a debug messages like "SSL_shutdown: -1" and
> > > > "SSL_get_error: ..." right before the message, and nothing at all
> > > > related to the connection 9140.
> > > >
> > > > It looks like the debug logging is only enabled on the global
> > > > level, but disabled at http or server level.  Please see the part
> > > > starting at "Note that redefining the log without also specifying
> > > > the debug level will disable the debugging log" in the "A
> > > > debugging log" article
> > > > (http://nginx.org/en/docs/debugging_log.html).
> > >
> > > So... Bad news: i cannot capture the event when full debug enabled.
> > Server
> > > cannot handle the load and our service partially down at that time.
> > >
> > > What can i say is that this problem reveal itself on all servers
> > with new
> > > nginx version.
> > >
> > > I'll send you the link privately where you can get our
> > (some-redacted)
> > > config files.
> >
> > Thank you for your efforts.  Just in case, it is possible to
> > configure debug logging only for parts of the load - using the
> > debug_connection directive with large networks in CIDR notation
> > (http://nginx.org/r/debug_connection).  It's probably not needed
> > in this particular case, see below.
> >
> > I was able to reporoduce an "SSL_shutdown() failed (SSL: ... bad
> > write retry)" error at least in one case, similar to the one
> > previously observed with SSL_write() in
> > https://trac.nginx.org/nginx/ticket/1194.  Previously, this case
> > wasn't causing SSL_shutdown() errors, but SSL shutdown fix
> > introduced in nginx 1.19.2 revealed the problem.
> >
> > The following patch should fix this.  It was discussed previously
> > as a possible fix for other SSL_shutdown() errors fixed in 1.19.2,
> > but wasn't commited as there were concerns it will effectively
> > disable SSL shutdown in some unrelated cases where c->error flag
> > is misused.  Now it is more or less clear that the change is
> > needed.
> >
> > Patch (it would be great if you'll be able to test if it fixes the
> > problem for you):
> >
> > # HG changeset patch
> > # User Maxim Dounin <[hidden email]>
> > # Date 1597531639 -10800
> > #      Sun Aug 16 01:47:19 2020 +0300
> > # Node ID be7a3155e00161baf7359ffa73a3a226f1e487c9
> > # Parent  7d46c9f56c9afe34a38bb3aea99550a2fd884280
> > SSL: disabled shutdown after connection errors.
> >
> > This fixes ""SSL_shutdown() failed (SSL: ... bad write retry)" errors
> > as observed on the second SSL_shutdown() call after SSL shutdown fixes
> > in
> > 09fb2135a589 (1.19.2), notably when sending fails in
> > ngx_http_test_expect(),
> > similarly to ticket 1194.
> >
> > Note that there are some places where c->error is misused to prevent
> > further output, such as ngx_http_v2_finalize_connection() if there
> > are pending streams, or in filter finalization.  These places seem
> > to be extreme enough to don't care about missing shutdown though.
> > For example, filter finalization currently prevents keepalive from
> > being used.
> >
> > 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) {
> >          mode = SSL_RECEIVED_SHUTDOWN|SSL_SENT_SHUTDOWN;
> >          SSL_set_quiet_shutdown(c->ssl->connection, 1);
> >  
> >
>
> Good day.
>
> Patch mentioned above solved half the problems.
>
> SSL_shutdown() failed (SSL: error:1409F07F:SSL
> routines:ssl3_write_pending:bad write retry) while processing HTTP/2
> connection
>
> Still remains in the logs.

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
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

RE: Re: SSL_shutdown() failed (SSL: ... bad write retry)

6617065164
In reply to this post by zakirenish
Please take me off all of your contact lists and please stop blowing up my phone with text messages.

  -----Original Message-----
  From: <[hidden email]>
  Sent: Wed, 19 Aug 2020 19:50:54 +0300
  To: [hidden email]
 Subject: Re: SSL_shutdown() failed (SSL: ... bad write retry)

>Hello!
>
>On Tue, Aug 18, 2020 at 05:35:16AM -0400, vergil wrote:
>
>> Maxim Dounin Wrote:
>> -------------------------------------------------------
>> > Hello!
>> >
>> > On Fr

==================================================================
This mobile text message is brought to you by AT&T
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

zakirenish
In reply to this post by Maxim Dounin
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
> [hidden email]
> 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.

Regards,
Alexander.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,289087,289142#msg-289142

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

RE: Re: SSL_shutdown() failed (SSL: ... bad write retry)

6617065164
In reply to this post by zakirenish
Please stop sending me messages!

  -----Original Message-----
  From: <[hidden email]>
  Sent: Thu, 20 Aug 2020 09:30:37 -0400
  To: [hidden email]
 Subject: Re: SSL_shutdown() failed (SSL: ... bad write retry)

>Maxim Dounin Wrote:
>-------------------------------------------------------
>> Do you see any other errors on the same connection before the
>> SSL_shutdown() error?  As sugges

==================================================================
This mobile text message is brought to you by AT&T
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Maxim Dounin
In reply to this post by zakirenish
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
> > [hidden email]
> > 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 <[hidden email]>
# 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;
     }


--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: SSL_shutdown() failed (SSL: ... bad write retry)

Sergey Kandaurov

> On 20 Aug 2020, at 22:16, Maxim Dounin <[hidden email]> 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
>>> [hidden email]
>>> 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 <[hidden email]>
> # 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
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

RE: Re: SSL_shutdown() failed (SSL: ... bad write retry)

6617065164
In reply to this post by zakirenish
Please remove me from all of your contact lists, please. Thank you.

  -----Original Message-----
  From: <[hidden email]>
  Sent: Thu, 20 Aug 2020 23:47:08 +0300
  To: [hidden email]
 Subject: Re: SSL_shutdown() failed (SSL: ... bad write retry)

>
>> On 20 Aug 2020, at 22:16, Maxim Dounin <[hidden email]> wrote:
>>
>> Hello!
>>
>> On Thu, Aug 20, 2020 at 09:30:37AM -0400, vergil wrote:
>>
>>> Maxim Dounin Wrote:
>>

==================================================================
This mobile text message is brought to you by AT&T
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
12