MINOR: mux-quic: replace printfs by traces
Convert all printfs in the mux-quic code with traces.
Note that some meaningul printfs were not converted because they use
extra args in a format-string. This is the case inside qcs_push_frame
and qc_send_max_streams. A dedicated trace event should be implemented
for them to be able to display the extra arguments.
diff --git a/src/mux_quic.c b/src/mux_quic.c
index ce11772..8496df7 100644
--- a/src/mux_quic.c
+++ b/src/mux_quic.c
@@ -22,6 +22,30 @@
const void *a1, const void *a2, const void *a3, const void *a4);
static const struct trace_event qmux_trace_events[] = {
+#define QMUX_EV_QCC_RECV (1ULL << 1)
+ { .mask = QMUX_EV_QCC_RECV, .name = "qcc_recv", .desc = "Rx on QUIC connection" },
+#define QMUX_EV_QCC_SEND (1ULL << 2)
+ { .mask = QMUX_EV_QCC_SEND, .name = "qcc_send", .desc = "Tx on QUIC connection" },
+#define QMUX_EV_QCC_WAKE (1ULL << 3)
+ { .mask = QMUX_EV_QCC_WAKE, .name = "qcc_wake", .desc = "QUIC connection woken up" },
+#define QMUX_EV_QCC_END (1ULL << 4)
+ { .mask = QMUX_EV_QCC_END, .name = "qcc_end", .desc = "QUIC connection terminated" },
+#define QMUX_EV_QCC_NQCS (1ULL << 5)
+ { .mask = QMUX_EV_QCC_NQCS, .name = "qcc_no_qcs", .desc = "QUIC stream not found" },
+#define QMUX_EV_QCS_NEW (1ULL << 6)
+ { .mask = QMUX_EV_QCS_NEW, .name = "qcs_new", .desc = "new QUIC stream" },
+#define QMUX_EV_QCS_RECV (1ULL << 7)
+ { .mask = QMUX_EV_QCS_RECV, .name = "qcs_recv", .desc = "Rx on QUIC stream" },
+#define QMUX_EV_QCS_SEND (1ULL << 8)
+ { .mask = QMUX_EV_QCS_SEND, .name = "qcs_send", .desc = "Tx on QUIC stream" },
+#define QMUX_EV_QCS_END (1ULL << 9)
+ { .mask = QMUX_EV_QCS_END, .name = "qcs_end", .desc = "QUIC stream terminated" },
+#define QMUX_EV_STRM_RECV (1ULL << 10)
+ { .mask = QMUX_EV_STRM_RECV, .name = "strm_recv", .desc = "receiving data for stream" },
+#define QMUX_EV_STRM_SEND (1ULL << 11)
+ { .mask = QMUX_EV_STRM_SEND, .name = "strm_send", .desc = "sending data for stream" },
+#define QMUX_EV_STRM_END (1ULL << 12)
+ { .mask = QMUX_EV_STRM_END, .name = "strm_end", .desc = "detaching app-layer stream" },
{ }
};
@@ -59,12 +83,12 @@
{
struct qcs *qcs;
+ TRACE_ENTER(QMUX_EV_QCS_NEW, qcc->conn);
+
qcs = pool_alloc(pool_head_qcs);
if (!qcs)
goto out;
- fprintf(stderr, "%s: stream ID %lu\n", __func__, id);
-
qcs->qcc = qcc;
qcs->cs = NULL;
qcs->flags = QC_SF_NONE;
@@ -95,6 +119,7 @@
qcs->subs = NULL;
out:
+ TRACE_LEAVE(QMUX_EV_QCS_NEW, qcc->conn, qcs);
return qcs;
}
@@ -116,7 +141,9 @@
int qcs_subscribe(struct qcs *qcs, int event_type, struct wait_event *es)
{
- fprintf(stderr, "%s\n", __func__);
+ struct qcc *qcc = qcs->qcc;
+
+ TRACE_ENTER(QMUX_EV_STRM_SEND|QMUX_EV_STRM_RECV, qcc->conn, qcs);
BUG_ON(event_type & ~(SUB_RETRY_SEND|SUB_RETRY_RECV));
BUG_ON(qcs->subs && qcs->subs != es);
@@ -124,6 +151,14 @@
es->events |= event_type;
qcs->subs = es;
+ if (event_type & SUB_RETRY_RECV)
+ TRACE_DEVEL("subscribe(recv)", QMUX_EV_STRM_RECV, qcc->conn, qcs);
+
+ if (event_type & SUB_RETRY_SEND)
+ TRACE_DEVEL("subscribe(send)", QMUX_EV_STRM_SEND, qcc->conn, qcs);
+
+ TRACE_LEAVE(QMUX_EV_STRM_SEND|QMUX_EV_STRM_RECV, qcc->conn, qcs);
+
return 0;
}
@@ -240,9 +275,11 @@
struct eb64_node *strm_node;
size_t total, diff;
+ TRACE_ENTER(QMUX_EV_QCC_RECV, qcc->conn);
+
strm_node = qcc_get_qcs(qcc, id);
if (!strm_node) {
- fprintf(stderr, "%s: stream not found: %ld\n", __func__, id);
+ TRACE_DEVEL("leaving on stream not found", QMUX_EV_QCC_RECV|QMUX_EV_QCC_NQCS, qcc->conn, NULL, &id);
return 1;
}
@@ -253,7 +290,7 @@
return 2;
if (offset + len <= qcs->rx.offset) {
- fprintf(stderr, "%s: already received STREAM data\n", __func__);
+ TRACE_DEVEL("leaving on already received offset", QMUX_EV_QCC_RECV|QMUX_EV_QCS_RECV, qcc->conn, qcs);
return 1;
}
@@ -265,7 +302,7 @@
return 2;
}
- fprintf(stderr, "%s: new STREAM data\n", __func__);
+ TRACE_DEVEL("newly received offset", QMUX_EV_QCC_RECV|QMUX_EV_QCS_RECV, qcc->conn, qcs);
diff = qcs->rx.offset - offset;
/* TODO do not partially copy a frame if not enough size left. Maybe
@@ -290,6 +327,7 @@
qcs->flags |= QC_SF_FIN_RECV;
out:
+ TRACE_LEAVE(QMUX_EV_QCC_RECV, qcc->conn);
return 0;
}
@@ -344,11 +382,15 @@
*/
int qcc_decode_qcs(struct qcc *qcc, struct qcs *qcs)
{
+ TRACE_ENTER(QMUX_EV_QCS_RECV, qcc->conn, qcs);
+
if (qcc->app_ops->decode_qcs(qcs, qcs->flags & QC_SF_FIN_RECV, qcc->ctx) < 0) {
- fprintf(stderr, "%s: decoding error\n", __func__);
+ TRACE_DEVEL("leaving on decoding error", QMUX_EV_QCS_RECV, qcc->conn, qcs);
return 1;
}
+ TRACE_LEAVE(QMUX_EV_QCS_RECV, qcc->conn, qcs);
+
return 0;
}
@@ -360,9 +402,10 @@
/* detaches the QUIC stream from its QCC and releases it to the QCS pool. */
static void qcs_destroy(struct qcs *qcs)
{
+ struct connection *conn = qcs->qcc->conn;
const uint64_t id = qcs->by_id.key;
- fprintf(stderr, "%s: release stream %llu\n", __func__, qcs->by_id.key);
+ TRACE_ENTER(QMUX_EV_QCS_END, conn, qcs);
if (quic_stream_is_remote(qcs->qcc, id)) {
if (quic_stream_is_bidi(id)) {
@@ -381,12 +424,12 @@
--qcs->qcc->strms[qcs_id_type(qcs->by_id.key)].nb_streams;
pool_free(pool_head_qcs, qcs);
+
+ TRACE_LEAVE(QMUX_EV_QCS_END, conn);
}
static inline int qcc_is_dead(const struct qcc *qcc)
{
- fprintf(stderr, "%s: %lu\n", __func__, qcc->strms[QCS_CLT_BIDI].nb_streams);
-
if (!qcc->strms[QCS_CLT_BIDI].nb_streams && !qcc->task)
return 1;
@@ -413,11 +456,15 @@
{
struct connection *conn = NULL;
+ TRACE_ENTER(QMUX_EV_QCC_END);
+
if (qcc) {
/* The connection must be aattached to this mux to be released */
if (qcc->conn && qcc->conn->ctx == qcc)
conn = qcc->conn;
+ TRACE_DEVEL("freeing qcc", QMUX_EV_QCC_END, conn);
+
if (qcc->wait_event.tasklet)
tasklet_free(qcc->wait_event.tasklet);
@@ -431,13 +478,16 @@
conn->mux = NULL;
conn->ctx = NULL;
+ TRACE_DEVEL("freeing conn", QMUX_EV_QCC_END, conn);
+
conn_stop_tracking(conn);
conn_full_close(conn);
if (conn->destroy_cb)
conn->destroy_cb(conn);
conn_free(conn);
- fprintf(stderr, "conn@%p released\n", conn);
}
+
+ TRACE_LEAVE(QMUX_EV_QCC_END);
}
/* Prepare a STREAM frame for <qcs> instance. First, transfer data from
@@ -461,7 +511,7 @@
int head, left, to_xfer;
int total = 0;
- fprintf(stderr, "%s\n", __func__);
+ TRACE_ENTER(QMUX_EV_QCS_SEND, qcc->conn, qcs);
qc_get_buf(qcs, out);
@@ -527,12 +577,13 @@
}
LIST_APPEND(frm_list, &frm->list);
+
out:
- fprintf(stderr, "%s: sent=%lu total=%d fin=%d id=%llu offset=%lu\n",
- __func__, (long unsigned)b_data(out), total, fin, (ull)qcs->by_id.key, qcs->tx.sent_offset);
+
return total;
err:
+ TRACE_DEVEL("leaving in error", QMUX_EV_QCS_SEND, qcc->conn, qcs);
return -1;
}
@@ -591,8 +642,12 @@
uint64_t first_offset = 0;
char first_stream_frame_type;
+ TRACE_ENTER(QMUX_EV_QCC_SEND, qcc->conn);
+
- if (LIST_ISEMPTY(frms))
+ if (LIST_ISEMPTY(frms)) {
+ TRACE_DEVEL("leaving with no frames to send", QMUX_EV_QCC_SEND, qcc->conn);
return 0;
+ }
retry_send:
first_frm = LIST_ELEM(frms->n, struct quic_frame *, list);
@@ -627,12 +682,14 @@
* Subscribe on it to retry later.
*/
if (!LIST_ISEMPTY(frms)) {
- fprintf(stderr, "%s: remaining frames to send\n", __func__);
+ TRACE_DEVEL("leaving with remaining frames to send, subscribing", QMUX_EV_QCC_SEND, qcc->conn);
qcc->conn->xprt->subscribe(qcc->conn, qcc->conn->xprt_ctx,
SUB_RETRY_SEND, &qcc->wait_event);
return 1;
}
+ TRACE_LEAVE(QMUX_EV_QCC_SEND);
+
return 0;
}
@@ -647,7 +704,7 @@
struct eb64_node *node;
int total = 0;
- fprintf(stderr, "%s\n", __func__);
+ TRACE_ENTER(QMUX_EV_QCC_SEND);
if (qcc->flags & QC_CF_BLK_MFCTL)
return 0;
@@ -690,7 +747,6 @@
qcs->flags &= ~QC_SF_BLK_MROOM;
}
- fprintf(stderr, "%s ret=%d\n", __func__, ret);
qcs->tx.offset += ret;
total += ret;
@@ -705,6 +761,8 @@
qc_send_frames(qcc, &frms);
+ TRACE_LEAVE(QMUX_EV_QCC_SEND);
+
return total;
}
@@ -755,7 +813,6 @@
frm->type = QUIC_FT_MAX_STREAMS_BIDI;
frm->max_streams_bidi.max_streams = qcc->lfctl.ms_bidi +
qcc->lfctl.cl_bidi_r;
- fprintf(stderr, "SET MAX_STREAMS %lu\n", frm->max_streams_bidi.max_streams);
LIST_APPEND(&frms, &frm->list);
if (qc_send_frames(qcc, &frms))
@@ -772,7 +829,7 @@
{
struct qcc *qcc = ctx;
- fprintf(stderr, "%s\n", __func__);
+ TRACE_ENTER(QMUX_EV_QCC_WAKE);
if (qc_is_max_streams_needed(qcc))
qc_send_max_streams(qcc);
@@ -787,6 +844,8 @@
}
}
+ TRACE_LEAVE(QMUX_EV_QCC_WAKE);
+
return NULL;
}
@@ -795,32 +854,35 @@
struct qcc *qcc = ctx;
int expired = tick_is_expired(t->expire, now_ms);
- fprintf(stderr, "%s\n", __func__);
+ TRACE_ENTER(QMUX_EV_QCC_WAKE, qcc ? qcc->conn : NULL);
if (qcc) {
if (!expired) {
- fprintf(stderr, "%s: not expired\n", __func__);
+ TRACE_DEVEL("leaving (not expired)", QMUX_EV_QCC_WAKE, qcc->conn);
return t;
}
if (!qcc_may_expire(qcc)) {
- fprintf(stderr, "%s: cannot expire\n", __func__);
+ TRACE_DEVEL("leaving (cannot expired)", QMUX_EV_QCC_WAKE, qcc->conn);
t->expire = TICK_ETERNITY;
return t;
}
}
- fprintf(stderr, "%s: timeout\n", __func__);
task_destroy(t);
- if (!qcc)
+ if (!qcc) {
+ TRACE_DEVEL("leaving (not more qcc)", QMUX_EV_QCC_WAKE);
return NULL;
+ }
qcc->task = NULL;
if (qcc_is_dead(qcc))
qc_release(qcc);
+ TRACE_LEAVE(QMUX_EV_QCC_WAKE);
+
return NULL;
}
@@ -926,8 +988,7 @@
struct qcs *qcs = cs->ctx;
struct qcc *qcc = qcs->qcc;
- fprintf(stderr, "%s: leaving with tx.buf.data=%lu, tx.xprt_buf.data=%lu\n",
- __func__, b_data(&qcs->tx.buf), b_data(&qcs->tx.xprt_buf));
+ TRACE_ENTER(QMUX_EV_STRM_END, qcc->conn, qcs);
/* TODO on CONNECTION_CLOSE reception, it should be possible to free
* qcs instances. This should be done once the buffering and ACK
@@ -935,6 +996,7 @@
*/
if ((b_data(&qcs->tx.buf) || b_data(&qcs->tx.xprt_buf))) {
+ TRACE_DEVEL("leaving with remaining data, detaching qcs", QMUX_EV_STRM_END, qcc->conn, qcs);
qcs->flags |= QC_SF_DETACH;
return;
}
@@ -946,6 +1008,8 @@
qcc->task->expire = tick_add(now_ms, qcc->timeout);
task_queue(qcc->task);
}
+
+ TRACE_LEAVE(QMUX_EV_STRM_END);
}
/* Called from the upper layer, to receive data */
@@ -958,7 +1022,7 @@
size_t ret = 0;
char fin = 0;
- fprintf(stderr, "%s\n", __func__);
+ TRACE_ENTER(QMUX_EV_STRM_RECV, qcs->qcc->conn, qcs);
qcs_htx = htx_from_buf(&qcs->rx.app_buf);
if (htx_is_empty(qcs_htx)) {
@@ -1012,6 +1076,8 @@
if (ret)
tasklet_wakeup(qcs->qcc->wait_event.tasklet);
+ TRACE_LEAVE(QMUX_EV_STRM_RECV, qcs->qcc->conn, qcs);
+
return ret;
}
@@ -1019,10 +1085,15 @@
size_t count, int flags)
{
struct qcs *qcs = cs->ctx;
+ size_t ret;
+
+ TRACE_ENTER(QMUX_EV_STRM_SEND, qcs->qcc->conn, qcs);
- fprintf(stderr, "%s\n", __func__);
+ ret = qcs->qcc->app_ops->snd_buf(cs, buf, count, flags);
- return qcs->qcc->app_ops->snd_buf(cs, buf, count, flags);
+ TRACE_LEAVE(QMUX_EV_STRM_SEND, qcs->qcc->conn, qcs);
+
+ return ret;
}
/* Called from the upper layer, to subscribe <es> to events <event_type>. The
@@ -1087,6 +1158,11 @@
if (qcs)
chunk_appendf(&trace_buf, " qcs=%p(%llu)", qcs, qcs->by_id.key);
+
+ if (mask & QMUX_EV_QCC_NQCS) {
+ const uint64_t *id = a3;
+ chunk_appendf(&trace_buf, " id=%lu", *id);
+ }
}
}