From: Frédéric Lécaille <flecaille@haproxy.com>
Date: Mon, 3 Apr 2023 15:42:05 +0000 (+0200)
Subject: MINOR: quic: Add trace to debug idle timer task issues
X-Git-Tag: v2.8-dev7~110
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=495968ed51b64cc818e32e09eeb412183b701336;p=thirdparty%2Fhaproxy.git

MINOR: quic: Add trace to debug idle timer task issues

Add TRACE_PROTO() call where this is relevant to debug issues about
qc_idle_timer_task() issues.

Must be backported to 2.6 and 2.7.
---

diff --git a/src/quic_conn.c b/src/quic_conn.c
index 2da4165681..5936a53905 100644
--- a/src/quic_conn.c
+++ b/src/quic_conn.c
@@ -726,6 +726,18 @@ static void quic_trace(enum trace_level level, uint64_t mask, const struct trace
 			if (dgram)
 				chunk_appendf(&trace_buf, " dgram.len=%zu", dgram->len);
 		}
+
+		if (mask & QUIC_EV_CONN_IDLE_TIMER) {
+			if (tick_isset(qc->ack_expire))
+				chunk_appendf(&trace_buf, " ack_expire=%ums",
+				              TICKS_TO_MS(tick_remain(now_ms, qc->ack_expire)));
+			if (tick_isset(qc->idle_expire))
+				chunk_appendf(&trace_buf, " idle_expire=%ums",
+				              TICKS_TO_MS(tick_remain(now_ms, qc->idle_expire)));
+			if (tick_isset(qc->idle_timer_task->expire))
+				chunk_appendf(&trace_buf, " expire=%ums",
+				              TICKS_TO_MS(tick_remain(now_ms, qc->idle_timer_task->expire)));
+		}
 	}
 	if (mask & QUIC_EV_CONN_LPKT) {
 		const struct quic_rx_packet *pkt = a2;
@@ -777,6 +789,7 @@ static inline int quic_peer_validated_addr(struct quic_conn *qc)
 void qc_kill_conn(struct quic_conn *qc)
 {
 	TRACE_ENTER(QUIC_EV_CONN_KILL, qc);
+	TRACE_PROTO("killing the connection", QUIC_EV_CONN_KILL, qc);
 	qc->flags |= QUIC_FL_CONN_TO_KILL;
 	task_wakeup(qc->idle_timer_task, TASK_WOKEN_OTHER);
 	TRACE_LEAVE(QUIC_EV_CONN_KILL, qc);
@@ -5615,7 +5628,7 @@ static void qc_idle_timer_do_rearm(struct quic_conn *qc, int arm_ack)
 	unsigned int expire;
 
 	if (stopping && qc->flags & (QUIC_FL_CONN_CLOSING|QUIC_FL_CONN_DRAINING)) {
-		TRACE_STATE("executing idle timer immediately on stopping", QUIC_EV_CONN_IDLE_TIMER, qc);
+		TRACE_PROTO("executing idle timer immediately on stopping", QUIC_EV_CONN_IDLE_TIMER, qc);
 		qc->ack_expire = TICK_ETERNITY;
 		task_wakeup(qc->idle_timer_task, TASK_WOKEN_MSG);
 	}
@@ -5628,12 +5641,13 @@ static void qc_idle_timer_do_rearm(struct quic_conn *qc, int arm_ack)
 				qc->ack_expire = tick_add(now_ms, MS_TO_TICKS(QUIC_ACK_DELAY));
 				qc->idle_timer_task->expire = qc->ack_expire;
 				task_queue(qc->idle_timer_task);
-				TRACE_PROTO("ack timer armed", QUIC_EV_CONN_SSLALERT, qc);
+				TRACE_PROTO("ack timer armed", QUIC_EV_CONN_IDLE_TIMER, qc);
 			}
 		}
 		else {
 			qc->idle_timer_task->expire = tick_first(qc->ack_expire, qc->idle_expire);
 			task_queue(qc->idle_timer_task);
+			TRACE_PROTO("idle timer armed", QUIC_EV_CONN_IDLE_TIMER, qc);
 		}
 	}
 }
@@ -5677,6 +5691,7 @@ struct task *qc_idle_timer_task(struct task *t, void *ctx, unsigned int state)
 		goto requeue;
 	}
 
+	TRACE_PROTO("idle timer task running", QUIC_EV_CONN_IDLE_TIMER, qc);
 	/* Notify the MUX before settings QUIC_FL_CONN_EXP_TIMER or the MUX
 	 * might free the quic-conn too early via quic_close().
 	 */
@@ -7925,7 +7940,7 @@ static struct quic_tx_packet *qc_build_pkt(unsigned char **pos,
 		    qc->ack_expire = TICK_ETERNITY;
 		    qc->idle_timer_task->expire = qc->idle_expire;
 		    task_queue(qc->idle_timer_task);
-		    TRACE_PROTO("ack timer cancelled", QUIC_EV_CONN_TXPKT, qc);
+		    TRACE_PROTO("ack timer cancelled", QUIC_EV_CONN_IDLE_TIMER, qc);
 		}
 	}