MINOR: h3: add traces on decode_qcs callback
Add traces inside h3_decode_qcs(). Every error path has now its
dedicated trace which should simplify debugging. Each early returns has
been converted to a goto invocation.
To complete the demux tracing, demux frame type and length are now
printed using the h3s instance whenever its possible on trace
invocation. A new internal value H3_FT_UNINIT is used as a frame type to
mark demuxing as inactive.
This should be backported up to 2.7.
diff --git a/include/haproxy/h3.h b/include/haproxy/h3.h
index ab088d8..1bedf43 100644
--- a/include/haproxy/h3.h
+++ b/include/haproxy/h3.h
@@ -75,6 +75,9 @@
/* Frame types. */
enum h3_ft {
+ /* internal value used to mark demuxing as inactive */
+ H3_FT_UNINIT = -1,
+
H3_FT_DATA = 0x00,
H3_FT_HEADERS = 0x01,
/* hole */
diff --git a/src/h3.c b/src/h3.c
index 263e0ce..a214a22 100644
--- a/src/h3.c
+++ b/src/h3.c
@@ -982,22 +982,26 @@
struct h3c *h3c = h3s->h3c;
ssize_t total = 0, ret;
- h3_debug_printf(stderr, "%s: STREAM ID: %lu\n", __func__, qcs->id);
+ TRACE_ENTER(H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
if (quic_stream_is_uni(qcs->id) && !(h3s->flags & H3_SF_UNI_INIT)) {
- if ((ret = h3_init_uni_stream(h3c, qcs, b)) < 0)
- return -1;
+ if ((ret = h3_init_uni_stream(h3c, qcs, b)) < 0) {
+ TRACE_ERROR("cannot initialize uni stream", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
+ goto err;
+ }
total += ret;
}
if (quic_stream_is_uni(qcs->id) && (h3s->flags & H3_SF_UNI_NO_H3)) {
/* For non-h3 STREAM, parse it and return immediately. */
- if ((ret = h3_parse_uni_stream_no_h3(qcs, b, fin)) < 0)
- return -1;
+ if ((ret = h3_parse_uni_stream_no_h3(qcs, b, fin)) < 0) {
+ TRACE_ERROR("error when parsing non-HTTP3 uni stream", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
+ goto err;
+ }
total += ret;
- return total;
+ goto done;
}
/* RFC 9114 6.2.1. Control Streams
@@ -1008,13 +1012,15 @@
* error of type H3_CLOSED_CRITICAL_STREAM.
*/
if (h3s->type == H3S_T_CTRL && fin) {
+ TRACE_ERROR("control stream closed by remote peer", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
qcc_emit_cc_app(qcs->qcc, H3_CLOSED_CRITICAL_STREAM, 1);
- return -1;
+ goto err;
}
if (!b_data(b) && fin && quic_stream_is_bidi(qcs->id)) {
+ TRACE_PROTO("received FIN without data", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
qcs_http_handle_standalone_fin(qcs);
- return 0;
+ goto done;
}
while (b_data(b) && !(qcs->flags & QC_SF_DEM_FULL) && !h3c->err && !h3s->err) {
@@ -1024,15 +1030,15 @@
if (!h3s->demux_frame_len) {
/* Switch to a new frame. */
size_t hlen = h3_decode_frm_header(&ftype, &flen, b);
- if (!hlen)
+ if (!hlen) {
+ TRACE_PROTO("pause parsing on incomplete frame header", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
break;
-
- h3_debug_printf(stderr, "%s: ftype: %lu, flen: %lu\n",
- __func__, ftype, flen);
+ }
h3s->demux_frame_type = ftype;
h3s->demux_frame_len = flen;
total += hlen;
+ TRACE_PROTO("parsing a new frame", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
/* Check that content-length is not exceeded on a new DATA frame. */
if (ftype == H3_FT_DATA) {
@@ -1042,8 +1048,9 @@
}
if (!h3_is_frame_valid(h3c, qcs, ftype)) {
+ TRACE_ERROR("received an invalid frame", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
qcc_emit_cc_app(qcs->qcc, H3_FRAME_UNEXPECTED, 1);
- return -1;
+ goto err;
}
if (!b_data(b))
@@ -1064,8 +1071,9 @@
* excessive decompressed size.
*/
if (flen > QC_S_RX_BUF_SZ) {
+ TRACE_ERROR("received a too big frame", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
qcc_emit_cc_app(qcs->qcc, H3_EXCESSIVE_LOAD, 1);
- return -1;
+ goto err;
}
break;
}
@@ -1102,8 +1110,9 @@
case H3_FT_SETTINGS:
ret = h3_parse_settings_frm(qcs->qcc->ctx, b, flen);
if (ret < 0) {
+ TRACE_ERROR("error on SETTINGS parsing", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
qcc_emit_cc_app(qcs->qcc, h3c->err, 1);
- return -1;
+ goto err;
}
h3c->flags |= H3_CF_SETTINGS_RECV;
break;
@@ -1113,7 +1122,6 @@
* Implementations MUST discard frames [...] that have unknown
* or unsupported types.
*/
- h3_debug_printf(stderr, "ignore unknown frame type 0x%lx\n", ftype);
ret = flen;
break;
}
@@ -1126,6 +1134,10 @@
}
}
+ /* Reset demux frame type for traces. */
+ if (!h3s->demux_frame_len)
+ h3s->demux_frame_type = H3_FT_UNINIT;
+
/* Interrupt decoding on stream/connection error detected. */
if (h3s->err) {
qcc_abort_stream_read(qcs);
@@ -1141,7 +1153,13 @@
* However, currently, io-cb of MUX does not handle Rx.
*/
+ done:
+ TRACE_LEAVE(H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
return total;
+
+ err:
+ TRACE_DEVEL("leaving on error", H3_EV_RX_FRAME, qcs->qcc->conn, qcs);
+ return -1;
}
/* Returns buffer for data sending.
@@ -1655,7 +1673,7 @@
h3s->h3c = conn_ctx;
h3s->demux_frame_len = 0;
- h3s->demux_frame_type = 0;
+ h3s->demux_frame_type = H3_FT_UNINIT;
h3s->body_len = 0;
h3s->data_len = 0;
h3s->flags = 0;
@@ -1820,6 +1838,20 @@
h3_inc_err_cnt(h3c->prx_counters, err_code);
}
+static inline const char *h3_ft_str(int type)
+{
+ switch (type) {
+ case H3_FT_DATA: return "DATA";
+ case H3_FT_HEADERS: return "HEADERS";
+ case H3_FT_SETTINGS: return "SETTINGS";
+ case H3_FT_PUSH_PROMISE: return "PUSH_PROMISE";
+ case H3_FT_MAX_PUSH_ID: return "MAX_PUSH_ID";
+ case H3_FT_CANCEL_PUSH: return "CANCEL_PUSH";
+ case H3_FT_GOAWAY: return "GOAWAY";
+ default: return "_UNKNOWN_";
+ }
+}
+
/* h3 trace handler */
static void h3_trace(enum trace_level level, uint64_t mask,
const struct trace_source *src,
@@ -1829,6 +1861,7 @@
const struct connection *conn = a1;
const struct qcc *qcc = conn ? conn->ctx : NULL;
const struct qcs *qcs = a2;
+ const struct h3s *h3s = qcs ? qcs->ctx : NULL;
if (!qcc)
return;
@@ -1840,6 +1873,11 @@
if (qcs)
chunk_appendf(&trace_buf, " qcs=%p(%llu)", qcs, (ull)qcs->id);
+
+ if (h3s && h3s->demux_frame_type != H3_FT_UNINIT) {
+ chunk_appendf(&trace_buf, " h3s.dem=%s/%d",
+ h3_ft_str(h3s->demux_frame_type), h3s->demux_frame_len);
+ }
}
}