Re: [patch] quic PTO counter fixes
> On 9 Nov 2023, at 19:14, Vladimir Homutov wrote: > >> On Thu, Oct 26, 2023 at 03:08:55AM +0400, Sergey Kandaurov wrote: >>> # HG changeset patch >>> # User Vladimir Khomutov >>> # Date 1697031803 -10800 >>> # Wed Oct 11 16:43:23 2023 +0300 >>> # Node ID 9ba2840e88f62343b3bd794e43900781dab43686 >>> # Parent 1f188102fbd944df797e8710f70cccee76164add >>> QUIC: fixed handling of PTO counter. >>> >>> The RFC 9002 clearly says in "6.2. Probe Timeout": >>>... >>>As with loss detection, the PTO is per packet number space. >>>That is, a PTO value is computed per packet number space. >>> >>> Despite that, current code is using per-connection PTO counter. >>> For example, this may lead to situation when packet loss at handshake >>> level will affect PTO calculation for initial packets, preventing >>> send of new probes. >> >> Although PTO value is per packet number space, PTO backoff is not, >> see "6.2.1 Computing PTO": >> >> : When ack-eliciting packets in multiple packet number spaces are in flight, >> the >> : timer MUST be set to the earlier value of the Initial and Handshake packet >> : number spaces. > > And I read this fragment as: >- there are multiple timer values (i.e. per packet number space) > (and value is pto * backoff) >- we have to choose the earliest value > > The ngx_quic_pto() has nothing that depends on packet number space > (with the minor exception that we add max_ack_delay at application level > after the handshake) > So pto_count is the only thing that can make timer values to be > different in different packet number spaces. While ngx_quic_pto() doesn't depend on space (except max_ack_delay), it is currently implemented such way that it returns just duration, and it is the caller's obligation to apply it to the time of the last ack-eliciting packet (earliest among spaces) to get pto timeout. This is done in ngx_quic_set_lost_timer() and ngx_quic_pto_handler(), and seemingly missed for path validation in ngx_quic_set_path_timer() and for 3*PTO connection tear down in ngx_quic_close_connection(). Probably ngx_quic_pto() should be refactored to include this "duration => pto_timeout" calculation. This won't even break its signature since it's already passed ctx, which seems to be enough to get the earliest ack-eliciting packet among spaces. > >> >> But: >> >> : When a PTO timer expires, the PTO backoff MUST be increased <..> >> >> : This exponential reduction in the sender's rate is important because >> consecutive >> : PTOs might be caused by loss of packets or acknowledgments due to severe >> : congestion. Even when there are ack-eliciting packets in flight in >> multiple >> : packet number spaces, the exponential increase in PTO occurs across all >> spaces >> : to prevent excess load on the network. For example, a timeout in the >> Initial >> : packet number space doubles the length of the timeout in the Handshake >> packet >> : number space. > > yes, this really looks like contradiction. > At least I don't understand how it is possible to have PTO value > different by packet number space given the way we calculate it. > >> Even if that would be proven otherwise, I don't think the description >> provides detailed explanation. It describes a pretty specific use case, >> when both Initial and Handshake packet number spaces have in-flight packets >> with different PTO timeout (i.e. different f->last). Typically they are >> sent coalesced (e.g. CRYPTO frames for ServerHello and (at least) >> EncryptedExtensions TLS messages). >> In interop tests, though, it might be different: such packets may be >> sent separately, with Handshake packet thus having a later PTO timeout. >> If such, PTO timer will first fire for the Initial packet, then for >> Handshake, >> which will result in PTO backoff accumulated for each packet: >> >> t1: <- Initial (lost) >> t2: <- Handshake (lost) >> t1': pto(t1) timeout >> <- Initial (pto_count=1) >> t2': pto(t2) timeout >> <- Handshake (pto_count=2) >> t1'': pto(t1') timeout >> <- Initial (pto_count=3) >> >> So, I would supplement the description with the phrase that that's >> fair typically with uncoalesced packets seen in interop tests, and >> that the same is true vice verse with packet loss at initial packet >> number space affecting PTO backoff in handshake packet number space. >> >> But see above about PTO backoff increase across all spaces. > > I tend to think that it is better to leave things as is. > maybe RFC needs some better wording in this case. > > I've checked ngtcp2 and msquic and it it looks like both > handle pto counter per-connection too; > (see pto_count in ngtcp2 and QUIC_LOSS_DETECTION.ProbeCount in msquic) > Ok, thanks for deep looking into this. >>> >> >> This part of the change to reset pto_count >> for duplicate ACK or ACK for non-ack-eliciting frame >> contradicts the OnAckReceived example in RFC 9002, >> although I didn't found a format text in the RFC
Re: [patch] quic PTO counter fixes
> On Thu, Oct 26, 2023 at 03:08:55AM +0400, Sergey Kandaurov wrote:
> > # HG changeset patch
> > # User Vladimir Khomutov
> > # Date 1697031803 -10800
> > # Wed Oct 11 16:43:23 2023 +0300
> > # Node ID 9ba2840e88f62343b3bd794e43900781dab43686
> > # Parent 1f188102fbd944df797e8710f70cccee76164add
> > QUIC: fixed handling of PTO counter.
> >
> > The RFC 9002 clearly says in "6.2. Probe Timeout":
> > ...
> > As with loss detection, the PTO is per packet number space.
> > That is, a PTO value is computed per packet number space.
> >
> > Despite that, current code is using per-connection PTO counter.
> > For example, this may lead to situation when packet loss at handshake
> > level will affect PTO calculation for initial packets, preventing
> > send of new probes.
>
> Although PTO value is per packet number space, PTO backoff is not,
> see "6.2.1 Computing PTO":
>
> : When ack-eliciting packets in multiple packet number spaces are in flight,
> the
> : timer MUST be set to the earlier value of the Initial and Handshake packet
> : number spaces.
And I read this fragment as:
- there are multiple timer values (i.e. per packet number space)
(and value is pto * backoff)
- we have to choose the earliest value
The ngx_quic_pto() has nothing that depends on packet number space
(with the minor exception that we add max_ack_delay at application level
after the handshake)
So pto_count is the only thing that can make timer values to be
different in different packet number spaces.
>
> But:
>
> : When a PTO timer expires, the PTO backoff MUST be increased <..>
>
> : This exponential reduction in the sender's rate is important because
> consecutive
> : PTOs might be caused by loss of packets or acknowledgments due to severe
> : congestion. Even when there are ack-eliciting packets in flight in multiple
> : packet number spaces, the exponential increase in PTO occurs across all
> spaces
> : to prevent excess load on the network. For example, a timeout in the
> Initial
> : packet number space doubles the length of the timeout in the Handshake
> packet
> : number space.
yes, this really looks like contradiction.
At least I don't understand how it is possible to have PTO value
different by packet number space given the way we calculate it.
> Even if that would be proven otherwise, I don't think the description
> provides detailed explanation. It describes a pretty specific use case,
> when both Initial and Handshake packet number spaces have in-flight packets
> with different PTO timeout (i.e. different f->last). Typically they are
> sent coalesced (e.g. CRYPTO frames for ServerHello and (at least)
> EncryptedExtensions TLS messages).
> In interop tests, though, it might be different: such packets may be
> sent separately, with Handshake packet thus having a later PTO timeout.
> If such, PTO timer will first fire for the Initial packet, then for Handshake,
> which will result in PTO backoff accumulated for each packet:
>
> t1: <- Initial (lost)
> t2: <- Handshake (lost)
> t1': pto(t1) timeout
> <- Initial (pto_count=1)
> t2': pto(t2) timeout
> <- Handshake (pto_count=2)
> t1'': pto(t1') timeout
> <- Initial (pto_count=3)
>
> So, I would supplement the description with the phrase that that's
> fair typically with uncoalesced packets seen in interop tests, and
> that the same is true vice verse with packet loss at initial packet
> number space affecting PTO backoff in handshake packet number space.
>
> But see above about PTO backoff increase across all spaces.
I tend to think that it is better to leave things as is.
maybe RFC needs some better wording in this case.
I've checked ngtcp2 and msquic and it it looks like both
handle pto counter per-connection too;
(see pto_count in ngtcp2 and QUIC_LOSS_DETECTION.ProbeCount in msquic)
> > Additionally, one case of successful ACK receiving was missing:
> > PING frames are not stored in the ctx->sent queue, thus PTO was not
> > reset when corresponding packets were acknowledged.
>
> See below.
>
> >
> > diff --git a/src/event/quic/ngx_event_quic.c
> > b/src/event/quic/ngx_event_quic.c
> > --- a/src/event/quic/ngx_event_quic.c
> > +++ b/src/event/quic/ngx_event_quic.c
> > @@ -1088,8 +1088,6 @@ ngx_quic_discard_ctx(ngx_connection_t *c
> >
> > ngx_quic_keys_discard(qc->keys, level);
> >
> > -qc->pto_count = 0;
> > -
> > ctx = ngx_quic_get_send_ctx(qc, level);
> >
> > ngx_quic_free_buffer(c, >crypto);
> > @@ -1120,6 +1118,7 @@ ngx_quic_discard_ctx(ngx_connection_t *c
> > }
> >
> > ctx->send_ack = 0;
> > +ctx->pto_count = 0;
> >
> > ngx_quic_set_lost_timer(c);
> > }
> > diff --git a/src/event/quic/ngx_event_quic_ack.c
> > b/src/event/quic/ngx_event_quic_ack.c
> > --- a/src/event/quic/ngx_event_quic_ack.c
> > +++ b/src/event/quic/ngx_event_quic_ack.c
> > @@ -286,8 +286,12 @@ ngx_quic_handle_ack_frame_range(ngx_conn
> > if (!found) {
> >
> > if (max < ctx->pnum) {
> > -
Re: [patch] quic PTO counter fixes
On Thu, Oct 26, 2023 at 11:37:27PM +0300, Vladimir Homutov wrote:
> # HG changeset patch
> # User Vladimir Khomutov
> # Date 1698352509 -10800
> # Thu Oct 26 23:35:09 2023 +0300
> # Node ID d62960a9e75f07a1d260cf7aaad965f56a9520c2
> # Parent 25a2efd97a3e21d106ce4547a763b77eb9c732ad
> QUIC: improved packet and frames debug tracing.
>
> Currently, packets generated by ngx_quic_frame_sendto() and
> ngx_quic_send_early_cc() are not logged, thus making it hard
> to read logs due to gaps appearing in packet numbers sequence.
>
> At frames level, it is handy to see immediately packet number
> in which they arrived or being sent.
>
> diff --git a/src/event/quic/ngx_event_quic_frames.c
> b/src/event/quic/ngx_event_quic_frames.c
> --- a/src/event/quic/ngx_event_quic_frames.c
> +++ b/src/event/quic/ngx_event_quic_frames.c
> @@ -886,8 +886,8 @@ ngx_quic_log_frame(ngx_log_t *log, ngx_q
> break;
> }
>
> -ngx_log_debug4(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s %*s",
> - tx ? "tx" : "rx", ngx_quic_level_name(f->level),
> +ngx_log_debug5(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s:%ui %*s",
> + tx ? "tx" : "rx", ngx_quic_level_name(f->level), f->pnum,
> p - buf, buf);
> }
>
> diff --git a/src/event/quic/ngx_event_quic_output.c
> b/src/event/quic/ngx_event_quic_output.c
> --- a/src/event/quic/ngx_event_quic_output.c
> +++ b/src/event/quic/ngx_event_quic_output.c
> @@ -35,6 +35,15 @@
> #define NGX_QUIC_SOCKET_RETRY_DELAY 10 /* ms, for NGX_AGAIN on write */
>
>
> +#define ngx_quic_log_packet(log, pkt)
> \
> +ngx_log_debug6(NGX_LOG_DEBUG_EVENT, log, 0,
> \
> + "quic packet tx %s bytes:%ui need_ack:%d"
> \
> + " number:%L encoded nl:%d trunc:0x%xD",
> \
> + ngx_quic_level_name((pkt)->level), (pkt)->payload.len,
> \
> + (pkt)->need_ack, (pkt)->number, (pkt)->num_len,
> \
> +(pkt)->trunc);
> +
> +
> static ngx_int_t ngx_quic_create_datagrams(ngx_connection_t *c);
> static void ngx_quic_commit_send(ngx_connection_t *c, ngx_quic_send_ctx_t
> *ctx);
> static void ngx_quic_revert_send(ngx_connection_t *c, ngx_quic_send_ctx_t
> *ctx,
> @@ -578,6 +587,11 @@ ngx_quic_output_packet(ngx_connection_t
> pkt.need_ack = 1;
> }
>
> +f->pnum = ctx->pnum;
> +f->first = now;
> +f->last = now;
> +f->plen = 0;
> +
> ngx_quic_log_frame(c->log, f, 1);
>
> flen = ngx_quic_create_frame(p, f);
> @@ -588,11 +602,6 @@ ngx_quic_output_packet(ngx_connection_t
> len += flen;
> p += flen;
>
> -f->pnum = ctx->pnum;
> -f->first = now;
> -f->last = now;
> -f->plen = 0;
> -
> nframes++;
> }
>
> @@ -610,11 +619,7 @@ ngx_quic_output_packet(ngx_connection_t
>
> res.data = data;
>
> -ngx_log_debug6(NGX_LOG_DEBUG_EVENT, c->log, 0,
> - "quic packet tx %s bytes:%ui"
> - " need_ack:%d number:%L encoded nl:%d trunc:0x%xD",
> - ngx_quic_level_name(ctx->level), pkt.payload.len,
> - pkt.need_ack, pkt.number, pkt.num_len, pkt.trunc);
> +ngx_quic_log_packet(c->log, );
>
> if (ngx_quic_encrypt(, ) != NGX_OK) {
> return NGX_ERROR;
> @@ -899,13 +904,13 @@ ngx_quic_send_early_cc(ngx_connection_t
> frame.u.close.reason.data = (u_char *) reason;
> frame.u.close.reason.len = ngx_strlen(reason);
>
> +ngx_quic_log_frame(c->log, , 1);
> +
> len = ngx_quic_create_frame(NULL, );
> if (len > NGX_QUIC_MAX_UDP_PAYLOAD_SIZE) {
> return NGX_ERROR;
> }
>
> -ngx_quic_log_frame(c->log, , 1);
> -
> len = ngx_quic_create_frame(src, );
> if (len == -1) {
> return NGX_ERROR;
> @@ -940,6 +945,8 @@ ngx_quic_send_early_cc(ngx_connection_t
>
> res.data = dst;
>
> +ngx_quic_log_packet(c->log, );
> +
> if (ngx_quic_encrypt(, ) != NGX_OK) {
> ngx_quic_keys_cleanup(pkt.keys);
> return NGX_ERROR;
> @@ -1198,13 +1205,17 @@ ngx_quic_frame_sendto(ngx_connection_t *
> pad = 4 - pkt.num_len;
> min_payload = ngx_max(min_payload, pad);
>
> +#if (NGX_DEBUG)
> +frame->pnum = pkt.number;
> +#endif
> +
> +ngx_quic_log_frame(c->log, frame, 1);
> +
> len = ngx_quic_create_frame(NULL, frame);
> if (len > NGX_QUIC_MAX_UDP_PAYLOAD_SIZE) {
> return NGX_ERROR;
> }
>
> -ngx_quic_log_frame(c->log, frame, 1);
> -
> len = ngx_quic_create_frame(src, frame);
> if (len == -1) {
> return NGX_ERROR;
> @@ -1220,6 +1231,8 @@ ngx_quic_frame_sendto(ngx_connection_t *
>
> res.data = dst;
>
> +ngx_quic_log_packet(c->log, );
> +
> if (ngx_quic_encrypt(, ) != NGX_OK) {
>
Re: [patch] quic PTO counter fixes
On Fri, Oct 27, 2023 at 12:27:22AM +0400, Sergey Kandaurov wrote:
> On Thu, Oct 26, 2023 at 05:20:39PM +0300, Vladimir Homutov wrote:
> > On Thu, Oct 26, 2023 at 03:08:55AM +0400, Sergey Kandaurov wrote:
> > > On Wed, Oct 11, 2023 at 04:58:47PM +0300, Vladimir Homutov via
> > > nginx-devel wrote:
> > [..]
> >
> > > > diff --git a/src/event/quic/ngx_event_quic_output.c
> > > > b/src/event/quic/ngx_event_quic_output.c
> > > > --- a/src/event/quic/ngx_event_quic_output.c
> > > > +++ b/src/event/quic/ngx_event_quic_output.c
> > > > @@ -563,8 +563,6 @@ ngx_quic_output_packet(ngx_connection_t
> > > > pkt.need_ack = 1;
> > > > }
> > > >
> > > > -ngx_quic_log_frame(c->log, f, 1);
> > > > -
> > > > flen = ngx_quic_create_frame(p, f);
> > > > if (flen == -1) {
> > > > return NGX_ERROR;
> > > > @@ -578,6 +576,8 @@ ngx_quic_output_packet(ngx_connection_t
> > > > f->last = now;
> > > > f->plen = 0;
> > > >
> > > > +ngx_quic_log_frame(c->log, f, 1);
> > > > +
> > > > nframes++;
> > >
> > > I'd rather move setting frame fields before calling
> > > ngx_quic_log_frame()/ngx_quic_create_frame()
> > > to preserve consistency with other places, i.e.:
> > > - set fields
> > > - log frame
> > > - create frame
> > >
> > > To look as follows:
> > >
> > > :f->pnum = ctx->pnum;
> > > :f->first = now;
> > > :f->last = now;
> > > :f->plen = 0;
> > > :
> > > :ngx_quic_log_frame(c->log, f, 1);
> > > :
> > > :flen = ngx_quic_create_frame(p, f);
> > > :
> >
> > agreed
> >
> > > > }
> > > >
> > > > @@ -925,6 +925,13 @@ ngx_quic_send_early_cc(ngx_connection_t
> > > >
> > > > res.data = dst;
> > > >
> > > > +ngx_log_debug7(NGX_LOG_DEBUG_EVENT, c->log, 0,
> > > > + "quic packet tx %s bytes:%ui need_ack:%d"
> > > > + " number:%L encoded nl:%d trunc:0x%xD frame:%ui]",
> > >
> > > typo: closing square bracket
> >
> > thanks, removed
> >
> > > Not sure we need logging for a (particular) frame in packet logging,
> > > not to say that it looks like a layering violation.
> > > Anyway, it is logged nearby, for example:
> > >
> > > quic frame tx init:0 CONNECTION_CLOSE err:11 invalid address validation
> > > token ft:0
> > > quic packet tx init bytes:36 need_ack:0 number:0 encoded nl:1 trunc:0x0
> > >
> > > So I'd remove this part.
> >
> > agreed, frame logging removed
> >
> > > > + ngx_quic_level_name(pkt.level), pkt.payload.len,
> > > > + pkt.need_ack, pkt.number, pkt.num_len, pkt.trunc,
> > > > + frame->type);
> > > > +
> > >
> > > BTW, it would make sense to get a new macro / inline function
> > > for packet tx logging, similar to ngx_quic_log_frame(),
> > > since we will have three places with identical ngx_log_debug7().
> >
> > actually, four (we have also retry), so having a macro is a good idea
> >
> > updated patch attached
>
> Well, I don't think retry needs logging, because this is not a real
> packet, it carries a token and is used to construct a Retry packet
> (which is also a special packet) later in ngx_quic_encrypt().
> Logging such a construct is bogus, because nearly all fields aren't
> initialized to sensible values, personally I've got the following:
>
> quic packet tx init bytes:0 need_ack:0 number:0 encoded nl:0 trunc:0x0
yes, this makes sense, removed.
# HG changeset patch
# User Vladimir Khomutov
# Date 1698352509 -10800
# Thu Oct 26 23:35:09 2023 +0300
# Node ID d62960a9e75f07a1d260cf7aaad965f56a9520c2
# Parent 25a2efd97a3e21d106ce4547a763b77eb9c732ad
QUIC: improved packet and frames debug tracing.
Currently, packets generated by ngx_quic_frame_sendto() and
ngx_quic_send_early_cc() are not logged, thus making it hard
to read logs due to gaps appearing in packet numbers sequence.
At frames level, it is handy to see immediately packet number
in which they arrived or being sent.
diff --git a/src/event/quic/ngx_event_quic_frames.c b/src/event/quic/ngx_event_quic_frames.c
--- a/src/event/quic/ngx_event_quic_frames.c
+++ b/src/event/quic/ngx_event_quic_frames.c
@@ -886,8 +886,8 @@ ngx_quic_log_frame(ngx_log_t *log, ngx_q
break;
}
-ngx_log_debug4(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s %*s",
- tx ? "tx" : "rx", ngx_quic_level_name(f->level),
+ngx_log_debug5(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s:%ui %*s",
+ tx ? "tx" : "rx", ngx_quic_level_name(f->level), f->pnum,
p - buf, buf);
}
diff --git a/src/event/quic/ngx_event_quic_output.c b/src/event/quic/ngx_event_quic_output.c
--- a/src/event/quic/ngx_event_quic_output.c
+++ b/src/event/quic/ngx_event_quic_output.c
@@ -35,6 +35,15 @@
#define NGX_QUIC_SOCKET_RETRY_DELAY 10 /* ms, for NGX_AGAIN on write */
+#define ngx_quic_log_packet(log, pkt) \
+
Re: [patch] quic PTO counter fixes
On Thu, Oct 26, 2023 at 05:20:39PM +0300, Vladimir Homutov wrote:
> On Thu, Oct 26, 2023 at 03:08:55AM +0400, Sergey Kandaurov wrote:
> > On Wed, Oct 11, 2023 at 04:58:47PM +0300, Vladimir Homutov via nginx-devel
> > wrote:
> [..]
>
> > > diff --git a/src/event/quic/ngx_event_quic_output.c
> > > b/src/event/quic/ngx_event_quic_output.c
> > > --- a/src/event/quic/ngx_event_quic_output.c
> > > +++ b/src/event/quic/ngx_event_quic_output.c
> > > @@ -563,8 +563,6 @@ ngx_quic_output_packet(ngx_connection_t
> > > pkt.need_ack = 1;
> > > }
> > >
> > > -ngx_quic_log_frame(c->log, f, 1);
> > > -
> > > flen = ngx_quic_create_frame(p, f);
> > > if (flen == -1) {
> > > return NGX_ERROR;
> > > @@ -578,6 +576,8 @@ ngx_quic_output_packet(ngx_connection_t
> > > f->last = now;
> > > f->plen = 0;
> > >
> > > +ngx_quic_log_frame(c->log, f, 1);
> > > +
> > > nframes++;
> >
> > I'd rather move setting frame fields before calling
> > ngx_quic_log_frame()/ngx_quic_create_frame()
> > to preserve consistency with other places, i.e.:
> > - set fields
> > - log frame
> > - create frame
> >
> > To look as follows:
> >
> > :f->pnum = ctx->pnum;
> > :f->first = now;
> > :f->last = now;
> > :f->plen = 0;
> > :
> > :ngx_quic_log_frame(c->log, f, 1);
> > :
> > :flen = ngx_quic_create_frame(p, f);
> > :
>
> agreed
>
> > > }
> > >
> > > @@ -925,6 +925,13 @@ ngx_quic_send_early_cc(ngx_connection_t
> > >
> > > res.data = dst;
> > >
> > > +ngx_log_debug7(NGX_LOG_DEBUG_EVENT, c->log, 0,
> > > + "quic packet tx %s bytes:%ui need_ack:%d"
> > > + " number:%L encoded nl:%d trunc:0x%xD frame:%ui]",
> >
> > typo: closing square bracket
>
> thanks, removed
>
> > Not sure we need logging for a (particular) frame in packet logging,
> > not to say that it looks like a layering violation.
> > Anyway, it is logged nearby, for example:
> >
> > quic frame tx init:0 CONNECTION_CLOSE err:11 invalid address validation
> > token ft:0
> > quic packet tx init bytes:36 need_ack:0 number:0 encoded nl:1 trunc:0x0
> >
> > So I'd remove this part.
>
> agreed, frame logging removed
>
> > > + ngx_quic_level_name(pkt.level), pkt.payload.len,
> > > + pkt.need_ack, pkt.number, pkt.num_len, pkt.trunc,
> > > + frame->type);
> > > +
> >
> > BTW, it would make sense to get a new macro / inline function
> > for packet tx logging, similar to ngx_quic_log_frame(),
> > since we will have three places with identical ngx_log_debug7().
>
> actually, four (we have also retry), so having a macro is a good idea
>
> updated patch attached
Well, I don't think retry needs logging, because this is not a real
packet, it carries a token and is used to construct a Retry packet
(which is also a special packet) later in ngx_quic_encrypt().
Logging such a construct is bogus, because nearly all fields aren't
initialized to sensible values, personally I've got the following:
quic packet tx init bytes:0 need_ack:0 number:0 encoded nl:0 trunc:0x0
Otherwise, it looks good.
> # HG changeset patch
> # User Vladimir Khomutov
> # Date 1698329226 -10800
> # Thu Oct 26 17:07:06 2023 +0300
> # Node ID b8cdb9518f877fb3ed6386731df1e263eeae8e7c
> # Parent 25a2efd97a3e21d106ce4547a763b77eb9c732ad
> QUIC: improved packet and frames debug tracing.
>
> Currently, packets generated by ngx_quic_frame_sendto() and
> ngx_quic_send_early_cc() are not logged, thus making it hard
> to read logs due to gaps appearing in packet numbers sequence.
>
> At frames level, it is handy to see immediately packet number
> in which they arrived or being sent.
>
> diff --git a/src/event/quic/ngx_event_quic_frames.c
> b/src/event/quic/ngx_event_quic_frames.c
> --- a/src/event/quic/ngx_event_quic_frames.c
> +++ b/src/event/quic/ngx_event_quic_frames.c
> @@ -886,8 +886,8 @@ ngx_quic_log_frame(ngx_log_t *log, ngx_q
> break;
> }
>
> -ngx_log_debug4(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s %*s",
> - tx ? "tx" : "rx", ngx_quic_level_name(f->level),
> +ngx_log_debug5(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s:%ui %*s",
> + tx ? "tx" : "rx", ngx_quic_level_name(f->level), f->pnum,
> p - buf, buf);
> }
>
> diff --git a/src/event/quic/ngx_event_quic_output.c
> b/src/event/quic/ngx_event_quic_output.c
> --- a/src/event/quic/ngx_event_quic_output.c
> +++ b/src/event/quic/ngx_event_quic_output.c
> @@ -35,6 +35,15 @@
> #define NGX_QUIC_SOCKET_RETRY_DELAY 10 /* ms, for NGX_AGAIN on write */
>
>
> +#define ngx_quic_log_packet(log, pkt)
> \
> +ngx_log_debug6(NGX_LOG_DEBUG_EVENT, log, 0,
> \
> + "quic packet tx %s bytes:%ui need_ack:%d"
> \
> + "
Re: [patch] quic PTO counter fixes
On Thu, Oct 26, 2023 at 03:08:55AM +0400, Sergey Kandaurov wrote:
> On Wed, Oct 11, 2023 at 04:58:47PM +0300, Vladimir Homutov via nginx-devel
> wrote:
[..]
> > diff --git a/src/event/quic/ngx_event_quic_output.c
> > b/src/event/quic/ngx_event_quic_output.c
> > --- a/src/event/quic/ngx_event_quic_output.c
> > +++ b/src/event/quic/ngx_event_quic_output.c
> > @@ -563,8 +563,6 @@ ngx_quic_output_packet(ngx_connection_t
> > pkt.need_ack = 1;
> > }
> >
> > -ngx_quic_log_frame(c->log, f, 1);
> > -
> > flen = ngx_quic_create_frame(p, f);
> > if (flen == -1) {
> > return NGX_ERROR;
> > @@ -578,6 +576,8 @@ ngx_quic_output_packet(ngx_connection_t
> > f->last = now;
> > f->plen = 0;
> >
> > +ngx_quic_log_frame(c->log, f, 1);
> > +
> > nframes++;
>
> I'd rather move setting frame fields before calling
> ngx_quic_log_frame()/ngx_quic_create_frame()
> to preserve consistency with other places, i.e.:
> - set fields
> - log frame
> - create frame
>
> To look as follows:
>
> :f->pnum = ctx->pnum;
> :f->first = now;
> :f->last = now;
> :f->plen = 0;
> :
> :ngx_quic_log_frame(c->log, f, 1);
> :
> :flen = ngx_quic_create_frame(p, f);
> :
agreed
> > }
> >
> > @@ -925,6 +925,13 @@ ngx_quic_send_early_cc(ngx_connection_t
> >
> > res.data = dst;
> >
> > +ngx_log_debug7(NGX_LOG_DEBUG_EVENT, c->log, 0,
> > + "quic packet tx %s bytes:%ui need_ack:%d"
> > + " number:%L encoded nl:%d trunc:0x%xD frame:%ui]",
>
> typo: closing square bracket
thanks, removed
> Not sure we need logging for a (particular) frame in packet logging,
> not to say that it looks like a layering violation.
> Anyway, it is logged nearby, for example:
>
> quic frame tx init:0 CONNECTION_CLOSE err:11 invalid address validation
> token ft:0
> quic packet tx init bytes:36 need_ack:0 number:0 encoded nl:1 trunc:0x0
>
> So I'd remove this part.
agreed, frame logging removed
> > + ngx_quic_level_name(pkt.level), pkt.payload.len,
> > + pkt.need_ack, pkt.number, pkt.num_len, pkt.trunc,
> > + frame->type);
> > +
>
> BTW, it would make sense to get a new macro / inline function
> for packet tx logging, similar to ngx_quic_log_frame(),
> since we will have three places with identical ngx_log_debug7().
actually, four (we have also retry), so having a macro is a good idea
updated patch attached
# HG changeset patch
# User Vladimir Khomutov
# Date 1698329226 -10800
# Thu Oct 26 17:07:06 2023 +0300
# Node ID b8cdb9518f877fb3ed6386731df1e263eeae8e7c
# Parent 25a2efd97a3e21d106ce4547a763b77eb9c732ad
QUIC: improved packet and frames debug tracing.
Currently, packets generated by ngx_quic_frame_sendto() and
ngx_quic_send_early_cc() are not logged, thus making it hard
to read logs due to gaps appearing in packet numbers sequence.
At frames level, it is handy to see immediately packet number
in which they arrived or being sent.
diff --git a/src/event/quic/ngx_event_quic_frames.c b/src/event/quic/ngx_event_quic_frames.c
--- a/src/event/quic/ngx_event_quic_frames.c
+++ b/src/event/quic/ngx_event_quic_frames.c
@@ -886,8 +886,8 @@ ngx_quic_log_frame(ngx_log_t *log, ngx_q
break;
}
-ngx_log_debug4(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s %*s",
- tx ? "tx" : "rx", ngx_quic_level_name(f->level),
+ngx_log_debug5(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s:%ui %*s",
+ tx ? "tx" : "rx", ngx_quic_level_name(f->level), f->pnum,
p - buf, buf);
}
diff --git a/src/event/quic/ngx_event_quic_output.c b/src/event/quic/ngx_event_quic_output.c
--- a/src/event/quic/ngx_event_quic_output.c
+++ b/src/event/quic/ngx_event_quic_output.c
@@ -35,6 +35,15 @@
#define NGX_QUIC_SOCKET_RETRY_DELAY 10 /* ms, for NGX_AGAIN on write */
+#define ngx_quic_log_packet(log, pkt) \
+ngx_log_debug6(NGX_LOG_DEBUG_EVENT, log, 0, \
+ "quic packet tx %s bytes:%ui need_ack:%d" \
+ " number:%L encoded nl:%d trunc:0x%xD",\
+ ngx_quic_level_name((pkt)->level), (pkt)->payload.len, \
+ (pkt)->need_ack, (pkt)->number, (pkt)->num_len,\
+(pkt)->trunc);
+
+
static ngx_int_t ngx_quic_create_datagrams(ngx_connection_t *c);
static void ngx_quic_commit_send(ngx_connection_t *c, ngx_quic_send_ctx_t *ctx);
static void ngx_quic_revert_send(ngx_connection_t *c, ngx_quic_send_ctx_t *ctx,
@@ -578,6 +587,11 @@ ngx_quic_output_packet(ngx_connection_t
pkt.need_ack = 1;
}
+f->pnum = ctx->pnum;
+f->first = now;
+f->last = now;
+f->plen = 0;
+
ngx_quic_log_frame(c->log, f, 1);
flen =
Re: [patch] quic PTO counter fixes
On Wed, Oct 11, 2023 at 04:58:47PM +0300, Vladimir Homutov via nginx-devel
wrote:
> Hello,
>
> a couple of patches in the quic code:
>
> first patch improves a bit debugging, and the second patch contains
> fixes for PTO counter calculation - see commit log for details.
>
> This helps with some clients in interop handshakeloss/handshakecorruption
> testcases
>
>
> # HG changeset patch
> # User Vladimir Khomutov
> # Date 1697031939 -10800
> # Wed Oct 11 16:45:39 2023 +0300
> # Node ID 1f188102fbd944df797e8710f70cccee76164add
> # Parent cdda286c0f1b4b10f30d4eb6a63fefb9b8708ecc
> QUIC: improved packet and frames debug tracing.
>
> Currently, packets generated by ngx_quic_frame_sendto() and
> ngx_quic_send_early_cc() are not logged, thus making it hard
> to read logs due to gaps appearing in packet numbers sequence.
> For such special packets, a frame type being sent is also output.
>
> At frames level, it is handy to see immediately packet number
> in which they arrived or being sent.
>
> diff --git a/src/event/quic/ngx_event_quic_frames.c
> b/src/event/quic/ngx_event_quic_frames.c
> --- a/src/event/quic/ngx_event_quic_frames.c
> +++ b/src/event/quic/ngx_event_quic_frames.c
> @@ -886,8 +886,8 @@ ngx_quic_log_frame(ngx_log_t *log, ngx_q
> break;
> }
>
> -ngx_log_debug4(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s %*s",
> - tx ? "tx" : "rx", ngx_quic_level_name(f->level),
> +ngx_log_debug5(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s:%ui %*s",
> + tx ? "tx" : "rx", ngx_quic_level_name(f->level), f->pnum,
> p - buf, buf);
> }
>
> diff --git a/src/event/quic/ngx_event_quic_output.c
> b/src/event/quic/ngx_event_quic_output.c
> --- a/src/event/quic/ngx_event_quic_output.c
> +++ b/src/event/quic/ngx_event_quic_output.c
> @@ -563,8 +563,6 @@ ngx_quic_output_packet(ngx_connection_t
> pkt.need_ack = 1;
> }
>
> -ngx_quic_log_frame(c->log, f, 1);
> -
> flen = ngx_quic_create_frame(p, f);
> if (flen == -1) {
> return NGX_ERROR;
> @@ -578,6 +576,8 @@ ngx_quic_output_packet(ngx_connection_t
> f->last = now;
> f->plen = 0;
>
> +ngx_quic_log_frame(c->log, f, 1);
> +
> nframes++;
I'd rather move setting frame fields before calling
ngx_quic_log_frame()/ngx_quic_create_frame()
to preserve consistency with other places, i.e.:
- set fields
- log frame
- create frame
To look as follows:
:f->pnum = ctx->pnum;
:f->first = now;
:f->last = now;
:f->plen = 0;
:
:ngx_quic_log_frame(c->log, f, 1);
:
:flen = ngx_quic_create_frame(p, f);
:
> }
>
> @@ -925,6 +925,13 @@ ngx_quic_send_early_cc(ngx_connection_t
>
> res.data = dst;
>
> +ngx_log_debug7(NGX_LOG_DEBUG_EVENT, c->log, 0,
> + "quic packet tx %s bytes:%ui need_ack:%d"
> + " number:%L encoded nl:%d trunc:0x%xD frame:%ui]",
typo: closing square bracket
Not sure we need logging for a (particular) frame in packet logging,
not to say that it looks like a layering violation.
Anyway, it is logged nearby, for example:
quic frame tx init:0 CONNECTION_CLOSE err:11 invalid address validation token
ft:0
quic packet tx init bytes:36 need_ack:0 number:0 encoded nl:1 trunc:0x0
So I'd remove this part.
> + ngx_quic_level_name(pkt.level), pkt.payload.len,
> + pkt.need_ack, pkt.number, pkt.num_len, pkt.trunc,
> + frame.type);
> +
> if (ngx_quic_encrypt(, ) != NGX_OK) {
> return NGX_ERROR;
> }
> @@ -1179,6 +1186,10 @@ ngx_quic_frame_sendto(ngx_connection_t *
> pad = 4 - pkt.num_len;
> min_payload = ngx_max(min_payload, pad);
>
> +#if (NGX_DEBUG)
> +frame->pnum = pkt.number;
> +#endif
> +
> len = ngx_quic_create_frame(NULL, frame);
> if (len > NGX_QUIC_MAX_UDP_PAYLOAD_SIZE) {
> return NGX_ERROR;
> @@ -1201,6 +1212,13 @@ ngx_quic_frame_sendto(ngx_connection_t *
>
> res.data = dst;
>
> +ngx_log_debug7(NGX_LOG_DEBUG_EVENT, c->log, 0,
> + "quic packet tx %s bytes:%ui need_ack:%d"
> + " number:%L encoded nl:%d trunc:0x%xD frame:%ui",
Same here.
> + ngx_quic_level_name(pkt.level), pkt.payload.len,
> + pkt.need_ack, pkt.number, pkt.num_len, pkt.trunc,
> + frame->type);
> +
BTW, it would make sense to get a new macro / inline function
for packet tx logging, similar to ngx_quic_log_frame(),
since we will have three places with identical ngx_log_debug7().
> if (ngx_quic_encrypt(, ) != NGX_OK) {
> return NGX_ERROR;
> }
> diff --git a/src/event/quic/ngx_event_quic_transport.c
> b/src/event/quic/ngx_event_quic_transport.c
> --- a/src/event/quic/ngx_event_quic_transport.c
> +++ b/src/event/quic/ngx_event_quic_transport.c
> @@ -1135,6 +1135,9 @@
Re: [patch] quic PTO counter fixes
Unsubscribe On Wed, 11 Oct 2023 at 13:59, Vladimir Homutov via nginx-devel < nginx-devel@nginx.org> wrote: > Hello, > > a couple of patches in the quic code: > > first patch improves a bit debugging, and the second patch contains > fixes for PTO counter calculation - see commit log for details. > > This helps with some clients in interop handshakeloss/handshakecorruption > testcases > > > ___ > nginx-devel mailing list > nginx-devel@nginx.org > https://mailman.nginx.org/mailman/listinfo/nginx-devel > ___ nginx-devel mailing list nginx-devel@nginx.org https://mailman.nginx.org/mailman/listinfo/nginx-devel
