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.
This commit is contained in:
Vladimir Khomutov 2023-10-26 23:35:09 +03:00
parent 1f1bc17ba8
commit a13ed7f5ed
3 changed files with 32 additions and 16 deletions

View File

@ -886,8 +886,8 @@ ngx_quic_log_frame(ngx_log_t *log, ngx_quic_frame_t *f, ngx_uint_t tx)
break; break;
} }
ngx_log_debug4(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s %*s", ngx_log_debug5(NGX_LOG_DEBUG_EVENT, log, 0, "quic frame %s %s:%uL %*s",
tx ? "tx" : "rx", ngx_quic_level_name(f->level), tx ? "tx" : "rx", ngx_quic_level_name(f->level), f->pnum,
p - buf, buf); p - buf, buf);
} }

View File

@ -35,6 +35,15 @@
#define NGX_QUIC_SOCKET_RETRY_DELAY 10 /* ms, for NGX_AGAIN on write */ #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 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_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, 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 *c, ngx_quic_send_ctx_t *ctx,
pkt.need_ack = 1; 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); ngx_quic_log_frame(c->log, f, 1);
flen = ngx_quic_create_frame(p, f); flen = ngx_quic_create_frame(p, f);
@ -588,11 +602,6 @@ ngx_quic_output_packet(ngx_connection_t *c, ngx_quic_send_ctx_t *ctx,
len += flen; len += flen;
p += flen; p += flen;
f->pnum = ctx->pnum;
f->first = now;
f->last = now;
f->plen = 0;
nframes++; nframes++;
} }
@ -610,11 +619,7 @@ ngx_quic_output_packet(ngx_connection_t *c, ngx_quic_send_ctx_t *ctx,
res.data = data; res.data = data;
ngx_log_debug6(NGX_LOG_DEBUG_EVENT, c->log, 0, ngx_quic_log_packet(c->log, &pkt);
"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);
if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) { if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) {
return NGX_ERROR; return NGX_ERROR;
@ -899,13 +904,13 @@ ngx_quic_send_early_cc(ngx_connection_t *c, ngx_quic_header_t *inpkt,
frame.u.close.reason.data = (u_char *) reason; frame.u.close.reason.data = (u_char *) reason;
frame.u.close.reason.len = ngx_strlen(reason); frame.u.close.reason.len = ngx_strlen(reason);
ngx_quic_log_frame(c->log, &frame, 1);
len = ngx_quic_create_frame(NULL, &frame); len = ngx_quic_create_frame(NULL, &frame);
if (len > NGX_QUIC_MAX_UDP_PAYLOAD_SIZE) { if (len > NGX_QUIC_MAX_UDP_PAYLOAD_SIZE) {
return NGX_ERROR; return NGX_ERROR;
} }
ngx_quic_log_frame(c->log, &frame, 1);
len = ngx_quic_create_frame(src, &frame); len = ngx_quic_create_frame(src, &frame);
if (len == -1) { if (len == -1) {
return NGX_ERROR; return NGX_ERROR;
@ -940,6 +945,8 @@ ngx_quic_send_early_cc(ngx_connection_t *c, ngx_quic_header_t *inpkt,
res.data = dst; res.data = dst;
ngx_quic_log_packet(c->log, &pkt);
if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) { if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) {
ngx_quic_keys_cleanup(pkt.keys); ngx_quic_keys_cleanup(pkt.keys);
return NGX_ERROR; return NGX_ERROR;
@ -1198,13 +1205,17 @@ ngx_quic_frame_sendto(ngx_connection_t *c, ngx_quic_frame_t *frame,
pad = 4 - pkt.num_len; pad = 4 - pkt.num_len;
min_payload = ngx_max(min_payload, pad); 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); len = ngx_quic_create_frame(NULL, frame);
if (len > NGX_QUIC_MAX_UDP_PAYLOAD_SIZE) { if (len > NGX_QUIC_MAX_UDP_PAYLOAD_SIZE) {
return NGX_ERROR; return NGX_ERROR;
} }
ngx_quic_log_frame(c->log, frame, 1);
len = ngx_quic_create_frame(src, frame); len = ngx_quic_create_frame(src, frame);
if (len == -1) { if (len == -1) {
return NGX_ERROR; return NGX_ERROR;
@ -1220,6 +1231,8 @@ ngx_quic_frame_sendto(ngx_connection_t *c, ngx_quic_frame_t *frame,
res.data = dst; res.data = dst;
ngx_quic_log_packet(c->log, &pkt);
if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) { if (ngx_quic_encrypt(&pkt, &res) != NGX_OK) {
return NGX_ERROR; return NGX_ERROR;
} }

View File

@ -1135,6 +1135,9 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
} }
f->level = pkt->level; f->level = pkt->level;
#if (NGX_DEBUG)
f->pnum = pkt->pn;
#endif
return p - start; return p - start;