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

> # HG changeset patch
> # User Vladimir Khomutov <vl@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).
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
https://mailman.nginx.org/mailman/listinfo/nginx-devel