[patch] quic PTO counter fixes

[Sergey Kandaurov]

On Thu, Oct 26, 2023 at 11:37:27PM +0300, Vladimir Homutov wrote:

> # HG changeset patch
> # User Vladimir Khomutov <vl at wbsrv.ru>
> # 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, &pkt);
>  
>      if (ngx_quic_encrypt(&pkt, &res) != 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, &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;
> @@ -940,6 +945,8 @@ ngx_quic_send_early_cc(ngx_connection_t 
>  
>      res.data = dst;
>  
> +    ngx_quic_log_packet(c->log, &pkt);
> +
>      if (ngx_quic_encrypt(&pkt, &res) != 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, &pkt);
> +
>      if (ngx_quic_encrypt(&pkt, &res) != 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 @@ ngx_quic_parse_frame(ngx_quic_header_t *
>      }
>  
>      f->level = pkt->level;
> +#if (NGX_DEBUG)
> +    f->pnum = pkt->pn;
> +#endif
>  
>      return p - start;
>  

Pushed, thanks
(with an obvious fix for f->pnum log format specifier, hope that's ok).