lwip/proxy: trace PCB lifetime in debug category, drop old noisy debug

src/lwip_tcp/lwip_tcp.c

@@ -189,6 +189,8 @@ void tcp_free(struct tcp_pcb *pcb)
         tcp_free_listen(pcb);
         return;
     }
+    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "LWIP_FREE pcb=%p state=%s lport=%u rport=%u arg=%p",
+                (void*)pcb, tcp_debug_state_str(pcb->state), pcb->local_port, pcb->remote_port, pcb->callback_arg);
     memory_pool_free(pcb->ctx->pcb_pool, pcb);
 }
 
@@ -355,7 +357,11 @@ void tcp_abandon(struct tcp_pcb *pcb, int reset)
     if (!pcb) return;
     if (pcb->state == LISTEN) return;
 
+    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "LWIP_ABANDON pcb=%p state=%s reset=%d errf=%p arg=%p",
+                (void*)pcb, tcp_debug_state_str(pcb->state), reset, (void*)pcb->errf, pcb->callback_arg);
+
     if (pcb->state == TIME_WAIT) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "LWIP_ABANDON_TW pcb=%p lport=%u", (void*)pcb, pcb->local_port);
         TCP_RMV(&pcb->ctx->tw_pcbs, pcb);
         tcp_free(pcb);
         return;
@@ -529,11 +535,6 @@ void tcp_recved(struct tcp_pcb *pcb, uint16_t len)
 
     wnd_inflation = tcp_update_rcv_ann_wnd(pcb);
 
-    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
-        "LWIP_RECVED lport=%u rport=%u len=%u rcv_wnd=%u rcv_ann=%u infl=%u wnd_upd=%d",
-        pcb->local_port, pcb->remote_port, len, pcb->rcv_wnd, pcb->rcv_ann_wnd,
-        (unsigned)wnd_inflation, wnd_inflation >= TCP_WND_UPDATE_THRESHOLD ? 1 : 0);
-
     if (wnd_inflation >= TCP_WND_UPDATE_THRESHOLD) {
         tcp_ack_now(pcb);
         tcp_output(pcb);
@@ -677,10 +678,6 @@ tcp_slowtmr_start:
                     if (pcb->persist_cnt >= backoff_cnt) {
                         int next_slot = 1;
                         if (pcb->snd_wnd == 0) {
-                            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
-                                "LWIP_PERSIST lport=%u rport=%u snd_wnd=0 probe=%u unsent=%d snd_buf=%u",
-                                pcb->local_port, pcb->remote_port, pcb->persist_probe,
-                                tcp_seg_count(pcb->unsent), (unsigned)tcp_sndbuf(pcb));
                             if (tcp_zero_window_probe(pcb) != LERR_OK) next_slot = 0;
                         } else {
                             if (tcp_split_unsent_seg(pcb, (uint16_t)pcb->snd_wnd) == LERR_OK) {
@@ -701,11 +698,6 @@ tcp_slowtmr_start:
                 if (pcb->rtime >= pcb->rto) {
                     lwip_tcp_trace_record(pcb->ctx, 'T', pcb->snd_nxt, 0, pcb->cwnd,
                                           (uint16_t)pcb->rto, pcb->rtime, (uint8_t)pcb->state);
-                    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
-                        "LWIP_RTO lport=%u rport=%u st=%s rtime=%d rto=%d nrtx=%u cwnd=%u snd_wnd=%u aq=%d",
-                        pcb->local_port, pcb->remote_port, tcp_debug_state_str(pcb->state),
-                        pcb->rtime, pcb->rto, pcb->nrtx, pcb->cwnd, pcb->snd_wnd,
-                        tcp_seg_count(pcb->unacked));
                     if ((tcp_rexmit_rto_prepare(pcb) == LERR_OK) || ((pcb->unacked == NULL) && (pcb->unsent != NULL))) {
                         if (pcb->state != SYN_SENT) {
                             uint8_t backoff_idx = LWIP_MIN(pcb->nrtx, sizeof(tcp_backoff) - 1);
@@ -1145,6 +1137,7 @@ struct tcp_pcb *tcp_alloc(struct lwip_tcp_ctx *ctx, uint8_t prio)
         pcb->ssthresh = TCP_SND_BUF;
         pcb->recv = tcp_recv_null;
         pcb->keep_idle = TCP_KEEPIDLE_DEFAULT;
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "LWIP_ALLOC pcb=%p prio=%u", (void*)pcb, prio);
     }
     return pcb;
 }

src/lwip_tcp/lwip_tcp_in.c

@@ -113,13 +113,6 @@ static void pbuf_realloc_local(struct pbuf *p, uint16_t new_len)
     p->tot_len = new_len;
 }
 
-int tcp_seg_count(const struct tcp_seg *seg)
-{
-    int n = 0;
-    while (seg) { n++; seg = seg->next; }
-    return n;
-}
-
 // ============================================================
 //   tcp_input — main entry point
 // ============================================================
@@ -273,15 +266,6 @@ void lwip_tcp_input(struct lwip_tcp_ctx *ctx, struct pbuf *p,
         recv_flags = 0;
         recv_acked = 0;
 
-        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
-            "LWIP_IN lport=%u rport=%u st=%s seq=%u ack=%u flags=%02x len=%u "
-            "rcv_wnd=%u rcv_ann=%u snd_wnd=%u snd_buf=%u cwnd=%u uq=%d aq=%d oq=%d",
-            pcb->local_port, pcb->remote_port, tcp_debug_state_str(pcb->state),
-            (unsigned)seqno, (unsigned)ackno, (unsigned)flags, (unsigned)tcplen,
-            pcb->rcv_wnd, pcb->rcv_ann_wnd, pcb->snd_wnd, (unsigned)tcp_sndbuf(pcb),
-            pcb->cwnd, tcp_seg_count(pcb->unsent),
-            tcp_seg_count(pcb->unacked), tcp_seg_count(pcb->ooseq));
-
         if (flags & TCP_PSH) {
             p->flags |= PBUF_FLAG_PUSH;
         }
@@ -346,11 +330,6 @@ void lwip_tcp_input(struct lwip_tcp_ctx *ctx, struct pbuf *p,
                 tcp_input_pcb = NULL;
                 if (tcp_input_delayed_close(pcb)) goto aborted;
                 tcp_output(pcb);
-                DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
-                    "LWIP_OUT lport=%u rport=%u st=%s rcv_wnd=%u rcv_ann=%u snd_wnd=%u snd_buf=%u cwnd=%u acked=%u fin=%d",
-                    pcb->local_port, pcb->remote_port, tcp_debug_state_str(pcb->state),
-                    pcb->rcv_wnd, pcb->rcv_ann_wnd, pcb->snd_wnd, (unsigned)tcp_sndbuf(pcb),
-                    pcb->cwnd, (unsigned)recv_acked, (recv_flags & TF_GOT_FIN) ? 1 : 0);
             }
         }
     aborted:

