From 609be50b8f9358f8054257228e5990e50743a6cb Mon Sep 17 00:00:00 2001 From: Evgeny Date: Wed, 3 Jun 2026 19:27:31 +0300 Subject: [PATCH] =?UTF-8?q?feat:=20ETCP=20trace=20logging=20=E2=80=94=20ET?= =?UTF-8?q?CP=5FSEND,=20ETCP=5FRECV,=20SEND=5FQ=5FDRAIN,=20SEND=5FQ=5FACKE?= =?UTF-8?q?D,=20CONSUMER=5FACK,=20ACK=5FSEND?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Six key log points at DEBUG level to trace the full ACK chain: ETCP_SEND — server sends direction A data ETCP_RECV — received any svc_route packet SEND_Q_DRAIN — send_q drained after client ACK SEND_Q_ACKED — server received client ACK (direction A) CONSUMER_ACK — server sends consumer ACK (direction B) ACK_SEND — low-level ACK packet sent --- src/etcp_router.c | 23 ++++++++++++++++++----- 1 file changed, 18 insertions(+), 5 deletions(-) diff --git a/src/etcp_router.c b/src/etcp_router.c index 91e0c244..24ceb60a 100644 --- a/src/etcp_router.c +++ b/src/etcp_router.c @@ -78,9 +78,10 @@ static int router_send_one_flags(struct ETCP_ROUTER_CONN* rconn, const uint8_t* queue_entry_free(entry); queue_dgram_free(entry); if (!seq_flags) rconn->tx_seq--; return -1; } rconn->last_dgram_ts = get_current_timestamp(); - DEBUG_TRACE(DEBUG_CATEGORY_ETCPROUTE, "router_send: seq=%u → %016llx svc_id=%u len=%zu inflight=%d", - seq, (unsigned long long)rconn->remote_node_id, rconn->svc_id, pl_len, - (int32_t)(rconn->tx_seq - rconn->tx_acked)); + DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "ETCP_SEND: svc_id=%u seq=%u len=%zu inflight=%d → %016llx", + rconn->svc_id, seq, pl_len, + (int32_t)(rconn->tx_seq - rconn->tx_acked), + (unsigned long long)rconn->remote_node_id); return etcp_send(conn, entry); } @@ -149,6 +150,9 @@ static void router_close_and_notify(struct ETCP_ROUTER_CONN* rconn) { } static void router_drain_send_q(struct ETCP_ROUTER_CONN* rconn) { + int sq = queue_entry_count(rconn->send_q); + if (sq > 0) DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "SEND_Q_DRAIN: svc_id=%u send_q=%d inflight=%d", + rconn->svc_id, sq, (int32_t)(rconn->tx_seq - rconn->tx_acked)); while (1) { if ((int32_t)(rconn->tx_seq - rconn->tx_acked) >= ROUTER_MAX_INFLIGHT) break; struct ll_entry* e = queue_data_get(rconn->send_q); @@ -224,8 +228,8 @@ static void router_send_ack(struct ETCP_ROUTER_CONN* rconn) { entry->dgram = (uint8_t*)hdr; entry->len = SVC_ROUTE_HDR_SIZE; - DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router_ack: → %016llx svc_id=%u rx_seq=%u", - (unsigned long long)rconn->remote_node_id, rconn->svc_id, rconn->rx_seq); + DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "ACK_SEND: svc_id=%u rx_seq=%u → %016llx", + rconn->svc_id, rconn->rx_seq, (unsigned long long)rconn->remote_node_id); etcp_send(conn, entry); } @@ -325,6 +329,9 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry) size_t pl_len = entry->len - SVC_ROUTE_HDR_SIZE; uint8_t* pl = entry->dgram + SVC_ROUTE_HDR_SIZE; + DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "ETCP_RECV: svc_id=%u seq=%u len=%zu from %016llx", + hdr->svc_id, hdr->seq, pl_len, (unsigned long long)hdr->src_node_id); + if (hdr->dst_node_id == inst->node_id) { // ========== Мы — целевая нода ========== struct ETCP_ROUTER_CONN* rconn = router_conn_find(inst, hdr->src_node_id, hdr->svc_id); @@ -340,6 +347,10 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry) if (rconn) { if ((int32_t)(hdr->seq - rconn->tx_acked) >= 0) { rconn->tx_acked = hdr->seq; + DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "SEND_Q_ACKED: svc_id=%u ack=%u inflight=%d send_q=%d from %016llx", + rconn->svc_id, hdr->seq, (int32_t)(rconn->tx_seq - rconn->tx_acked), + queue_entry_count(rconn->send_q), + (unsigned long long)hdr->src_node_id); } else { DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "router: stale ACK seq=%u tx_acked=%u from %016llx, ignoring", hdr->seq, rconn->tx_acked, (unsigned long long)hdr->src_node_id); @@ -557,6 +568,8 @@ void etcp_router_consumer_ack(struct UTUN_INSTANCE* inst, uint64_t remote_node_i struct ETCP_ROUTER_CONN* rconn = etcp_router_conn_get(inst, remote_node_id, svc_id); if (!rconn) return; rconn->consumer_ack = 1; + DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "CONSUMER_ACK: svc_id=%u rx_seq=%u → %016llx", + svc_id, rconn->rx_seq, (unsigned long long)remote_node_id); router_ack_do_send(rconn); }