From a20d73d2bebbc65e330332b505f7aff6a92c9a2f Mon Sep 17 00:00:00 2001 From: evgeny Date: Fri, 25 Sep 2026 22:12:47 +0300 Subject: [PATCH] =?UTF-8?q?proxy/tun:=20=D0=B4=D0=BE=D0=B1=D0=B0=D0=B2?= =?UTF-8?q?=D0=B8=D1=82=D1=8C=20DEBUG-=D0=BB=D0=BE=D0=B3=D0=B8=20=D0=B4?= =?UTF-8?q?=D0=B8=D0=B0=D0=B3=D0=BD=D0=BE=D1=81=D1=82=D0=B8=D0=BA=D0=B8=20?= =?UTF-8?q?=D0=B7=D0=B0=D1=81=D1=82=D1=80=D0=B5=D0=B2=D0=B0=D0=BD=D0=B8?= =?UTF-8?q?=D1=8F=20keep-alive=20(lwIP=20IN/OUT/RECVED/RTO/PERSIST=20+=20p?= =?UTF-8?q?er-conn=20DIAG)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- src/lwip_tcp/lwip_tcp.c | 14 +++++++++++ src/lwip_tcp/lwip_tcp_in.c | 21 ++++++++++++++++ src/lwip_tcp/lwip_tcp_priv.h | 4 +++ src/proxy/tcp_proxy_client.c | 42 ++++++++++++++++++++++++++++++-- src/proxy/tcp_proxy_client.h | 2 ++ tests/tcp_proxy_full/client.conf | 1 + 6 files changed, 82 insertions(+), 2 deletions(-) diff --git a/src/lwip_tcp/lwip_tcp.c b/src/lwip_tcp/lwip_tcp.c index 55bbbe41..daa4c051 100644 --- a/src/lwip_tcp/lwip_tcp.c +++ b/src/lwip_tcp/lwip_tcp.c @@ -528,6 +528,11 @@ 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); @@ -670,6 +675,10 @@ void tcp_slowtmr(struct lwip_tcp_ctx *ctx) 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) { @@ -690,6 +699,11 @@ void tcp_slowtmr(struct lwip_tcp_ctx *ctx) 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); diff --git a/src/lwip_tcp/lwip_tcp_in.c b/src/lwip_tcp/lwip_tcp_in.c index 52d925c7..f6ae604f 100644 --- a/src/lwip_tcp/lwip_tcp_in.c +++ b/src/lwip_tcp/lwip_tcp_in.c @@ -113,6 +113,13 @@ 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 // ============================================================ @@ -266,6 +273,15 @@ 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; } @@ -330,6 +346,11 @@ 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: diff --git a/src/lwip_tcp/lwip_tcp_priv.h b/src/lwip_tcp/lwip_tcp_priv.h index 4ff59d77..f901922b 100644 --- a/src/lwip_tcp/lwip_tcp_priv.h +++ b/src/lwip_tcp/lwip_tcp_priv.h @@ -186,6 +186,10 @@ PACK_STRUCT_END extern const uint8_t tcp_backoff[13]; 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); err_t tcp_send_fin(struct tcp_pcb *pcb); diff --git a/src/proxy/tcp_proxy_client.c b/src/proxy/tcp_proxy_client.c index 5930c406..0ba71f62 100644 --- a/src/proxy/tcp_proxy_client.c +++ b/src/proxy/tcp_proxy_client.c @@ -49,6 +49,7 @@ 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 @@ -191,13 +192,25 @@ static void tcp_proxy_client_feed_from_transport(struct tcp_proxy_client_conn *p uint32_t q_pre = queue_entry_count(pc->to_lwip); while (1) { uint16_t space = tcp_sndbuf(pc->pcb); - if (space < TCP_MSS / 2) break; + if (space < TCP_MSS / 2) { + if (queue_entry_count(pc->to_lwip) > 0) + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, + "PROXY FEED stalled sid=%08x snd_buf=%u to_lwip=%d snd_wnd=%u cwnd=%u", + pc->stream_id, space, queue_entry_count(pc->to_lwip), + pc->pcb->snd_wnd, pc->pcb->cwnd); + break; + } struct ll_entry *e = queue_data_get(pc->to_lwip); if (!e) break; if (e->len <= space) { err_t ret = tcp_write(pc->pcb, e->dgram, e->len, TCP_WRITE_FLAG_COPY); if (ret == LERR_OK) { sent_any = 1; queue_dgram_free(e); queue_entry_free(e); } - else { queue_data_put_first(pc->to_lwip, e); break; } + else { + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, + "PROXY FEED write fail sid=%08x len=%u ret=%d snd_buf=%u q=%d", + pc->stream_id, e->len, ret, space, queue_entry_count(pc->to_lwip) + 1); + queue_data_put_first(pc->to_lwip, e); break; + } } else { queue_data_put_first(pc->to_lwip, e); break; @@ -258,6 +271,7 @@ 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); u_free(pc); return LERR_MEM; } 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,6 +358,28 @@ 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; } @@ -513,6 +549,7 @@ 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); } @@ -794,6 +831,7 @@ 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; } diff --git a/src/proxy/tcp_proxy_client.h b/src/proxy/tcp_proxy_client.h index 141bebb6..e30ea755 100644 --- a/src/proxy/tcp_proxy_client.h +++ b/src/proxy/tcp_proxy_client.h @@ -51,6 +51,8 @@ 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; }; diff --git a/tests/tcp_proxy_full/client.conf b/tests/tcp_proxy_full/client.conf index 8c91af03..5f6338b5 100644 --- a/tests/tcp_proxy_full/client.conf +++ b/tests/tcp_proxy_full/client.conf @@ -29,3 +29,4 @@ traffic=info tun=info proxy=debug etcp_route=debug +debug=debug