diff --git a/src/lwip_tcp/lwip_tcp.c b/src/lwip_tcp/lwip_tcp.c index 9c64a42c..75f3e534 100644 --- a/src/lwip_tcp/lwip_tcp.c +++ b/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; } diff --git a/src/lwip_tcp/lwip_tcp_in.c b/src/lwip_tcp/lwip_tcp_in.c index 476bd2eb..1ce2c9f7 100644 --- a/src/lwip_tcp/lwip_tcp_in.c +++ b/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: diff --git a/src/lwip_tcp/lwip_tcp_priv.h b/src/lwip_tcp/lwip_tcp_priv.h index a254477a..8b0b1cea 100644 --- a/src/lwip_tcp/lwip_tcp_priv.h +++ b/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); diff --git a/src/proxy/tcp_proxy_client.c b/src/proxy/tcp_proxy_client.c index f05f62f9..70eee600 100644 --- a/src/proxy/tcp_proxy_client.c +++ b/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; } diff --git a/src/proxy/tcp_proxy_client.h b/src/proxy/tcp_proxy_client.h index ce37f8c1..45717624 100644 --- a/src/proxy/tcp_proxy_client.h +++ b/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; }; diff --git a/tests/tcp_proxy_full/client.conf b/tests/tcp_proxy_full/client.conf index ab2a71a8..5f6338b5 100644 --- a/tests/tcp_proxy_full/client.conf +++ b/tests/tcp_proxy_full/client.conf @@ -29,4 +29,4 @@ traffic=info tun=info proxy=debug etcp_route=debug -debug=info +debug=debug diff --git a/tests/tcp_proxy_full/exit.conf b/tests/tcp_proxy_full/exit.conf index 22fdd540..5aa7c2b8 100644 --- a/tests/tcp_proxy_full/exit.conf +++ b/tests/tcp_proxy_full/exit.conf @@ -22,3 +22,4 @@ socket=info traffic=info proxy=debug etcp_route=debug +debug=debug diff --git a/tests/tcp_proxy_full/intermediate.conf b/tests/tcp_proxy_full/intermediate.conf index 8d39ce64..7bd6e75b 100644 --- a/tests/tcp_proxy_full/intermediate.conf +++ b/tests/tcp_proxy_full/intermediate.conf @@ -25,4 +25,5 @@ general=info traffic=info etcp_route=debug proxy=debug + debug=debug