MINOR: quic: Traces adjustments at proto level.

Dump variables displayed by TRACE_ENTER() or TRACE_LEAVE() by calls to TRACE_PROTO().
No more variables are displayed by the two former macros. For now on, these information
are accessible from proto level.
Add new calls to TRACE_PROTO() at important locations in relation whith QUIC transport
protocol.
When relevant, try to prefix such traces with TX or RX keyword to identify the
concerned subpart (transmission or reception) of the protocol.

Must be backported to 2.7.

diff --git a/include/haproxy/quic_tp.h b/include/haproxy/quic_tp.h
index 16296e5f8a8f59cda5084ce07c7628dd7b0e182e..c5959dfffe016329e1c87163ff9598361eac00be 100644 (file)
--- a/include/haproxy/quic_tp.h
+++ b/include/haproxy/quic_tp.h
@@ -59,7 +59,7 @@ static inline void quic_tp_version_info_dump(struct buffer *b,
                                chunk_appendf(b, "0x%08x", ntohl(*ver));
                }
        }
-       chunk_appendf(b, ")\n");
+       chunk_appendf(b, ")");
 }
 
 static inline void quic_transport_params_dump(struct buffer *b,
@@ -119,7 +119,7 @@ static inline void quic_transport_params_dump(struct buffer *b,
                        prev = 1;
                        chunk_appendf(b, "pref_addr");
                }
-               chunk_appendf(b, ")\n");
+               chunk_appendf(b, ")");
        }
 
        quic_tp_version_info_dump(b, &p->version_information, local);

diff --git a/src/quic_cc_cubic.c b/src/quic_cc_cubic.c
index 0654e42cec318bab673db1555fd78d7a11070585..6e829dd2dcc87f1c74555b3fe2e2cd786ce3f04b 100644 (file)
--- a/src/quic_cc_cubic.c
+++ b/src/quic_cc_cubic.c
@@ -1,5 +1,6 @@
-#include <haproxy/trace.h>
 #include <haproxy/quic_cc.h>
+#include <haproxy/ticks.h>
+#include <haproxy/trace.h>
 
 /* This source file is highly inspired from Linux kernel source file
  * implementation for TCP Cubic. In fact, we have no choice if we do
@@ -198,7 +199,8 @@ static void quic_cc_cubic_ss_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        struct quic_path *path = container_of(cc, struct quic_path, cc);
        struct cubic *c = quic_cc_priv(cc);
 
-       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc, ev);
+       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc);
+       TRACE_PROTO("CC cubic", QUIC_EV_CONN_CC, cc->qc, ev);
        switch (ev->type) {
        case QUIC_CC_EVT_ACK:
                path->cwnd += ev->ack.acked;
@@ -219,13 +221,15 @@ static void quic_cc_cubic_ss_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        }
 
  out:
-       TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc, NULL, cc);
+       TRACE_PROTO("CC cubic", QUIC_EV_CONN_CC, cc->qc, NULL, cc);
+       TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc);
 }
 
 /* Congestion avoidance callback. */
 static void quic_cc_cubic_ca_cb(struct quic_cc *cc, struct quic_cc_event *ev)
 {
-       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc, ev);
+       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc);
+       TRACE_PROTO("CC cubic", QUIC_EV_CONN_CC, cc->qc, ev);
        switch (ev->type) {
        case QUIC_CC_EVT_ACK:
                quic_cubic_update(cc, ev->ack.acked);
@@ -239,7 +243,7 @@ static void quic_cc_cubic_ca_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        }
 
  out:
-       TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc, NULL, cc);
+       TRACE_PROTO("CC cubic", QUIC_EV_CONN_CC, cc->qc, NULL, cc);
 }
 
 /* Recovery period callback */
@@ -248,6 +252,7 @@ static void quic_cc_cubic_rp_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        struct cubic *c = quic_cc_priv(cc);
 
        TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc, ev);
+       TRACE_PROTO("CC cubic", QUIC_EV_CONN_CC, cc->qc, ev);
 
        BUG_ON(!tick_isset(c->recovery_start_time));
 
@@ -257,8 +262,10 @@ static void quic_cc_cubic_rp_cb(struct quic_cc *cc, struct quic_cc_event *ev)
                 * A recovery period ends and the sender enters congestion avoidance when a
                 * packet sent during the recovery period is acknowledged.
                 */
-               if (tick_is_le(ev->ack.time_sent, c->recovery_start_time))
+               if (tick_is_le(ev->ack.time_sent, c->recovery_start_time)) {
+                       TRACE_PROTO("CC cubic (still in recov. period)", QUIC_EV_CONN_CC, cc->qc);
                        goto leave;
+               }
 
                cc->algo->state = QUIC_CC_ST_CA;
                c->recovery_start_time = TICK_ETERNITY;
@@ -271,6 +278,7 @@ static void quic_cc_cubic_rp_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        }
 
  leave:
+       TRACE_PROTO("CC cubic", QUIC_EV_CONN_CC, cc->qc, NULL, cc);
        TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc, NULL, cc);
 }
 

diff --git a/src/quic_cc_newreno.c b/src/quic_cc_newreno.c
index 2eedbfbe7a17c82701bc7de4d063616028f6b72a..bf714b1eb2054533320c84231c6fa25cbe9a74c7 100644 (file)
--- a/src/quic_cc_newreno.c
+++ b/src/quic_cc_newreno.c
@@ -80,7 +80,8 @@ static void quic_cc_nr_ss_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        struct quic_path *path;
        struct nr *nr = quic_cc_priv(cc);
 
-       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc, ev);
+       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc);
+       TRACE_PROTO("CC reno", QUIC_EV_CONN_CC, cc->qc, ev);
        path = container_of(cc, struct quic_path, cc);
        switch (ev->type) {
        case QUIC_CC_EVT_ACK:
@@ -98,7 +99,8 @@ static void quic_cc_nr_ss_cb(struct quic_cc *cc, struct quic_cc_event *ev)
                /* XXX TO DO XXX */
                break;
        }
-       TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc,, cc);
+       TRACE_PROTO("CC reno", QUIC_EV_CONN_CC, cc->qc, NULL, cc);
+       TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc);
 }
 
 /* Congestion avoidance callback. */
@@ -107,7 +109,8 @@ static void quic_cc_nr_ca_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        struct quic_path *path;
        struct nr *nr = quic_cc_priv(cc);
 
-       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc, ev);
+       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc);
+       TRACE_PROTO("CC reno", QUIC_EV_CONN_CC, cc->qc, ev);
        path = container_of(cc, struct quic_path, cc);
        switch (ev->type) {
        case QUIC_CC_EVT_ACK:
@@ -132,7 +135,8 @@ static void quic_cc_nr_ca_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        }
 
  out:
-       TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc, NULL, cc);
+       TRACE_PROTO("CC reno", QUIC_EV_CONN_CC, cc->qc, NULL, cc);
+       TRACE_LEAVE(QUIC_EV_CONN_CC, cc->qc);
 }
 
 /*  Recovery period callback. */
@@ -143,7 +147,8 @@ static void quic_cc_nr_rp_cb(struct quic_cc *cc, struct quic_cc_event *ev)
 
        BUG_ON(!tick_isset(nr->recovery_start_time));
 
-       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc, ev);
+       TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc);
+       TRACE_PROTO("CC reno", QUIC_EV_CONN_CC, cc->qc, ev);
        path = container_of(cc, struct quic_path, cc);
        switch (ev->type) {
        case QUIC_CC_EVT_ACK:
@@ -151,8 +156,10 @@ static void quic_cc_nr_rp_cb(struct quic_cc *cc, struct quic_cc_event *ev)
                 * A recovery period ends and the sender enters congestion avoidance when a
                 * packet sent during the recovery period is acknowledged.
                 */
-               if (tick_is_le(ev->ack.time_sent, nr->recovery_start_time))
+               if (tick_is_le(ev->ack.time_sent, nr->recovery_start_time)) {
+                       TRACE_PROTO("CC reno (still in recovery period)", QUIC_EV_CONN_CC, cc->qc, ev);
                        goto leave;
+               }
 
                cc->algo->state = QUIC_CC_ST_CA;
                nr->recovery_start_time = TICK_ETERNITY;
@@ -167,6 +174,7 @@ static void quic_cc_nr_rp_cb(struct quic_cc *cc, struct quic_cc_event *ev)
        }
 
  leave:
+       TRACE_PROTO("CC reno", QUIC_EV_CONN_CC, cc->qc, ev);
        TRACE_ENTER(QUIC_EV_CONN_CC, cc->qc, ev);
 }
 static void quic_cc_nr_state_trace(struct buffer *buf, const struct quic_cc *cc)

diff --git a/src/quic_conn.c b/src/quic_conn.c
index ef2707c14fd505e5f0186462510a550d5e433511..f65e217c606885b1521ae32f79127531b94bfb43 100644 (file)
--- a/src/quic_conn.c
+++ b/src/quic_conn.c
@@ -702,10 +702,8 @@ static void quic_trace(enum trace_level level, uint64_t mask, const struct trace
                if (mask & QUIC_EV_CONN_PSTRM) {
                        const struct quic_frame *frm = a2;
 
-                       if (frm) {
-                               chunk_appendf(&trace_buf, " frm@%p", frm);
+                       if (frm)
                                chunk_frm_appendf(&trace_buf, frm);
-                       }
                }
 
                if (mask & QUIC_EV_CONN_ELEVELSEL) {
@@ -793,8 +791,8 @@ static inline void qc_set_timer(struct quic_conn *qc)
        unsigned int pto;
        int handshake_confirmed;
 
-       TRACE_ENTER(QUIC_EV_CONN_STIMER, qc,
-                   NULL, NULL, &qc->path->ifae_pkts);
+       TRACE_ENTER(QUIC_EV_CONN_STIMER, qc);
+       TRACE_PROTO("set timer", QUIC_EV_CONN_STIMER, qc, NULL, NULL, &qc->path->ifae_pkts);
 
        pktns = NULL;
        if (!qc->timer_task) {
@@ -842,7 +840,8 @@ static inline void qc_set_timer(struct quic_conn *qc)
                task_schedule(qc->timer_task, qc->timer);
        }
  leave:
-       TRACE_LEAVE(QUIC_EV_CONN_STIMER, qc, pktns);
+       TRACE_PROTO("set timer", QUIC_EV_CONN_STIMER, qc, pktns);
+       TRACE_LEAVE(QUIC_EV_CONN_STIMER, qc);
 }
 
 /* Derive new keys and ivs required for Key Update feature for <qc> QUIC
@@ -930,7 +929,8 @@ static int quic_tls_key_update(struct quic_conn *qc)
 
        ret = 1;
  leave:
-       TRACE_LEAVE(QUIC_EV_CONN_KP, qc, &kp_trace);
+       TRACE_PROTO("key update", QUIC_EV_CONN_KP, qc, &kp_trace);
+       TRACE_LEAVE(QUIC_EV_CONN_KP, qc);
        return ret;
 }
 
@@ -1746,7 +1746,8 @@ static int quic_stream_try_to_consume(struct quic_conn *qc,
 static inline void qc_treat_acked_tx_frm(struct quic_conn *qc,
                                          struct quic_frame *frm)
 {
-       TRACE_ENTER(QUIC_EV_CONN_PRSAFRM, qc, frm);
+       TRACE_ENTER(QUIC_EV_CONN_PRSAFRM, qc);
+       TRACE_PROTO("RX ack TX frm", QUIC_EV_CONN_PRSAFRM, qc, frm);
 
        switch (frm->type) {
        case QUIC_FT_STREAM_8 ... QUIC_FT_STREAM_F:
@@ -2215,7 +2216,7 @@ static inline int qc_parse_ack_frm(struct quic_conn *qc,
                }
        }
 
-       TRACE_PROTO("rcvd ack range", QUIC_EV_CONN_PRSAFRM,
+       TRACE_PROTO("RX ack range", QUIC_EV_CONN_PRSAFRM,
                    qc, NULL, &largest, &smallest);
        do {
                uint64_t gap, ack_range;
@@ -2253,7 +2254,7 @@ static inline int qc_parse_ack_frm(struct quic_conn *qc,
                /* Next range */
                smallest = largest - ack_range;
 
-               TRACE_PROTO("rcvd next ack range", QUIC_EV_CONN_PRSAFRM,
+               TRACE_PROTO("RX next ack range", QUIC_EV_CONN_PRSAFRM,
                            qc, NULL, &largest, &smallest);
        } while (1);
 
@@ -2640,7 +2641,7 @@ static void qc_prep_fast_retrans(struct quic_conn *qc,
                p = eb64_entry(node, struct quic_tx_packet, pn_node);
                node = eb64_next(node);
                /* Skip the empty and coalesced packets */
-               TRACE_PRINTF(TRACE_LEVEL_DEVELOPER, QUIC_EV_CONN_SPPKTS, qc, 0, 0, 0,
+               TRACE_PRINTF(TRACE_LEVEL_PROTO, QUIC_EV_CONN_SPPKTS, qc, 0, 0, 0,
                             "--> pn=%llu (%d %d %d)", (ull)p->pn_node.key,
                             LIST_ISEMPTY(&p->frms), !!(p->flags & QUIC_FL_TX_PACKET_COALESCED),
                             qc_pkt_with_only_acked_frms(p));
@@ -2663,7 +2664,7 @@ static void qc_prep_fast_retrans(struct quic_conn *qc,
                goto leave;
        }
 
-       TRACE_DEVEL("duplicating packet", QUIC_EV_CONN_SPPKTS, qc, pkt);
+       TRACE_PROTO("duplicating packet", QUIC_EV_CONN_SPPKTS, qc, pkt);
        qc_dup_pkt_frms(qc, &pkt->frms, frms);
        if (frms == frms1 && frms2) {
                frms = frms2;
@@ -2702,7 +2703,7 @@ static void qc_prep_hdshk_fast_retrans(struct quic_conn *qc,
                struct quic_tx_packet *p;
 
                p = eb64_entry(node, struct quic_tx_packet, pn_node);
-               TRACE_PRINTF(TRACE_LEVEL_DEVELOPER, QUIC_EV_CONN_SPPKTS, qc, 0, 0, 0,
+               TRACE_PRINTF(TRACE_LEVEL_PROTO, QUIC_EV_CONN_SPPKTS, qc, 0, 0, 0,
                             "--> pn=%llu (%d %d)", (ull)p->pn_node.key,
                             LIST_ISEMPTY(&p->frms), !!(p->flags & QUIC_FL_TX_PACKET_COALESCED));
                if (!LIST_ISEMPTY(&p->frms) && !(p->flags & QUIC_FL_TX_PACKET_COALESCED) &&
@@ -2737,7 +2738,7 @@ static void qc_prep_hdshk_fast_retrans(struct quic_conn *qc,
 
        /* No risk to loop here, #packet per datagram is bounded */
  requeue:
-       TRACE_DEVEL("duplicating packet", QUIC_EV_CONN_PRSAFRM, qc, NULL, &pkt->pn_node.key);
+       TRACE_PROTO("duplicating packet", QUIC_EV_CONN_PRSAFRM, qc, NULL, &pkt->pn_node.key);
        qc_dup_pkt_frms(qc, &pkt->frms, tmp);
        if (qel == iqel) {
                if (pkt->next && pkt->next->type == QUIC_PACKET_TYPE_HANDSHAKE) {
@@ -3089,7 +3090,6 @@ static int qc_parse_pkt_frms(struct quic_conn *qc, struct quic_rx_packet *pkt,
                        goto leave;
                }
 
-               TRACE_PROTO("RX frame", QUIC_EV_CONN_PSTRM, qc, &frm);
                switch (frm.type) {
                case QUIC_FT_PADDING:
                        break;
@@ -3523,7 +3523,7 @@ static int qc_prep_pkts(struct quic_conn *qc, struct buffer *buf,
                        (qel == &qc->els[QUIC_TLS_ENC_LEVEL_INITIAL] ||
                         qel == &qc->els[QUIC_TLS_ENC_LEVEL_HANDSHAKE]);
 
-               TRACE_POINT(QUIC_EV_CONN_PHPKTS, qc, qel);
+               TRACE_PROTO("TX prep pks", QUIC_EV_CONN_PHPKTS, qc, qel);
                probe = 0;
                cc =  qc->flags & QUIC_FL_CONN_IMMEDIATE_CLOSE;
                /* We do not probe if an immediate close was asked */
@@ -3724,7 +3724,7 @@ int qc_send_ppkts(struct buffer *buf, struct ssl_sock_ctx *ctx)
                tmpbuf.area = (char *)pos;
                tmpbuf.size = tmpbuf.data = dglen;
 
-               TRACE_DATA("send dgram", QUIC_EV_CONN_SPPKTS, qc);
+               TRACE_PROTO("TX dgram", QUIC_EV_CONN_SPPKTS, qc);
                /* If sendto is on error just skip the call to it for the rest
                 * of the loop but continue to purge the buffer. Data will be
                 * transmitted when QUIC packets are detected as lost on our
@@ -3802,7 +3802,7 @@ int qc_send_ppkts(struct buffer *buf, struct ssl_sock_ctx *ctx)
                        pkt->pktns->tx.in_flight += pkt->in_flight_len;
                        if (pkt->in_flight_len)
                                qc_set_timer(qc);
-                       TRACE_DATA("sent pkt", QUIC_EV_CONN_SPPKTS, qc, pkt);
+                       TRACE_PROTO("TX pkt", QUIC_EV_CONN_SPPKTS, qc, pkt);
                        next_pkt = pkt->next;
                        quic_tx_packet_refinc(pkt);
                        eb64_insert(&pkt->pktns->tx.pkts, &pkt->pn_node);
@@ -4278,7 +4278,7 @@ static inline void qc_rm_hp_pkts(struct quic_conn *qc, struct quic_enc_level *el
        app_qel = &qc->els[QUIC_TLS_ENC_LEVEL_APP];
        /* A server must not process incoming 1-RTT packets before the handshake is complete. */
        if (el == app_qel && qc_is_listener(qc) && qc->state < QUIC_HS_ST_COMPLETE) {
-               TRACE_DEVEL("hp not removed (handshake not completed)",
+               TRACE_PROTO("RX hp not removed (handshake not completed)",
                            QUIC_EV_CONN_ELRMHP, qc);
                goto out;
        }
@@ -4289,7 +4289,7 @@ static inline void qc_rm_hp_pkts(struct quic_conn *qc, struct quic_enc_level *el
                tls_ctx = qc_select_tls_ctx(qc, el, pqpkt);
                if (!qc_do_rm_hp(qc, pqpkt, tls_ctx, el->pktns->rx.largest_pn,
                                 pqpkt->data + pqpkt->pn_offset, pqpkt->data)) {
-                       TRACE_ERROR("hp removing error", QUIC_EV_CONN_ELRMHP, qc);
+                       TRACE_ERROR("RX hp removing error", QUIC_EV_CONN_ELRMHP, qc);
                }
                else {
                        qc_handle_spin_bit(qc, pqpkt, el);
@@ -4299,7 +4299,7 @@ static inline void qc_rm_hp_pkts(struct quic_conn *qc, struct quic_enc_level *el
                        pqpkt->pn_node.key = pqpkt->pn;
                        eb64_insert(&el->rx.pkts, &pqpkt->pn_node);
                        quic_rx_packet_refinc(pqpkt);
-                       TRACE_DEVEL("hp removed", QUIC_EV_CONN_ELRMHP, qc, pqpkt);
+                       TRACE_PROTO("RX hp removed", QUIC_EV_CONN_ELRMHP, qc, pqpkt);
                }
                LIST_DELETE(&pqpkt->list);
                quic_rx_packet_refdec(pqpkt);
@@ -4323,7 +4323,7 @@ static inline int qc_treat_rx_crypto_frms(struct quic_conn *qc,
        struct quic_cstream *cstream = el->cstream;
        ncb_sz_t data;
 
-       TRACE_ENTER(QUIC_EV_CONN_PHPKTS, qc, el);
+       TRACE_ENTER(QUIC_EV_CONN_PHPKTS, qc);
 
        BUG_ON(!cstream);
        ncbuf = &cstream->rx.ncbuf;
@@ -4461,24 +4461,24 @@ static int qc_qel_may_rm_hp(struct quic_conn *qc, struct quic_enc_level *qel)
 
        /* check if tls secrets are available */
        if (qel->tls_ctx.flags & QUIC_FL_TLS_SECRETS_DCD) {
-               TRACE_DEVEL("Discarded keys", QUIC_EV_CONN_TRMHP, qc);
+               TRACE_PROTO("Discarded keys", QUIC_EV_CONN_TRMHP, qc);
                goto cant_rm_hp;
        }
 
        if (!quic_tls_has_rx_sec(qel)) {
-               TRACE_DEVEL("non available secrets", QUIC_EV_CONN_TRMHP, qc);
+               TRACE_PROTO("non available secrets", QUIC_EV_CONN_TRMHP, qc);
                goto cant_rm_hp;
        }
 
        if (tel == QUIC_TLS_ENC_LEVEL_APP && qc->state < QUIC_HS_ST_COMPLETE) {
-               TRACE_DEVEL("handshake not complete", QUIC_EV_CONN_TRMHP, qc);
+               TRACE_PROTO("handshake not complete", QUIC_EV_CONN_TRMHP, qc);
                goto cant_rm_hp;
        }
 
        /* check if the connection layer is ready before using app level */
        if ((tel == QUIC_TLS_ENC_LEVEL_APP || tel == QUIC_TLS_ENC_LEVEL_EARLY_DATA) &&
            qc->mux_state == QC_MUX_NULL) {
-               TRACE_DEVEL("connection layer not ready", QUIC_EV_CONN_TRMHP, qc);
+               TRACE_PROTO("connection layer not ready", QUIC_EV_CONN_TRMHP, qc);
                goto cant_rm_hp;
        }
 
@@ -4997,7 +4997,8 @@ struct task *quic_conn_io_cb(struct task *t, void *context, unsigned int state)
        }
 
  out:
-       TRACE_LEAVE(QUIC_EV_CONN_IO_CB, qc, &st, &ssl_err);
+       TRACE_PROTO("ssl error", QUIC_EV_CONN_IO_CB, qc, &st, &ssl_err);
+       TRACE_LEAVE(QUIC_EV_CONN_IO_CB, qc);
        return t;
 }
 
@@ -5141,7 +5142,8 @@ struct task *qc_process_timer(struct task *task, void *ctx, unsigned int state)
        struct quic_conn *qc = ctx;
        struct quic_pktns *pktns;
 
-       TRACE_ENTER(QUIC_EV_CONN_PTIMER, qc,
+       TRACE_ENTER(QUIC_EV_CONN_PTIMER, qc);
+       TRACE_PROTO("process timer", QUIC_EV_CONN_PTIMER, qc,
                    NULL, NULL, &qc->path->ifae_pkts);
        task->expire = TICK_ETERNITY;
        pktns = quic_loss_pktns(qc);
@@ -5211,7 +5213,8 @@ struct task *qc_process_timer(struct task *task, void *ctx, unsigned int state)
        qc->path->loss.pto_count++;
 
  out:
-       TRACE_LEAVE(QUIC_EV_CONN_PTIMER, qc, pktns);
+       TRACE_PROTO("process timer", QUIC_EV_CONN_PTIMER, qc, pktns);
+       TRACE_LEAVE(QUIC_EV_CONN_PTIMER, qc);
 
        return task;
 }
@@ -5844,7 +5847,7 @@ static inline int qc_try_rm_hp(struct quic_conn *qc,
                        goto out;
                }
 
-               TRACE_PROTO("hp not removed", QUIC_EV_CONN_TRMHP, qc, pkt);
+               TRACE_PROTO("RX hp not removed", QUIC_EV_CONN_TRMHP, qc, pkt);
                LIST_APPEND(&qel->rx.pqpkts, &pkt->list);
                quic_rx_packet_refinc(pkt);
        }
@@ -6575,7 +6578,7 @@ static struct quic_conn *quic_rx_pkt_retrieve_conn(struct quic_rx_packet *pkt,
                }
        }
        else if (!qc) {
-               TRACE_PROTO("No connection on a non Initial packet", QUIC_EV_CONN_LPKT, NULL, NULL, NULL, pkt->version);
+               TRACE_PROTO("RX non Initial pkt without connection", QUIC_EV_CONN_LPKT, NULL, NULL, NULL, pkt->version);
                if (global.cluster_secret && !send_stateless_reset(l, &dgram->saddr, pkt))
                        TRACE_ERROR("stateless reset not sent", QUIC_EV_CONN_LPKT, qc);
                goto err;
@@ -6759,7 +6762,7 @@ static int quic_rx_pkt_parse(struct quic_rx_packet *pkt,
                 */
                if (pkt->type == QUIC_PACKET_TYPE_INITIAL &&
                    dgram->len < QUIC_INITIAL_PACKET_MINLEN) {
-                       TRACE_PROTO("Too short datagram with an Initial packet", QUIC_EV_CONN_LPKT);
+                       TRACE_PROTO("RX too short datagram with an Initial packet", QUIC_EV_CONN_LPKT);
                        HA_ATOMIC_INC(&prx_counters->too_short_initial_dgram);
                        goto drop;
                }
@@ -6769,14 +6772,14 @@ static int quic_rx_pkt_parse(struct quic_rx_packet *pkt,
                 * datagram.
                 */
                if (pkt->type == QUIC_PACKET_TYPE_0RTT && !l->bind_conf->ssl_conf.early_data) {
-                       TRACE_PROTO("0-RTT packet not supported", QUIC_EV_CONN_LPKT);
+                       TRACE_PROTO("RX 0-RTT packet not supported", QUIC_EV_CONN_LPKT);
                        goto drop;
                }
        }
        else {
-               TRACE_PROTO("short header packet received", QUIC_EV_CONN_LPKT);
+               TRACE_PROTO("RX short header packet", QUIC_EV_CONN_LPKT);
                if (end - buf < QUIC_HAP_CID_LEN) {
-                       TRACE_PROTO("Packet dropped", QUIC_EV_CONN_LPKT);
+                       TRACE_PROTO("RX pkt dropped", QUIC_EV_CONN_LPKT);
                        goto drop;
                }
 
@@ -6789,7 +6792,7 @@ static int quic_rx_pkt_parse(struct quic_rx_packet *pkt,
                if (!(pkt->flags & QUIC_FL_RX_PACKET_DGRAM_FIRST) &&
                    (pkt->dcid.len != dgram->dcid_len ||
                     memcmp(dgram->dcid, pkt->dcid.data, pkt->dcid.len))) {
-                       TRACE_PROTO("Packet dropped", QUIC_EV_CONN_LPKT);
+                       TRACE_PROTO("RX pkt dropped", QUIC_EV_CONN_LPKT);
                        goto drop;
                }
 
@@ -6800,7 +6803,8 @@ static int quic_rx_pkt_parse(struct quic_rx_packet *pkt,
                pkt->len = end - beg;
        }
 
-       TRACE_LEAVE(QUIC_EV_CONN_LPKT, NULL, pkt, NULL, qv);
+       TRACE_PROTO("RX pkt parsed", QUIC_EV_CONN_LPKT, NULL, pkt, NULL, qv);
+       TRACE_LEAVE(QUIC_EV_CONN_LPKT);
        return 0;
 
  drop:
@@ -6808,7 +6812,8 @@ static int quic_rx_pkt_parse(struct quic_rx_packet *pkt,
  drop_silent:
        if (!pkt->len)
                pkt->len = end - beg;
-       TRACE_LEAVE(QUIC_EV_CONN_LPKT, NULL, pkt, NULL, qv);
+       TRACE_PROTO("RX pkt parsing failed", QUIC_EV_CONN_LPKT, NULL, pkt, NULL, qv);
+       TRACE_LEAVE(QUIC_EV_CONN_LPKT);
        return -1;
 }
 
@@ -6967,7 +6972,8 @@ static void qc_rx_pkt_handle(struct quic_conn *qc, struct quic_rx_packet *pkt,
        struct quic_enc_level *qel = NULL;
        size_t b_cspace;
 
-       TRACE_ENTER(QUIC_EV_CONN_LPKT, qc, pkt, NULL, qv);
+       TRACE_ENTER(QUIC_EV_CONN_LPKT, qc);
+       TRACE_PROTO("RX pkt", QUIC_EV_CONN_LPKT, qc, pkt, NULL, qv);
 
        if (pkt->flags & QUIC_FL_RX_PACKET_DGRAM_FIRST &&
            qc->flags & QUIC_FL_CONN_ANTI_AMPLIFICATION_REACHED) {
@@ -7031,12 +7037,14 @@ static void qc_rx_pkt_handle(struct quic_conn *qc, struct quic_rx_packet *pkt,
                                              qc->wait_event.tasklet);
 
  drop_silent:
-       TRACE_LEAVE(QUIC_EV_CONN_LPKT, qc ? qc : NULL, pkt, NULL, qv);
+       TRACE_PROTO("RX pkt", QUIC_EV_CONN_LPKT, qc ? qc : NULL, pkt, NULL, qv);
+       TRACE_LEAVE(QUIC_EV_CONN_LPKT, qc ? qc : NULL);
        return;
 
  drop:
        HA_ATOMIC_INC(&qc->prx_counters->dropped_pkt);
-       TRACE_LEAVE(QUIC_EV_CONN_LPKT, qc ? qc : NULL, pkt, NULL, qv);
+       TRACE_PROTO("packet drop", QUIC_EV_CONN_LPKT, qc ? qc : NULL, pkt, NULL, qv);
+       TRACE_LEAVE(QUIC_EV_CONN_LPKT, qc ? qc : NULL);
 }
 
 /* This function builds into <buf> buffer a QUIC long packet header.
@@ -7208,7 +7216,7 @@ static inline int qc_build_frms(struct list *outlist, struct list *inlist,
                room = QUIC_MIN(room, remain - headlen);
        }
 
-       TRACE_PROTO("************** frames build (headlen)",
+       TRACE_PROTO("TX frms build (headlen)",
                    QUIC_EV_CONN_BCFRMS, qc, &headlen);
 
        /* NOTE: switch/case block inside a loop, a successful status must be
@@ -7818,7 +7826,8 @@ static struct quic_tx_packet *qc_build_pkt(unsigned char **pos,
        size_t pn_len, payload_len, aad_len;
        struct quic_tx_packet *pkt;
 
-       TRACE_ENTER(QUIC_EV_CONN_TXPKT, qc, NULL, qel);
+       TRACE_ENTER(QUIC_EV_CONN_TXPKT, qc);
+       TRACE_PROTO("TX pkt build", QUIC_EV_CONN_TXPKT, qc, NULL, qel);
        *err = 0;
        pkt = pool_alloc(pool_head_quic_tx_packet);
        if (!pkt) {
@@ -7886,7 +7895,8 @@ static struct quic_tx_packet *qc_build_pkt(unsigned char **pos,
 
        ret_pkt = pkt;
  leave:
-       TRACE_LEAVE(QUIC_EV_CONN_TXPKT, qc, ret_pkt);
+       TRACE_PROTO("TX pkt built", QUIC_EV_CONN_TXPKT, qc, ret_pkt);
+       TRACE_LEAVE(QUIC_EV_CONN_TXPKT, qc);
        return ret_pkt;
 
  err:
@@ -8270,8 +8280,10 @@ static int cli_io_handler_dump_quic(struct appctx *appctx)
 
                chunk_appendf(&trash, "  loc. TPs:");
                quic_transport_params_dump(&trash, qc, &qc->rx.params);
+               chunk_appendf(&trash, "\n");
                chunk_appendf(&trash, "  rem. TPs:");
                quic_transport_params_dump(&trash, qc, &qc->tx.params);
+               chunk_appendf(&trash, "\n");
 
                /* Connection state */
                if (qc->flags & QUIC_FL_CONN_CLOSING)

diff --git a/src/quic_frame.c b/src/quic_frame.c
index f569c9fd2560c3b1406fb23a8f0ba6697ec18023..ec5e0427e160767d56dd2d3d72f3c16a3e1890e4 100644 (file)
--- a/src/quic_frame.c
+++ b/src/quic_frame.c
@@ -286,7 +286,7 @@ static int quic_build_ack_frame(unsigned char **buf, const unsigned char *end,
 
        ar = eb64_last(&tx_ack->arngs->root);
        ar_node = eb64_entry(ar, struct quic_arng_node, first);
-       TRACE_DEVEL("ack range", QUIC_EV_CONN_PRSAFRM,
+       TRACE_PROTO("TX ack range", QUIC_EV_CONN_PRSAFRM,
                    qc,, &ar_node->last, &ar_node->first.key);
        if (!quic_enc_int(buf, end, ar_node->last) ||
            !quic_enc_int(buf, end, tx_ack->ack_delay) ||
@@ -296,7 +296,7 @@ static int quic_build_ack_frame(unsigned char **buf, const unsigned char *end,
 
        while ((prev_ar = eb64_prev(ar))) {
                prev_ar_node = eb64_entry(prev_ar, struct quic_arng_node, first);
-               TRACE_DEVEL("ack range", QUIC_EV_CONN_PRSAFRM, qc,,
+               TRACE_PROTO("TX ack range", QUIC_EV_CONN_PRSAFRM, qc,,
                            &prev_ar_node->last, &prev_ar_node->first.key);
                if (!quic_enc_int(buf, end, ar_node->first.key - prev_ar_node->last - 2) ||
                    !quic_enc_int(buf, end, prev_ar_node->last - prev_ar_node->first.key))
@@ -1115,12 +1115,13 @@ int qc_parse_frm(struct quic_frame *frm, struct quic_rx_packet *pkt,
                goto leave;
        }
 
-       TRACE_PROTO("frame", QUIC_EV_CONN_PRSFRM, qc, frm);
        if (!parser->func(frm, qc, buf, end)) {
                TRACE_DEVEL("parsing error", QUIC_EV_CONN_PRSFRM, qc, frm);
                goto leave;
        }
 
+       TRACE_PROTO("RX frm", QUIC_EV_CONN_PSTRM, qc, frm);
+
        pkt->flags |= parser->flags;
 
        ret = 1;
@@ -1155,10 +1156,10 @@ int qc_build_frm(unsigned char **buf, const unsigned char *end,
                goto leave;
        }
 
-       TRACE_PROTO("TX frame", QUIC_EV_CONN_BFRM, qc, frm);
+       TRACE_PROTO("TX frm", QUIC_EV_CONN_BFRM, qc, frm);
        *pos++ = frm->type;
        if (!quic_frame_builders[frm->type].func(&pos, end, frm, qc)) {
-               TRACE_DEVEL("frame building error", QUIC_EV_CONN_BFRM, qc, frm);
+               TRACE_ERROR("frame building error", QUIC_EV_CONN_BFRM, qc, frm);
                goto leave;
        }
 

diff --git a/src/quic_loss.c b/src/quic_loss.c
index a92b69942f31bcf38bbabb3996c9dcfad1332958..8f19645a703f700b128e7943f7af47bb0ac34564 100644 (file)
--- a/src/quic_loss.c
+++ b/src/quic_loss.c
@@ -20,7 +20,7 @@ void quic_loss_srtt_update(struct quic_loss *ql,
                            struct quic_conn *qc)
 {
        TRACE_ENTER(QUIC_EV_CONN_RTTUPDT, qc);
-       TRACE_DEVEL("Loss info update", QUIC_EV_CONN_RTTUPDT, qc, &rtt, &ack_delay, ql);
+       TRACE_PROTO("TX loss srtt update", QUIC_EV_CONN_RTTUPDT, qc, &rtt, &ack_delay, ql);
 
        ql->latest_rtt = rtt;
        if (!ql->rtt_min) {
@@ -46,7 +46,7 @@ void quic_loss_srtt_update(struct quic_loss *ql,
                ql->srtt += rtt - (ql->srtt >> 3);
        }
 
-       TRACE_DEVEL("Loss info update", QUIC_EV_CONN_RTTUPDT, qc,,, ql);
+       TRACE_PROTO("TX loss srtt update", QUIC_EV_CONN_RTTUPDT, qc,,, ql);
        TRACE_LEAVE(QUIC_EV_CONN_RTTUPDT, qc);
 }
 
@@ -62,9 +62,9 @@ struct quic_pktns *quic_loss_pktns(struct quic_conn *qc)
        TRACE_ENTER(QUIC_EV_CONN_SPTO, qc);
 
        pktns = &qc->pktns[QUIC_TLS_PKTNS_INITIAL];
-       TRACE_DEVEL("pktns", QUIC_EV_CONN_SPTO, qc, pktns);
+       TRACE_PROTO("TX loss pktns", QUIC_EV_CONN_SPTO, qc, pktns);
        for (i = QUIC_TLS_PKTNS_HANDSHAKE; i < QUIC_TLS_PKTNS_MAX; i++) {
-               TRACE_DEVEL("pktns", QUIC_EV_CONN_SPTO, qc, &qc->pktns[i]);
+               TRACE_PROTO("TX loss pktns", QUIC_EV_CONN_SPTO, qc, &qc->pktns[i]);
                if (!tick_isset(pktns->tx.loss_time) ||
                    qc->pktns[i].tx.loss_time < pktns->tx.loss_time)
                        pktns = &qc->pktns[i];
@@ -118,7 +118,7 @@ struct quic_pktns *quic_pto_pktns(struct quic_conn *qc,
 
                if (i == QUIC_TLS_PKTNS_01RTT) {
                        if (!handshake_confirmed) {
-                               TRACE_STATE("handshake not already completed", QUIC_EV_CONN_SPTO, qc);
+                               TRACE_STATE("TX PTO handshake not already completed", QUIC_EV_CONN_SPTO, qc);
                                pktns = p;
                                goto out;
                        }
@@ -132,13 +132,14 @@ struct quic_pktns *quic_pto_pktns(struct quic_conn *qc,
                        lpto = tmp_pto;
                        pktns = p;
                }
-               TRACE_DEVEL("pktns", QUIC_EV_CONN_SPTO, qc, p);
+               TRACE_PROTO("TX PTO", QUIC_EV_CONN_SPTO, qc, p);
        }
 
  out:
        if (pto)
                *pto = lpto;
-       TRACE_LEAVE(QUIC_EV_CONN_SPTO, qc, pktns, &duration);
+       TRACE_PROTO("TX PTO", QUIC_EV_CONN_SPTO, qc, pktns, &duration);
+       TRACE_LEAVE(QUIC_EV_CONN_SPTO, qc);
 
        return pktns;
 }
@@ -159,7 +160,8 @@ void qc_packet_loss_lookup(struct quic_pktns *pktns, struct quic_conn *qc,
        struct quic_loss *ql;
        unsigned int loss_delay;
 
-       TRACE_ENTER(QUIC_EV_CONN_PKTLOSS, qc, pktns);
+       TRACE_ENTER(QUIC_EV_CONN_PKTLOSS, qc);
+       TRACE_PROTO("TX loss", QUIC_EV_CONN_PKTLOSS, qc, pktns);
        pkts = &pktns->tx.pkts;
        pktns->tx.loss_time = TICK_ETERNITY;
        if (eb_is_empty(pkts))
@@ -200,6 +202,7 @@ void qc_packet_loss_lookup(struct quic_pktns *pktns, struct quic_conn *qc,
        }
 
  out:
-       TRACE_LEAVE(QUIC_EV_CONN_PKTLOSS, qc, pktns, lost_pkts);
+       TRACE_PROTO("TX loss", QUIC_EV_CONN_PKTLOSS, qc, pktns, lost_pkts);
+       TRACE_LEAVE(QUIC_EV_CONN_PKTLOSS, qc);
 }