jeka
/
utun2
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity
Browse Source

proxy/tun: добавить DEBUG-логи диагностики застревания keep-alive (lwIP IN/OUT/RECVED/RTO/PERSIST + per-conn DIAG)

proxy
evgeny 7 days ago
parent
4353daf913
commit
a20d73d2be
6 changed files with 82 additions and 2 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Split View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 14
      src/lwip_tcp/lwip_tcp.c
  2. 21
      src/lwip_tcp/lwip_tcp_in.c
  3. 4
      src/lwip_tcp/lwip_tcp_priv.h
  4. 42
      src/proxy/tcp_proxy_client.c
  5. 2
      src/proxy/tcp_proxy_client.h
  6. 1
      tests/tcp_proxy_full/client.conf

14
src/lwip_tcp/lwip_tcp.c
Unescape View File

@ -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);

21
src/lwip_tcp/lwip_tcp_in.c
Unescape View File

@ -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:

4
src/lwip_tcp/lwip_tcp_priv.h
Unescape View File

@ -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);

42
src/proxy/tcp_proxy_client.c
Unescape View File

@ -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;
}

2
src/proxy/tcp_proxy_client.h
Unescape View File

@ -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;
};

1
tests/tcp_proxy_full/client.conf
Unescape View File

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

Write Preview
Loading…
Cancel
Save