src/lwip_tcp/lwip_tcp_priv.h

@@ -188,7 +188,6 @@ extern const uint8_t tcp_persist_backoff[7];
 
 // state name (для логов)
 const char *tcp_debug_state_str(enum tcp_state s);
-int tcp_seg_count(const struct tcp_seg *seg);
 
 // Internal functions
 err_t tcp_send_empty_ack(struct tcp_pcb *pcb);

src/proxy/tcp_proxy_client.c

@@ -51,7 +51,6 @@ static int   tcp_proxy_client_send_data(struct tcp_proxy_client_conn* pc, const
 static void  tcp_proxy_client_tx_queue_drain_cb(struct ll_queue* q, void* arg);
 static void  tcp_proxy_client_pause_resume_cb(struct ll_queue* q, void* arg);
 static void  tcp_proxy_client_retry_timer_cb(void* arg);
-static void  tcp_proxy_client_diag_timer_cb(void* arg);
 
 // ====================================================================
 // Помощник ll_entry
@@ -216,6 +215,7 @@ static err_t tcp_proxy_client_accept_cb(void *arg, struct tcp_pcb *newpcb, err_t
     struct tcp_proxy_client_conn *pc = u_calloc(1, sizeof(struct tcp_proxy_client_conn));
     if (!pc) { DEBUG_ERROR(DEBUG_CATEGORY_PROXY, "TCP proxy client: accept alloc failed"); return LERR_MEM; }
     pc->proxy = p; pc->pcb = newpcb; pc->stream_id = ++p->next_stream_id;
+    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY ACCEPT pcb=%p sid=%08x", (void*)newpcb, pc->stream_id);
     proxy_flow_init(&pc->flow, p->inst, p->ua, p->via_node_id, ETCP_RT_ID_TCP_PROXY_SERVER, pc->stream_id, tcp_proxy_client_flow_wake, pc);
 
     int i;
@@ -251,7 +251,6 @@ static err_t tcp_proxy_client_accept_cb(void *arg, struct tcp_pcb *newpcb, err_t
     if (tcp_proxy_client_send_connect(pc) != 0) { DEBUG_ERROR(DEBUG_CATEGORY_PROXY, "TCP proxy client: send_connect failed sid=%08x to %d.%d.%d.%d:%d", pc->stream_id, pc->dest_ip[0], pc->dest_ip[1], pc->dest_ip[2], pc->dest_ip[3], ntohs(pc->dest_port)); tcp_arg(newpcb, NULL); tcp_abort(newpcb); queue_free(pc->to_lwip); queue_free(pc->tx_queue); u_free(pc); return LERR_ABRT; }
 
     pc->next = p->conns; p->conns = pc; p->conn_count++;
-    pc->diag_timer = uasync_set_timeout(p->ua, 5000, pc, tcp_proxy_client_diag_timer_cb, "tpc_diag");
     DEBUG_INFO(DEBUG_CATEGORY_PROXY, "TCP proxy client: new conn sid=%08x local_port=%u -> %d.%d.%d.%d:%d total_conns=%d snd_wnd=%u mss=%u",
                pc->stream_id, newpcb->local_port, pc->dest_ip[0], pc->dest_ip[1], pc->dest_ip[2], pc->dest_ip[3], ntohs(pc->dest_port), p->conn_count, newpcb->snd_wnd, newpcb->mss);
     return LERR_OK;
@@ -344,28 +343,6 @@ static void tcp_proxy_client_retry_timer_cb(void* arg) {
     }
 }
 
-static void tcp_proxy_client_diag_timer_cb(void* arg) {
-    struct tcp_proxy_client_conn* pc = (struct tcp_proxy_client_conn*)arg;
-    if (!pc || !pc->proxy) return;
-    pc->diag_timer = NULL;
-    if (pc->rem_closed) return;
-    struct tcp_pcb* pcb = pc->pcb;
-    if (!pcb || pcb->state == CLOSED) return;
-    DEBUG_INFO(DEBUG_CATEGORY_DEBUG,
-        "PROXY DIAG sid=%08x st=%s fin_l=%d fin_r=%d "
-        "rcv_wnd=%u rcv_ann=%u snd_wnd=%u snd_buf=%u cwnd=%u "
-        "unsent=%d unacked=%d ooseq=%d "
-        "tx_q=%d to_lwip=%d to_exit=%u from_exit=%u bp=%u err=%d rem_closed=%d",
-        pc->stream_id, tcp_debug_state_str(pcb->state),
-        pc->fin_local, pc->fin_remote,
-        pcb->rcv_wnd, pcb->rcv_ann_wnd, pcb->snd_wnd, (unsigned)tcp_sndbuf(pcb), pcb->cwnd,
-        tcp_seg_count(pcb->unsent), tcp_seg_count(pcb->unacked), tcp_seg_count(pcb->ooseq),
-        pc->tx_queue ? queue_entry_count(pc->tx_queue) : -1,
-        pc->to_lwip ? queue_entry_count(pc->to_lwip) : -1,
-        pc->bytes_to_exit, pc->bytes_from_exit, pc->bp_count, pc->error, pc->rem_closed);
-    pc->diag_timer = uasync_set_timeout(pc->proxy->ua, 5000, pc, tcp_proxy_client_diag_timer_cb, "tpc_diag");
-}
-
 static err_t tcp_proxy_client_recv_cb(void *arg, struct tcp_pcb *pcb, struct pbuf *p, err_t err) {
     struct tcp_proxy_client_conn *pc = (struct tcp_proxy_client_conn *)arg;
     if (!pc || !pc->proxy || pc->rem_closed) { if (p) pbuf_free(p); return LERR_OK; }
@@ -426,6 +403,8 @@ static err_t tcp_proxy_client_sent_cb(void *arg, struct tcp_pcb *pcb, uint16_t l
 
 static void tcp_proxy_client_err_cb(void *arg, err_t err) {
     struct tcp_proxy_client_conn *pc = (struct tcp_proxy_client_conn *)arg;
+    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY ERR_CB pc=%p pcb=%p sid=%08x err=%d rem_closed=%d",
+                (void*)pc, (void*)(pc ? pc->pcb : NULL), pc ? pc->stream_id : 0, err, pc ? pc->rem_closed : 0);
     if (!pc || !pc->proxy || pc->rem_closed) { DEBUG_ERROR(DEBUG_CATEGORY_PROXY, "PROXY tcp_proxy_client_err_cb: pc=%p proxy=%p rem_closed=%d err=%d", (void*)pc, pc ? (void*)pc->proxy : NULL, pc ? pc->rem_closed : 0, err); return; }
     DEBUG_ERROR(DEBUG_CATEGORY_PROXY, "TCP proxy client: error %d sid=%08x fin_local=%d rem_closed=%d",
                  err, pc->stream_id, pc->fin_local, pc->rem_closed);
@@ -444,6 +423,8 @@ static err_t tcp_proxy_client_poll_cb(void *arg, struct tcp_pcb *pcb) {
     if (pc->error) {
         DEBUG_ERROR(DEBUG_CATEGORY_PROXY, "PROXY CLEANUP error sid=%08x", pc->stream_id);
     if (pc->pcb) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY POLL_ABORT pcb=%p state=%s sid=%08x",
+                    (void*)pc->pcb, tcp_debug_state_str(pc->pcb->state), pc->stream_id);
         tcp_arg(pc->pcb, NULL);
         tcp_recv(pc->pcb, NULL);
         tcp_sent(pc->pcb, NULL);
@@ -526,6 +507,7 @@ static void tcp_proxy_client_conn_free(struct tcp_proxy_client_conn *pc) {
     if (!pc) return;
     struct tcp_proxy_client *p = pc->proxy;
     proxy_flow_destroy(&pc->flow);
+    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY FREE pcb=%p sid=%08x", (void*)pc->pcb, pc->stream_id);
     uint32_t pending = pc->to_lwip ? queue_entry_count(pc->to_lwip) : 0;
     DEBUG_INFO(DEBUG_CATEGORY_PROXY, "PROXY FREE sid=%08x total_conns=%d to_lwip_q=%u",
                pc->stream_id, p->conn_count, pending);
@@ -547,7 +529,6 @@ static void tcp_proxy_client_conn_free(struct tcp_proxy_client_conn *pc) {
         queue_free(pc->tx_queue); pc->tx_queue = NULL;
     }
     if (pc->tx_retry_timer) { uasync_cancel_timeout(p->ua, pc->tx_retry_timer); pc->tx_retry_timer = NULL; }
-    if (pc->diag_timer) { uasync_cancel_timeout(p->ua, pc->diag_timer); pc->diag_timer = NULL; }
     if (p && p->inst) etcp_router_cancel_send_ready(p->inst, TOPO_GROUP_UTUN, p->via_node_id, ETCP_RT_ID_TCP_PROXY_SERVER, &pc->tx_waiter);
     u_free(pc);
 }
@@ -558,6 +539,8 @@ static void tcp_proxy_client_conn_free(struct tcp_proxy_client_conn *pc) {
 static void tcp_proxy_client_conn_finish(struct tcp_proxy_client_conn *pc) {
     if (!pc) return;
     if (pc->pcb) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY FINISH pcb=%p state=%s sid=%08x",
+                    (void*)pc->pcb, tcp_debug_state_str(pc->pcb->state), pc->stream_id);
         tcp_arg(pc->pcb, NULL);
         tcp_recv(pc->pcb, NULL);
         tcp_sent(pc->pcb, NULL);
@@ -592,7 +575,7 @@ static void tcp_proxy_client_handle_data(struct tcp_proxy_client* p, struct ETCP
             if (e) { queue_dgram_free(e); queue_entry_free(e); }
             DEBUG_ERROR(DEBUG_CATEGORY_PROXY, "proxy: receive failed sid=%08x", stream_id);
             tcp_proxy_client_send_error(pc);
-            if (pc->pcb) { tcp_arg(pc->pcb, NULL); tcp_err(pc->pcb, NULL); tcp_abort(pc->pcb); pc->pcb = NULL; }
+            if (pc->pcb) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY DATA_ABORT pcb=%p state=%s sid=%08x", (void*)pc->pcb, tcp_debug_state_str(pc->pcb->state), stream_id); tcp_arg(pc->pcb, NULL); tcp_err(pc->pcb, NULL); tcp_abort(pc->pcb); pc->pcb = NULL; }
             tcp_proxy_client_conn_free(pc);
         } else {
             queue_data_put(pc->to_lwip, e);
@@ -608,6 +591,8 @@ static void tcp_proxy_client_handle_close(struct tcp_proxy_client* p, uint32_t s
     DEBUG_INFO(DEBUG_CATEGORY_PROXY, "PROXY REM_CLOSED sid=%08x fin_local=%d pcb_state=%u", stream_id, pc->fin_local, pc->pcb ? pc->pcb->state : 0);
     pc->rem_closed = 1;
     if (pc->pcb) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY CLOSE pcb=%p state=%s sid=%08x",
+                    (void*)pc->pcb, tcp_debug_state_str(pc->pcb->state), stream_id);
         tcp_arg(pc->pcb, NULL);
         tcp_recv(pc->pcb, NULL);
         tcp_sent(pc->pcb, NULL);
@@ -624,6 +609,8 @@ static void tcp_proxy_client_handle_error(struct tcp_proxy_client* p, uint32_t s
     if (!pc) { DEBUG_INFO(DEBUG_CATEGORY_PROXY, "PROXY ERROR sid=%08x — no conn, dropping", stream_id); return; }
     DEBUG_ERROR(DEBUG_CATEGORY_PROXY, "PROXY ERROR from exit sid=%08x fin_local=%d", stream_id, pc->fin_local);
     if (pc->pcb) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY ERROR pcb=%p state=%s sid=%08x",
+                    (void*)pc->pcb, tcp_debug_state_str(pc->pcb->state), stream_id);
         tcp_arg(pc->pcb, NULL);
         tcp_recv(pc->pcb, NULL);
         tcp_sent(pc->pcb, NULL);
@@ -678,6 +665,8 @@ void tcp_proxy_client_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* en
             for (pc = proxy->conns; pc; pc = next) {
                 next = pc->next;
                 if (pc->pcb) {
+                    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "PROXY CLOSE_ALL pcb=%p state=%s sid=%08x",
+                                (void*)pc->pcb, tcp_debug_state_str(pc->pcb->state), pc->stream_id);
                     tcp_arg(pc->pcb, NULL);
                     tcp_recv(pc->pcb, NULL);
                     tcp_sent(pc->pcb, NULL);
@@ -854,7 +843,6 @@ void tcp_proxy_client_destroy(struct tcp_proxy_client* p) {
             queue_free(pc->tx_queue); pc->tx_queue = NULL;
         }
         if (pc->tx_retry_timer) { uasync_cancel_timeout(p->ua, pc->tx_retry_timer); pc->tx_retry_timer = NULL; }
-        if (pc->diag_timer) { uasync_cancel_timeout(p->ua, pc->diag_timer); pc->diag_timer = NULL; }
         if (p->inst) etcp_router_cancel_send_ready(p->inst, TOPO_GROUP_UTUN, p->via_node_id, ETCP_RT_ID_TCP_PROXY_SERVER, &pc->tx_waiter);
         u_free(pc); pc = next;
     }

src/proxy/tcp_proxy_client.h

@@ -54,8 +54,6 @@ struct tcp_proxy_client_conn {
     uint32_t bytes_from_exit;  // байт получено от exit (в lwIP/TUN)
     uint32_t bp_count;         // счётчик backpressure (send fail)
 
-    void*    diag_timer;       // периодический снимок состояния (DEBUG-категория)
-
     uint8_t  dest_ip[4];
     uint16_t dest_port;
 };

tests/tcp_proxy_full/client.conf

@@ -29,4 +29,4 @@ traffic=info
 tun=info
 proxy=debug
 etcp_route=debug
-debug=info
+debug=debug

tests/tcp_proxy_full/exit.conf

@@ -22,3 +22,4 @@ socket=info
 traffic=info
 proxy=debug
 etcp_route=debug
+debug=debug

tests/tcp_proxy_full/intermediate.conf

@@ -25,4 +25,5 @@ general=info
 traffic=info
     etcp_route=debug
     proxy=debug
+    debug=debug