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 <v...@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;
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
https://mailman.nginx.org/mailman/listinfo/nginx-devel
