Hello!

On Wed, Dec 18, 2019 at 08:24:25PM +0300, Maxim Dounin wrote:

> On Mon, Dec 16, 2019 at 03:02:37PM +0100, Gábor Boskovits wrote:
>
> > On berlin.guix.gnu.org we observed a regression upon upgrading nginx
> > to 1.17.5. The problem was, when pipelining request to a proxy using
> > tls, we suddenly started to get 408 client timeouts, manifesting in
> > dropped connections. Currently we worked around the issue by
> > downgrading to 1.17.4. I have collected some information about the
> > problem here:
> > https://gitlab.com/g_bor/fix-nginx-tls
> > It contains the logs from the good and the bad version, a full nginx
> > config, some info about how nginx was built. I managed to bisect the
> > problem down to changeset 9d2ad2fb4423, which introduced the problem.
> > Any help in further debuggin this would be greatly appreciated.
>
> Thanks for the report, it indeed looks like a bug introduced
> in 9d2ad2fb4423.
>
> The problem is that c->read->handler is overwritted when switching
> to the next pipelined request, ngx_ssl_next_read_handler() is not
> called, and c->read->ready remains not set. I'll take a look how
> to fix it properly.

Please try the following patch:

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1577129029 -10800
# Mon Dec 23 22:23:49 2019 +0300
# Node ID c2dc6bfd2a0bce28618ef96b87fbdb63c6010575
# Parent 8e64e11aaca02d50649cd2d9b448508f5b268062
SSL: reworked posted next events.

Introduced in 9d2ad2fb4423 available bytes handling in SSL relied
on connection read handler being overwritten to set the ready flag
and the amount of available bytes. This approach is, however, does
not work properly when connection read handler is changed, for example,
when switching to a next pipelined request, and can result in unexpected
connection timeouts, see here:

http://mailman.nginx.org/pipermail/nginx-devel/2019-December/012825.html

Fix is to introduce ngx_event_process_posted_next() instead, which
will set ready and available regardless of how event handler is set.

diff --git a/src/event/ngx_event.c b/src/event/ngx_event.c
--- a/src/event/ngx_event.c
+++ b/src/event/ngx_event.c
@@ -238,8 +238,6 @@ ngx_process_events_and_timers(ngx_cycle_
}

if (!ngx_queue_empty(&ngx_posted_next_events)) {
- ngx_queue_add(&ngx_posted_events, &ngx_posted_next_events);
- ngx_queue_init(&ngx_posted_next_events);
timer = 0;
}

@@ -263,6 +261,7 @@ ngx_process_events_and_timers(ngx_cycle_
}

ngx_event_process_posted(cycle, &ngx_posted_events);
+ ngx_event_process_posted_next(cycle, &ngx_posted_next_events);
}


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
@@ -43,7 +43,6 @@ static ssize_t ngx_ssl_recv_early(ngx_co
#endif
static ngx_int_t ngx_ssl_handle_recv(ngx_connection_t *c, int n);
static void ngx_ssl_write_handler(ngx_event_t *wev);
-static void ngx_ssl_next_read_handler(ngx_event_t *rev);
#ifdef SSL_READ_EARLY_DATA_SUCCESS
static ssize_t ngx_ssl_write_early(ngx_connection_t *c, u_char *data,
size_t size);
@@ -2018,11 +2017,6 @@ ngx_ssl_recv(ngx_connection_t *c, u_char
c->read->available = 0;
c->read->ready = 0;

- if (c->ssl->next_read_handler == NULL) {
- c->ssl->next_read_handler = c->read->handler;
- c->read->handler = ngx_ssl_next_read_handler;
- }
-
ngx_post_event(c->read, &ngx_posted_next_events);
}

@@ -2328,31 +2322,6 @@ ngx_ssl_write_handler(ngx_event_t *wev)
}


-static void
-ngx_ssl_next_read_handler(ngx_event_t *rev)
-{
- ngx_connection_t *c;
-
- c = rev->data;
-
- ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "SSL next read handler");
-
- rev->handler = c->ssl->next_read_handler;
- c->ssl->next_read_handler = NULL;
-
- if (!rev->ready) {
- rev->ready = 1;
- rev->available = -1;
- }
-
- if (rev->posted) {
- ngx_delete_posted_event(rev);
- }
-
- rev->handler(rev);
-}
-
-
/*
* OpenSSL has no SSL_writev() so we copy several bufs into our 16K buffer
* before the SSL_write() call to decrease a SSL overhead.
diff --git a/src/event/ngx_event_openssl.h b/src/event/ngx_event_openssl.h
--- a/src/event/ngx_event_openssl.h
+++ b/src/event/ngx_event_openssl.h
@@ -86,7 +86,6 @@ struct ngx_ssl_connection_s {

ngx_event_handler_pt saved_read_handler;
ngx_event_handler_pt saved_write_handler;
- ngx_event_handler_pt next_read_handler;

u_char early_buf;

diff --git a/src/event/ngx_event_posted.c b/src/event/ngx_event_posted.c
--- a/src/event/ngx_event_posted.c
+++ b/src/event/ngx_event_posted.c
@@ -34,3 +34,29 @@ ngx_event_process_posted(ngx_cycle_t *cy
ev->handler(ev);
}
}
+
+
+void
+ngx_event_process_posted_next(ngx_cycle_t *cycle, ngx_queue_t *posted)
+{
+ ngx_queue_t *q;
+ ngx_event_t *ev;
+
+ while (!ngx_queue_empty(posted)) {
+
+ q = ngx_queue_head(posted);
+ ev = ngx_queue_data(q, ngx_event_t, queue);
+
+ ngx_log_debug1(NGX_LOG_DEBUG_EVENT, cycle->log, 0,
+ "posted next event %p", ev);
+
+ ngx_delete_posted_event(ev);
+
+ if (!ev->ready) {
+ ev->ready = 1;
+ ev->available = -1;
+ }
+
+ ev->handler(ev);
+ }
+}
diff --git a/src/event/ngx_event_posted.h b/src/event/ngx_event_posted.h
--- a/src/event/ngx_event_posted.h
+++ b/src/event/ngx_event_posted.h
@@ -39,6 +39,7 @@


void ngx_event_process_posted(ngx_cycle_t *cycle, ngx_queue_t *posted);
+void ngx_event_process_posted_next(ngx_cycle_t *cycle, ngx_queue_t *posted);


extern ngx_queue_t ngx_posted_accept_events;


--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel