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 <mdounin@mdounin.ru>
> > # 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
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx