From: Amaury Denoyelle <adenoyelle@haproxy.com>
Date: Fri, 18 Nov 2022 14:24:08 +0000 (+0100)
Subject: MINOR: quic: complete traces/debug for handshake
X-Git-Tag: v2.7-dev9~1
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=2f668f0e601a6ae5fa13a6e15b10dce5a42b4167;p=thirdparty%2Fhaproxy.git

MINOR: quic: complete traces/debug for handshake

Add more traces to follow CRYPTO data buffering in ncbuf. Offset for
quic_enc_level is now reported for event QUIC_EV_CONN_PRHPKTS. Also
ncb_advance() must never fail so a BUG_ON() statement is here to
guarantee it.

This was useful to track handshake failure reported too often. This is
related to github issue #1903.

This should be backported up to 2.6.
---

diff --git a/src/quic_conn.c b/src/quic_conn.c
index a2b42c9232..496aa69899 100644
--- a/src/quic_conn.c
+++ b/src/quic_conn.c
@@ -459,7 +459,7 @@ static void quic_trace(enum trace_level level, uint64_t mask, const struct trace
 			if (qel) {
 				const struct quic_pktns *pktns = qel->pktns;
 				chunk_appendf(&trace_buf,
-				              " qel=%c state=%s ack?%d cwnd=%llu ppif=%lld pif=%llu if=%llu pp=%u",
+				              " qel=%c state=%s ack?%d cwnd=%llu ppif=%lld pif=%llu if=%llu pp=%u off=%llu",
 				              quic_enc_level_char_from_qel(qel, qc),
 				              quic_hdshk_state_str(qc->state),
 				              !!(qel->pktns->flags & QUIC_FL_PKTNS_ACK_REQUIRED),
@@ -467,7 +467,8 @@ static void quic_trace(enum trace_level level, uint64_t mask, const struct trace
 				              (unsigned long long)qc->path->prep_in_flight,
 				              (unsigned long long)qc->path->in_flight,
 				              (unsigned long long)pktns->tx.in_flight,
-				              pktns->tx.pto_probe);
+				              pktns->tx.pto_probe,
+				              qel->cstream ? (unsigned long long)qel->cstream->rx.offset : 0);
 			}
 		}
 
@@ -2223,6 +2224,9 @@ static inline int qc_provide_cdata(struct quic_enc_level *el,
                                    struct quic_rx_packet *pkt,
                                    struct quic_rx_crypto_frm *cf)
 {
+#ifdef DEBUG_STRICT
+	enum ncb_ret ncb_ret;
+#endif
 	int ssl_err, state;
 	struct quic_conn *qc;
 	int ret = 0;
@@ -2319,8 +2323,20 @@ static inline int qc_provide_cdata(struct quic_enc_level *el,
 	/* The CRYPTO data are consumed even in case of an error to release
 	 * the memory asap.
 	 */
-	if (!ncb_is_null(ncbuf))
+	if (!ncb_is_null(ncbuf)) {
+#ifdef DEBUG_STRICT
+		ncb_ret = ncb_advance(ncbuf, len);
+		/* ncb_advance() must always succeed. This is guaranteed as
+		 * this is only done inside a data block. If false, this will
+		 * lead to handshake failure with quic_enc_level offset shifted
+		 * from buffer data.
+		 */
+		BUG_ON(ncb_ret != NCB_RET_OK);
+#else
 		ncb_advance(ncbuf, len);
+#endif
+	}
+
 	TRACE_LEAVE(QUIC_EV_CONN_SSLDATA, qc);
 	return ret;
 }
@@ -2690,6 +2706,7 @@ static int qc_handle_crypto_frm(struct quic_conn *qc,
 		}
 
 		cstream->rx.offset += frm->len;
+		TRACE_DEVEL("increment crypto level offset", QUIC_EV_CONN_PHPKTS, qc, qel);
 		goto done;
 	}
 
@@ -3863,23 +3880,25 @@ static inline int qc_treat_rx_crypto_frms(struct quic_conn *qc,
 	if (ncb_is_null(ncbuf))
 		goto done;
 
+	/* TODO not working if buffer is wrapping */
 	while ((data = ncb_data(ncbuf, 0))) {
 		const unsigned char *cdata = (const unsigned char *)ncb_head(ncbuf);
 
 		if (!qc_provide_cdata(el, ctx, cdata, data, NULL, NULL))
 			goto leave;
 
-		TRACE_DEVEL("buffered crypto data were provided to TLS stack",
-		            QUIC_EV_CONN_PHPKTS, qc);
-
 		cstream->rx.offset += data;
+		TRACE_DEVEL("buffered crypto data were provided to TLS stack",
+		            QUIC_EV_CONN_PHPKTS, qc, el);
 	}
 
  done:
 	ret = 1;
  leave:
-	if (ncb_is_empty(ncbuf))
+	if (!ncb_is_null(ncbuf) && ncb_is_empty(ncbuf)) {
+		TRACE_DEVEL("freeing crypto buf", QUIC_EV_CONN_PHPKTS, qc, el);
 		quic_free_ncbuf(ncbuf);
+	}
 	TRACE_LEAVE(QUIC_EV_CONN_PHPKTS, qc);
 	return ret;
 }