From a13ed7f5ed5bebdc0b9217ffafb75ab69f835a84 Mon Sep 17 00:00:00 2001 From: Vladimir Khomutov Date: Thu, 26 Oct 2023 23:35:09 +0300 Subject: 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. --- src/event/quic/ngx_event_quic_frames.c | 4 +-- src/event/quic/ngx_event_quic_output.c | 41 ++++++++++++++++++++----------- src/event/quic/ngx_event_quic_transport.c | 3 +++ 3 files changed, 32 insertions(+), 16 deletions(-) (limited to 'src') diff --git a/src/event/quic/ngx_event_quic_frames.c b/src/event/quic/ngx_event_quic_frames.c index 7bcfb3211..42b7d9f41 100644 --- 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_quic_frame_t *f, ngx_uint_t tx) 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 --git a/src/event/quic/ngx_event_quic_output.c b/src/event/quic/ngx_event_quic_output.c index dd528a7fe..914d81921 100644 --- 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 *c, ngx_quic_send_ctx_t *ctx, 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 *c, ngx_quic_send_ctx_t *ctx, 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 *c, ngx_quic_send_ctx_t *ctx, 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 *c, ngx_quic_header_t *inpkt, 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 *c, ngx_quic_header_t *inpkt, 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 *c, ngx_quic_frame_t *frame, 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 *c, ngx_quic_frame_t *frame, 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 index 4e0324f4a..19670a6b1 100644 --- 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 *pkt, u_char *start, u_char *end, } f->level = pkt->level; +#if (NGX_DEBUG) + f->pnum = pkt->pn; +#endif return p - start; -- cgit