[nginx] QUIC: "handshake_timeout" configuration parameter.

[Vladimir Homutov]

On Fri, Sep 22, 2023 at 03:36:25PM +0000, Roman Arutyunyan wrote:
> details:   https://hg.nginx.org/nginx/rev/ad3d34ddfdcc
> branches:
> changeset: 9158:ad3d34ddfdcc
> user:      Roman Arutyunyan <arut at nginx.com>
> date:      Wed Sep 13 17:59:37 2023 +0400
> description:
> QUIC: "handshake_timeout" configuration parameter.
>
> Previously QUIC did not have such parameter and handshake duration was
> controlled by HTTP/3.  However that required creating and storing HTTP/3
> session on first client datagram.  Apparently there's no convenient way to
> store the session object until QUIC handshake is complete.  In the followup
> patches session creation will be postponed to init() callback.
>

[...]

> diff -r daf8f5ba23d8 -r ad3d34ddfdcc src/event/quic/ngx_event_quic.c
> --- a/src/event/quic/ngx_event_quic.c	Fri Sep 01 20:31:46 2023 +0400
> +++ b/src/event/quic/ngx_event_quic.c	Wed Sep 13 17:59:37 2023 +0400
> @@ -211,6 +211,8 @@ ngx_quic_run(ngx_connection_t *c, ngx_qu
>      qc = ngx_quic_get_connection(c);
>
>      ngx_add_timer(c->read, qc->tp.max_idle_timeout);
> +    ngx_add_timer(&qc->close, qc->conf->handshake_timeout);
> +

It looks like I've hit an issue with early data in such case.
See the attached patch with details.

While there, I suggest a little debug improvement to better track
stream and their parent connections.


-------------- next part --------------
# HG changeset patch
# User Vladimir Khomutov <vl at wbsrv.ru>
# Date 1712576340 -10800
#      Mon Apr 08 14:39:00 2024 +0300
# Node ID 6e79f4ec40ed1c1ffec6a46b453051c01e556610
# Parent  99e7050ac886f7c70a4048691e46846b930b1e28
QUIC: fixed close timer processing with early data.

The ngx_quic_run() function uses qc->close timer to limit the handshake
duration.  Normally it is removed by ngx_quic_do_init_streams() which is
called once when we are done with initial SSL processing.

The problem happens when the client sends early data and streams are
initialized in the ngx_quic_run() -> ngx_quic_handle_datagram() call.
The order of set/remove timer calls is now reversed; the close timer is
set up and the timer fires when assigned, starting the unexpected connection
close process.

The patch moves timer cancelling right before the place where the stream
initialization flag is tested, thus making it work with early data.

The issue was introduced in ad3d34ddfdcc.

diff --git a/src/event/quic/ngx_event_quic_streams.c b/src/event/quic/ngx_event_quic_streams.c
--- a/src/event/quic/ngx_event_quic_streams.c
+++ b/src/event/quic/ngx_event_quic_streams.c
@@ -575,6 +575,10 @@ ngx_quic_init_streams(ngx_connection_t *
 
     qc = ngx_quic_get_connection(c);
 
+    if (!qc->closing && qc->close.timer_set) {
+        ngx_del_timer(&qc->close);
+    }
+
     if (qc->streams.initialized) {
         return NGX_OK;
     }
@@ -630,10 +634,6 @@ ngx_quic_do_init_streams(ngx_connection_
 
     qc->streams.initialized = 1;
 
-    if (!qc->closing && qc->close.timer_set) {
-        ngx_del_timer(&qc->close);
-    }
-
     return NGX_OK;
 }
 
-------------- next part --------------
# HG changeset patch
# User Vladimir Khomutov <vl at wbsrv.ru>
# Date 1712575741 -10800
#      Mon Apr 08 14:29:01 2024 +0300
# Node ID d9b80de50040bb8ac2a7e193971d1dfeb579cfc9
# Parent  6e79f4ec40ed1c1ffec6a46b453051c01e556610
QUIC: added debug logging of stream creation.

Currently, it is hard to associate stream connection number with its parent
connection.  The typical case is to identify QUIC connection number given
some user-visible URI (which occurs in request stream).

The patch adds the debug log message which reports about stream creation in
the stream log and also shows the parent connection number.

diff --git a/src/event/quic/ngx_event_quic_streams.c b/src/event/quic/ngx_event_quic_streams.c
--- a/src/event/quic/ngx_event_quic_streams.c
+++ b/src/event/quic/ngx_event_quic_streams.c
@@ -805,6 +805,10 @@ ngx_quic_create_stream(ngx_connection_t 
 
     ngx_rbtree_insert(&qc->streams.tree, &qs->node);
 
+    ngx_log_debug2(NGX_LOG_DEBUG_EVENT, sc->log, 0,
+                   "quic stream id:0x%xL created in connection *%uA", id,
+                   c->log->connection);
+
     return qs;
 }