# HG changeset patch
# User Vladimir Khomutov <vl@wbsrv.ru>
# Date 1698352509 -10800
# Node ID 7ec761f0365f418511e30b82e9adf80bc56681df
# Parent  8b1526a7e383a8fa322ee9f43347ecf9a4298fdb
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 -r 8b1526a7e383 -r 7ec761f0365f src/event/quic/ngx_event_quic_frames.c
--- a/src/event/quic/ngx_event_quic_frames.c	Fri Oct 27 01:29:28 2023 +0400
+++ b/src/event/quic/ngx_event_quic_frames.c	Thu Oct 26 23:35:09 2023 +0300
@@ -886,8 +886,8 @@
         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:%uL %*s",
+                   tx ? "tx" : "rx", ngx_quic_level_name(f->level), f->pnum,
                    p - buf, buf);
 }
 
diff -r 8b1526a7e383 -r 7ec761f0365f src/event/quic/ngx_event_quic_output.c
--- a/src/event/quic/ngx_event_quic_output.c	Fri Oct 27 01:29:28 2023 +0400
+++ b/src/event/quic/ngx_event_quic_output.c	Thu Oct 26 23:35:09 2023 +0300
@@ -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 @@
             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 @@
         len += flen;
         p += flen;
 
-        f->pnum = ctx->pnum;
-        f->first = now;
-        f->last = now;
-        f->plen = 0;
-
         nframes++;
     }
 
@@ -610,11 +619,7 @@
 
     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 @@
     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 @@
 
     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 @@
     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 @@
 
     res.data = dst;
 
+    ngx_quic_log_packet(c->log, &pkt);
+
     if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) {
         return NGX_ERROR;
     }
diff -r 8b1526a7e383 -r 7ec761f0365f src/event/quic/ngx_event_quic_transport.c
--- a/src/event/quic/ngx_event_quic_transport.c	Fri Oct 27 01:29:28 2023 +0400
+++ b/src/event/quic/ngx_event_quic_transport.c	Thu Oct 26 23:35:09 2023 +0300
@@ -1135,6 +1135,9 @@
     }
 
     f->level = pkt->level;
+#if (NGX_DEBUG)
+    f->pnum = pkt->pn;
+#endif
 
     return p - start;