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 <vl@wbsrv.ru>
> # 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 = 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;
> @@ -1001,6 +1008,8 @@ ngx_quic_send_retry(ngx_connection_t *c,
>
> res.data = buf;
>
> + ngx_quic_log_packet(c->log, &pkt);
> +
> if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) {
> return NGX_ERROR;
> }
> @@ -1198,13 +1207,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 +1233,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;
>
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
https://mailman.nginx.org/mailman/listinfo/nginx-devel