From 4f137577d7e4a0ad2d49965640379295277cd139 Mon Sep 17 00:00:00 2001 From: Amaury Denoyelle Date: Thu, 24 Mar 2022 17:10:00 +0100 Subject: [PATCH] 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. --- src/mux_quic.c | 136 ++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 106 insertions(+), 30 deletions(-) diff --git a/src/mux_quic.c b/src/mux_quic.c index ce11772af..8496df730 100644 --- a/src/mux_quic.c +++ b/src/mux_quic.c @@ -22,6 +22,30 @@ static void qmux_trace(enum trace_level level, uint64_t mask, 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_new(struct qcc *qcc, uint64_t id, enum qcs_type type) { 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 @@ struct qcs *qcs_new(struct qcc *qcc, uint64_t id, enum qcs_type type) qcs->subs = NULL; out: + TRACE_LEAVE(QMUX_EV_QCS_NEW, qcc->conn, qcs); return qcs; } @@ -116,7 +141,9 @@ struct buffer *qc_get_buf(struct qcs *qcs, struct buffer *bptr) 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 @@ int qcs_subscribe(struct qcs *qcs, int event_type, struct wait_event *es) 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 @@ int qcc_recv(struct qcc *qcc, uint64_t id, uint64_t len, uint64_t offset, 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 @@ int qcc_recv(struct qcc *qcc, uint64_t id, uint64_t len, uint64_t offset, 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 @@ int qcc_recv(struct qcc *qcc, uint64_t id, uint64_t len, uint64_t offset, 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 @@ int qcc_recv(struct qcc *qcc, uint64_t id, uint64_t len, uint64_t offset, qcs->flags |= QC_SF_FIN_RECV; out: + TRACE_LEAVE(QMUX_EV_QCC_RECV, qcc->conn); return 0; } @@ -344,11 +382,15 @@ int qcc_recv_max_stream_data(struct qcc *qcc, uint64_t id, uint64_t max) */ 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 @@ static int qc_is_max_streams_needed(struct qcc *qcc) /* 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 @@ static void qcs_destroy(struct qcs *qcs) --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 @@ static void qc_release(struct qcc *qcc) { 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 @@ static void qc_release(struct qcc *qcc) 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 instance. First, transfer data from @@ -461,7 +511,7 @@ static int qcs_push_frame(struct qcs *qcs, struct buffer *out, 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 @@ static int qcs_push_frame(struct qcs *qcs, struct buffer *out, } 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 @@ static int qc_send_frames(struct qcc *qcc, struct list *frms) uint64_t first_offset = 0; char first_stream_frame_type; - if (LIST_ISEMPTY(frms)) + TRACE_ENTER(QMUX_EV_QCC_SEND, qcc->conn); + + 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 @@ static int qc_send_frames(struct qcc *qcc, struct list *frms) * 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 @@ static int qc_send(struct qcc *qcc) 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 @@ static int qc_send(struct qcc *qcc) qcs->flags &= ~QC_SF_BLK_MROOM; } - fprintf(stderr, "%s ret=%d\n", __func__, ret); qcs->tx.offset += ret; total += ret; @@ -705,6 +761,8 @@ static int qc_send(struct qcc *qcc) qc_send_frames(qcc, &frms); + TRACE_LEAVE(QMUX_EV_QCC_SEND); + return total; } @@ -755,7 +813,6 @@ static int qc_send_max_streams(struct qcc *qcc) 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 @@ static struct task *qc_io_cb(struct task *t, void *ctx, unsigned int status) { 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 @@ static struct task *qc_io_cb(struct task *t, void *ctx, unsigned int status) } } + TRACE_LEAVE(QMUX_EV_QCC_WAKE); + return NULL; } @@ -795,32 +854,35 @@ static struct task *qc_timeout_task(struct task *t, void *ctx, unsigned int stat 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 @@ static void qc_detach(struct conn_stream *cs) 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 @@ static void qc_detach(struct conn_stream *cs) */ 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 @@ static void qc_detach(struct conn_stream *cs) 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 @@ static size_t qc_rcv_buf(struct conn_stream *cs, struct buffer *buf, 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 @@ static size_t qc_rcv_buf(struct conn_stream *cs, struct buffer *buf, 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 @@ static size_t qc_snd_buf(struct conn_stream *cs, struct buffer *buf, size_t count, int flags) { struct qcs *qcs = cs->ctx; + size_t ret; - fprintf(stderr, "%s\n", __func__); + TRACE_ENTER(QMUX_EV_STRM_SEND, qcs->qcc->conn, qcs); - return qcs->qcc->app_ops->snd_buf(cs, buf, count, flags); + ret = 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 to events . The @@ -1087,6 +1158,11 @@ static void qmux_trace(enum trace_level level, uint64_t mask, 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); + } } }