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

fix: move debug logs before async operations (queue_put, timer_set, resume) for meaningful log ordering

Browse Source
This commit is contained in:
Evgeny committed 2026-06-02 21:53:51 +03:00
1 parent c5c4967b69
commit fceec1aea6
12 files changed
+71 -72
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

src/dummynet.c
-3
View File
@@ -316,9 +316,6 @@ static void dummynet_delay_callback(void* user_arg) {
dir->stats.queue_max = queue_count + 1;
}
DEBUG_DEBUG(DEBUG_CATEGORY_DUMMYNET, "Dir %d: packet added to queue (size=%d)",
dir_idx, queue_count + 1);
/* Запускаем шейпер если не активен */
if (!dir->shaper_pending) {
dir->shaper_pending = 1;
src/etcp.c
+7 -9
View File
@@ -751,8 +751,8 @@ static void ack_timeout_check(struct ETCP_CONN* etcp) {
// shedule timer
int64_t next_timeout=timeout - elapsed;
if (next_timeout<0) next_timeout=0;
etcp->retrans_timer = uasync_set_timeout(etcp->instance->ua, next_timeout+10, etcp, ack_timeout_cb, "etcp_retrans");
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "[%s] retransmission timer set for %llu units", etcp->log_name, next_timeout);
etcp->retrans_timer = uasync_set_timeout(etcp->instance->ua, next_timeout+10, etcp, ack_timeout_cb, "etcp_retrans");
return;
}
current = etcp->input_wait_ack->head;
@@ -778,8 +778,8 @@ static void input_send_q_cb(struct ll_queue* q, void* arg) {// etcp->input_send_
struct ETCP_CONN* etcp=(struct ETCP_CONN*)arg;
etcp_conn_process_send_queue(etcp);
if (etcp->tx_state==ETCP_TX_STATE_DATA_WAIT) {
queue_resume_callback(etcp->input_send_q);
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "resume input_send_q");
queue_resume_callback(etcp->input_send_q);
} else DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "no resume - link busy");
}
/*
@@ -837,14 +837,12 @@ static void etcp_link_ready_callback(struct ETCP_CONN* etcp) {
if (etcp->tx_state!=ETCP_TX_STATE_LINK_WAIT) return;
etcp->tx_state = ETCP_TX_STATE_DATA_WAIT;
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "resume input_send_q+ack_q; link_wait->data_wait");
queue_resume_callback(etcp->input_send_q);
// queue_resume_callback(etcp->ack_q);
if (etcp->ack_q->count && etcp->ack_resp_timer == NULL) {
ack_response_timer_cb(etcp);
}
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "resume input_send_q+ack_q; link_wait->data_wait");
}
// Process packets in send queue and transmit them
@@ -1163,11 +1161,11 @@ void etcp_output_try_assembly(struct ETCP_CONN* etcp) {
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "move: ETCP -> PN");
// Add to output_queue using the same ETCP_FRAGMENT structure
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "[%s] moving packet id=%u to output_queue (qlen=%d)", etcp->log_name,
next_expected_id, etcp->output_queue->count);
if (queue_data_put(etcp->output_queue, (struct ll_entry*)rx_pkt) == 0) {
delivered_bytes += rx_pkt->ll.len;
delivered_count++;
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "[%s] moved packet id=%u to output_queue (qlen=%d)", etcp->log_name,
next_expected_id, etcp->output_queue->count);
} else {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "[%s] failed to add packet id=%u to output_queue", etcp->log_name,
next_expected_id);
@@ -1402,8 +1400,8 @@ void etcp_conn_input(struct ETCP_DGRAM* pkt) {
queue_data_put_with_index(etcp->ack_q, (struct ll_entry*)p);
if (etcp->ack_resp_timer == NULL) {
etcp->ack_resp_timer = uasync_set_timeout(etcp->instance->ua, ACK_DELAY_TB, etcp, ack_response_timer_cb, "etcp_ack_resp");
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "[%s] set ack_timer for delayed ACK send", etcp->log_name);
etcp->ack_resp_timer = uasync_set_timeout(etcp->instance->ua, ACK_DELAY_TB, etcp, ack_response_timer_cb, "etcp_ack_resp");
}
if (((int32_t)(etcp->last_delivered_id-seq)<0) && (queue_find_data_by_index(etcp->recv_q, &seq)==NULL)) {// проверяем есть ли пакет с этим seq
uint32_t pkt_len=len-5;
@@ -1444,8 +1442,8 @@ void etcp_conn_input(struct ETCP_DGRAM* pkt) {
}
// Copy the actual payload data
memcpy(payload_data, data + 5, pkt_len);
queue_data_put_with_index(etcp->recv_q, (struct ll_entry*)rx_pkt);
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] RX seq=%u need=%u asm_len=%d", etcp->log_name, seq, etcp->last_delivered_id+1, etcp->recv_q->count);
queue_data_put_with_index(etcp->recv_q, (struct ll_entry*)rx_pkt);
if ((int32_t)(seq - etcp->last_delivered_id) == 1) etcp_output_try_assembly(etcp);// пробуем собрать выходную очередь из фрагментов
} else {
etcp->rx_dup_count++;
src/etcp_api.c
+1 -1
View File
@@ -121,13 +121,13 @@ int etcp_send(struct ETCP_CONN* conn, struct ll_entry* entry) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP_API, "etcp_send: pn=%p or input null", pn);
return -1;
}
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP_API, "etcp_send: queued to [%s]", conn->log_name);
int result = queue_data_put(pn->input, entry);
DEBUG_TRACE(DEBUG_CATEGORY_NORMALIZER, "etcp_send after put result=%d", result);
if (result != 0) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP_API, "etcp_send: queue_data_put failed");
return -1;
}
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP_API, "etcp_send: queued to [%s]", conn->log_name);
return 0;
}
src/etcp_connections.c
+4 -4
View File
@@ -67,8 +67,8 @@ void etcp_link_burst_check(struct ETCP_LINK* link) {
void etcp_link_burst_finish(struct ETCP_LINK* link) {
if (!link || !link->etcp || !link->etcp->instance) return;
link->burst_active = 0;
link->burst_resp_timer = uasync_set_timeout(link->etcp->instance->ua, BURST_RESP_TIMEOUT_TB, link, burst_resp_timeout_cb, "burst_resp");
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] burst end id=%u pkt_sz=%u wait_resp", link->etcp->log_name, link->burst_id, link->burst_pkt_size);
link->burst_resp_timer = uasync_set_timeout(link->etcp->instance->ua, BURST_RESP_TIMEOUT_TB, link, burst_resp_timeout_cb, "burst_resp");
if (link->etcp->link_ready_for_send_fn) link->etcp->link_ready_for_send_fn(link->etcp);
}
@@ -276,8 +276,8 @@ static void start_keepalive_timer(struct ETCP_LINK* link) {
}
if (link->keepalive_timer == NULL) {
link->keepalive_timer = uasync_set_timeout(link->etcp->instance->ua, link->keepalive_interval * 10, link, keepalive_timer_cb, "link_keepalive");
DEBUG_DEBUG(DEBUG_CATEGORY_KEEPALIVE, "[%s] Keepalive timer started on link %p (interval=%d ms)", link->etcp->log_name, link, link->keepalive_interval);
link->keepalive_timer = uasync_set_timeout(link->etcp->instance->ua, link->keepalive_interval * 10, link, keepalive_timer_cb, "link_keepalive");
}
}
@@ -1100,6 +1100,8 @@ int etcp_send_ping_to_socket(struct UTUN_INSTANCE* instance, struct ETCP_SOCKET*
DEBUG_ERROR(DEBUG_CATEGORY_CRYPTO, "set key failed");
return -5;
}
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "ping sent nonce=%016llx timeout=%d ulen=%zu",
(unsigned long long)ctx->nonce, timeout_ms, user_data_len);
etcp_send_ping_raw(dgram, e_sock->fd, &sc, addr);
u_free(dgram);
if (instance->pending_pings == NULL) {
@@ -1110,8 +1112,6 @@ int etcp_send_ping_to_socket(struct UTUN_INSTANCE* instance, struct ETCP_SOCKET*
last->next = ctx;
}
ctx->timeout_timer = uasync_set_timeout(instance->ua, timeout_ms * 10, ctx, ping_timeout_cbk, "ping_timeout");
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "ping sent nonce=%016llx timeout=%d ulen=%zu",
(unsigned long long)ctx->nonce, timeout_ms, user_data_len);
return 0;
}
src/etcp_loadbalancer.c
+1 -1
View File
@@ -164,9 +164,9 @@ void etcp_loadbalancer_send(struct ETCP_DGRAM* dgram) {
uint64_t now_tb=get_time_tb();
if (link->shaper_load_time_tb >= now_tb + SHAPER_BURST_DELAY_TB) {
uint64_t wait_tb = link->shaper_load_time_tb - now_tb;
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] scheduling shaper timer (wait_tb=%llu) BW=%d pkt_size=%d", etcp->log_name, (unsigned long long)wait_tb, link->bandwidth, pkt_size);
link->shaper_timer = uasync_set_timeout(link->etcp->instance->ua, wait_tb, link, shaper_timer_cb, "shaper");
if (link->shaper_timer == NULL) DEBUG_ERROR(DEBUG_CATEGORY_TIMERS, "Filed to allocate timer");
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] scheduled shaper timer (wait_tb=%llu) BW=%d pkt_size=%d", etcp->log_name, (unsigned long long)wait_tb, link->bandwidth, pkt_size);
}
// Inactivity correction
src/etcp_router.c
+44 -44
View File
@@ -73,12 +73,12 @@ static int router_send_one_flags(struct ETCP_ROUTER_CONN* rconn, const uint8_t*
struct ETCP_CONN* conn = route_bgp_find_conn_for_node(inst->bgp, rconn->remote_node_id);
if (!conn) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "router_send_one: no route to %016llx svc_id=%u",
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "router_send_one: no route to %016llx svc_id=%u",
(unsigned long long)rconn->remote_node_id, rconn->svc_id);
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_ETCP, "router_send: seq=%u → %016llx svc_id=%u len=%zu inflight=%u",
DEBUG_TRACE(DEBUG_CATEGORY_ETCPROUTE, "router_send: seq=%u → %016llx svc_id=%u len=%zu inflight=%u",
seq, (unsigned long long)rconn->remote_node_id, rconn->svc_id, pl_len,
rconn->tx_seq - rconn->rx_acked);
return etcp_send(conn, entry);
@@ -99,7 +99,7 @@ static void router_send_to(struct UTUN_INSTANCE* inst, uint64_t dst, uint8_t svc
if (!entry) { u_free(hdr); return; }
entry->dgram = (uint8_t*)hdr;
entry->len = SVC_ROUTE_HDR_SIZE;
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "router_send_to: seq_flags=0x%08x → %016llx svc_id=%u",
DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router_send_to: seq_flags=0x%08x → %016llx svc_id=%u",
seq_flags, (unsigned long long)dst, svc_id);
etcp_send(conn, entry);
}
@@ -114,7 +114,7 @@ static void router_send_close_to_service(struct ETCP_ROUTER_CONN* rconn) {
if (!e->dgram) { queue_entry_free(e); return; }
e->dgram[0] = rconn->svc_id;
e->len = 1;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "router_close_svc: svc_id=%u remote=%016llx",
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "router_close_svc: svc_id=%u remote=%016llx",
rconn->svc_id, (unsigned long long)rconn->remote_node_id);
cb(NULL, e);
}
@@ -143,7 +143,7 @@ static void router_close_and_notify(struct ETCP_ROUTER_CONN* rconn) {
}
if (inst->router_conns)
queue_remove_data(inst->router_conns, &rconn->ll);
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "router_conn: closed remote=%016llx svc_id=%u",
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "router_conn: closed remote=%016llx svc_id=%u",
(unsigned long long)rconn->remote_node_id, rconn->svc_id);
queue_entry_free(&rconn->ll);
}
@@ -173,18 +173,18 @@ static void router_send_resume_cb(void* arg) {
static void router_enqueue_send(struct ETCP_ROUTER_CONN* rconn, const uint8_t* payload, size_t pl_len) {
struct ll_entry* qe = queue_entry_new(0);
if (!qe) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router_enqueue_send: queue_entry_new failed"); return; }
if (!qe) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router_enqueue_send: queue_entry_new failed"); return; }
qe->dgram = u_malloc(pl_len);
if (!qe->dgram) { queue_entry_free(qe); return; }
qe->len = pl_len;
if (pl_len > 0) memcpy(qe->dgram, payload, pl_len);
DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router_send_q: queued svc_id=%u inflight=%u send_q=%d",
rconn->svc_id, rconn->tx_seq - rconn->rx_acked, queue_entry_count(rconn->send_q));
queue_data_put(rconn->send_q, qe);
rconn->send_blocked = 1;
if (!rconn->send_resume_timer)
rconn->send_resume_timer = uasync_set_timeout(rconn->inst->ua,
ROUTER_SEND_RESUME_TB, rconn, router_send_resume_cb, "router_send_resume");
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "router_send_q: queued svc_id=%u inflight=%u send_q=%d",
rconn->svc_id, rconn->tx_seq - rconn->rx_acked, queue_entry_count(rconn->send_q));
}
// ====================================================================
@@ -205,12 +205,12 @@ static void router_send_ack(struct ETCP_ROUTER_CONN* rconn) {
struct UTUN_INSTANCE* inst = rconn->inst;
struct ETCP_CONN* conn = route_bgp_find_conn_for_node(inst->bgp, rconn->remote_node_id);
if (!conn) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "router_ack: no route to %016llx svc_id=%u",
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "router_ack: no route to %016llx svc_id=%u",
(unsigned long long)rconn->remote_node_id, rconn->svc_id);
return;
}
struct SVC_ROUTE_HDR* hdr = (struct SVC_ROUTE_HDR*)u_malloc(SVC_ROUTE_HDR_SIZE);
if (!hdr) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router_ack: u_malloc failed"); return; }
if (!hdr) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router_ack: u_malloc failed"); return; }
hdr->cmd = ETCP_ID_SVC_ROUTE;
hdr->dst_node_id = rconn->remote_node_id;
hdr->src_node_id = inst->node_id;
@@ -222,7 +222,7 @@ 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_ETCP, "router_ack: → %016llx svc_id=%u rx_seq=%u",
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);
etcp_send(conn, entry);
}
@@ -260,19 +260,19 @@ static void router_deliver(struct ETCP_ROUTER_CONN* rconn, struct ETCP_CONN* con
struct UTUN_INSTANCE* inst = rconn->inst;
etcp_recv_fn cb = inst->router_bindings.callbacks[rconn->svc_id];
if (!cb) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "router_deliver: no handler for svc_id=%u", rconn->svc_id);
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "router_deliver: no handler for svc_id=%u", rconn->svc_id);
return;
}
size_t entry_len = 1 + payload_len;
struct ll_entry* svc_entry = queue_entry_new(0);
if (!svc_entry) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router_deliver: queue_entry_new failed"); return; }
if (!svc_entry) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router_deliver: queue_entry_new failed"); return; }
svc_entry->len = entry_len;
svc_entry->dgram = u_malloc(entry_len);
if (!svc_entry->dgram) { queue_entry_free(svc_entry); return; }
svc_entry->dgram[0] = rconn->svc_id;
if (payload_len > 0) memcpy(svc_entry->dgram + 1, payload, payload_len);
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "router_deliver: svc_id=%u len=%zu from remote=%016llx",
DEBUG_TRACE(DEBUG_CATEGORY_ETCPROUTE, "router_deliver: svc_id=%u len=%zu from remote=%016llx",
rconn->svc_id, payload_len, (unsigned long long)rconn->remote_node_id);
cb(conn, svc_entry);
}
@@ -299,7 +299,7 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry)
if (!entry) return;
struct UTUN_INSTANCE* inst = conn ? conn->instance : NULL;
if (!inst || entry->len < SVC_ROUTE_HDR_SIZE) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_router: invalid packet inst=%p len=%zu min=%u",
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "etcp_router: invalid packet inst=%p len=%zu min=%u",
(void*)inst, entry->len, (unsigned)SVC_ROUTE_HDR_SIZE);
if (entry) { queue_dgram_free(entry); queue_entry_free(entry); }
return;
@@ -344,7 +344,7 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry)
{
int32_t d = (int32_t)(seq - rconn->rx_seq);
if (d > ROUTER_MAX_INFLIGHT || d < -ROUTER_MAX_INFLIGHT) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router: seq=%u out of bounds, rx_seq=%u (d=%d), dropping",
DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router: seq=%u out of bounds, rx_seq=%u (d=%d), dropping",
seq, rconn->rx_seq, d);
queue_dgram_free(entry); queue_entry_free(entry);
return;
@@ -354,7 +354,7 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry)
// Дубликат (seq уже доставлен или в recv_q)
if (((int32_t)(rconn->rx_seq - seq) > 0) ||
queue_find_data_by_index(rconn->recv_q, &seq)) {
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "router: dup seq=%u rx_seq=%u, dropping", seq, rconn->rx_seq);
DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router: dup seq=%u rx_seq=%u, dropping", seq, rconn->rx_seq);
queue_dgram_free(entry); queue_entry_free(entry);
return;
}
@@ -368,10 +368,10 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry)
qe->len = pl_len;
memcpy(qe->dgram, pl, pl_len);
queue_data_put_with_index(rconn->recv_q, qe);
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "router: queued seq=%u rx_seq=%u recv_q=%d from %016llx svc_id=%u",
DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router: queued seq=%u rx_seq=%u recv_q=%d from %016llx svc_id=%u",
seq, rconn->rx_seq, queue_entry_count(rconn->recv_q),
(unsigned long long)hdr->src_node_id, rconn->svc_id);
queue_data_put_with_index(rconn->recv_q, qe);
if (seq == rconn->rx_seq)
router_try_assembly(rconn, conn);
@@ -382,12 +382,12 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry)
// ========== Транзит ==========
struct ETCP_CONN* next = route_bgp_find_conn_for_node(inst->bgp, hdr->dst_node_id);
if (!next) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_router: no route to %016llx svc_id=%u, dropping",
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "etcp_router: no route to %016llx svc_id=%u, dropping",
(unsigned long long)hdr->dst_node_id, hdr->svc_id);
queue_dgram_free(entry); queue_entry_free(entry);
return;
}
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_router: forwarding svc_id=%u → %016llx via %s",
DEBUG_TRACE(DEBUG_CATEGORY_ETCPROUTE, "etcp_router: forwarding svc_id=%u → %016llx via %s",
hdr->svc_id, (unsigned long long)hdr->dst_node_id, next->log_name);
etcp_send(next, entry);
}
@@ -398,21 +398,21 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry)
// ====================================================================
int etcp_router_init(struct UTUN_INSTANCE* inst) {
if (!inst) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_router_init: NULL instance"); return -1; }
if (!inst) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_init: NULL instance"); return -1; }
memset(&inst->router_bindings, 0, sizeof(inst->router_bindings));
inst->router_conns = queue_new(inst->ua,
ROUTER_CONN_HASH_SIZE, 0, 9, "router_conns");
if (!inst->router_conns) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_router_init: queue_new(router_conns) failed");
DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_init: queue_new(router_conns) failed");
return -1;
}
int ret = etcp_bind(inst, ETCP_ID_SVC_ROUTE, etcp_router_recv_cb);
if (ret != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_router_init: etcp_bind failed, ret=%d", ret);
DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_init: etcp_bind failed, ret=%d", ret);
queue_free(inst->router_conns); inst->router_conns = NULL;
return -1;
}
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_router initialized for node %016llx", (unsigned long long)inst->node_id);
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "etcp_router initialized for node %016llx", (unsigned long long)inst->node_id);
return 0;
}
@@ -443,43 +443,43 @@ void etcp_router_destroy(struct UTUN_INSTANCE* inst) {
inst->router_conns = NULL;
}
memset(&inst->router_bindings, 0, sizeof(inst->router_bindings));
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_router destroyed");
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "etcp_router destroyed");
}
int etcp_router_bind(struct UTUN_INSTANCE* inst, uint8_t svc_id, etcp_recv_fn callback) {
if (!inst) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_router_bind: NULL instance"); return -1; }
if (!callback) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_router_bind: NULL callback for svc_id=%u", svc_id); return -1; }
if (!inst) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_bind: NULL instance"); return -1; }
if (!callback) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_bind: NULL callback for svc_id=%u", svc_id); return -1; }
if (inst->router_bindings.callbacks[svc_id])
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_router_bind: overwriting svc_id=%u", svc_id);
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_bind: overwriting svc_id=%u", svc_id);
inst->router_bindings.callbacks[svc_id] = callback;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_router_bind: svc_id=%u → cb=%p", svc_id, (void*)callback);
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_bind: svc_id=%u → cb=%p", svc_id, (void*)callback);
return 0;
}
int etcp_router_unbind(struct UTUN_INSTANCE* inst, uint8_t svc_id) {
if (!inst) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_router_unbind: NULL instance"); return -1; }
if (!inst) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_unbind: NULL instance"); return -1; }
if (!inst->router_bindings.callbacks[svc_id]) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_router_unbind: svc_id=%u not bound", svc_id);
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_unbind: svc_id=%u not bound", svc_id);
return -1;
}
inst->router_bindings.callbacks[svc_id] = NULL;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_router_unbind: svc_id=%u", svc_id);
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "etcp_router_unbind: svc_id=%u", svc_id);
return 0;
}
int etcp_route_send(struct UTUN_INSTANCE* inst, uint64_t dst_node_id, struct ll_entry* entry) {
if (!inst || !entry) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_route_send: NULL inst=%p entry=%p", (void*)inst, (void*)entry);
DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_route_send: NULL inst=%p entry=%p", (void*)inst, (void*)entry);
if (entry) { queue_dgram_free(entry); queue_entry_free(entry); } return -1;
}
if (!entry->dgram || entry->len < 1) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_route_send: empty entry"); queue_dgram_free(entry); queue_entry_free(entry); return -1;
DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "etcp_route_send: empty entry"); queue_dgram_free(entry); queue_entry_free(entry); return -1;
}
uint8_t svc_id = entry->dgram[0];
size_t payload_len = entry->len - 1;
if (dst_node_id == inst->node_id) {
DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_route_send: loopback svc_id=%u len=%zu", svc_id, payload_len);
DEBUG_TRACE(DEBUG_CATEGORY_ETCPROUTE, "etcp_route_send: loopback svc_id=%u len=%zu", svc_id, payload_len);
if (inst->router_bindings.callbacks[svc_id])
inst->router_bindings.callbacks[svc_id](NULL, entry);
else { queue_dgram_free(entry); queue_entry_free(entry); }
@@ -488,7 +488,7 @@ int etcp_route_send(struct UTUN_INSTANCE* inst, uint64_t dst_node_id, struct ll_
struct ETCP_CONN* etcp_conn = route_bgp_find_conn_for_node(inst->bgp, dst_node_id);
if (!etcp_conn) {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_route_send: no BGP route to %016llx svc_id=%u, dropping",
DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "etcp_route_send: no BGP route to %016llx svc_id=%u, dropping",
(unsigned long long)dst_node_id, svc_id);
queue_dgram_free(entry); queue_entry_free(entry);
return -1;
@@ -544,7 +544,7 @@ struct ETCP_ROUTER_CONN* etcp_router_conn_get(struct UTUN_INSTANCE* inst,
size_t data_size = sizeof(struct ETCP_ROUTER_CONN) - sizeof(struct ll_entry);
rconn = (struct ETCP_ROUTER_CONN*)queue_entry_new(data_size);
if (!rconn) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router_conn_get: queue_entry_new failed"); return NULL; }
if (!rconn) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router_conn_get: queue_entry_new failed"); return NULL; }
rconn->remote_node_id = remote_node_id;
rconn->svc_id = svc_id;
rconn->last_dgram_ts = get_current_timestamp();
@@ -557,19 +557,19 @@ struct ETCP_ROUTER_CONN* etcp_router_conn_get(struct UTUN_INSTANCE* inst,
rconn->send_blocked = 0;
rconn->send_resume_timer = NULL;
rconn->recv_q = queue_new(inst->ua, ROUTER_RECVQ_HASH_SIZE, 0, 4, "router_recv_q");
if (!rconn->recv_q) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router_conn_get: queue_new(recv_q) failed"); queue_entry_free(&rconn->ll); return NULL; }
if (!rconn->recv_q) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router_conn_get: queue_new(recv_q) failed"); queue_entry_free(&rconn->ll); return NULL; }
rconn->send_q = queue_new(inst->ua, 0, 0, 0, "router_send_q");
if (!rconn->send_q) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router_conn_get: queue_new(send_q) failed"); queue_free(rconn->recv_q); queue_entry_free(&rconn->ll); return NULL; }
queue_data_put_with_index(inst->router_conns, &rconn->ll);
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "router_conn: new conn remote=%016llx svc_id=%u",
if (!rconn->send_q) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router_conn_get: queue_new(send_q) failed"); queue_free(rconn->recv_q); queue_entry_free(&rconn->ll); return NULL; }
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "router_conn: new conn remote=%016llx svc_id=%u",
(unsigned long long)remote_node_id, svc_id);
queue_data_put_with_index(inst->router_conns, &rconn->ll);
return rconn;
}
int etcp_router_conn_send(struct ETCP_ROUTER_CONN* rconn,
const uint8_t* data, size_t len) {
if (!rconn || !data || len == 0) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "router_conn_send: invalid args rconn=%p data=%p len=%zu",
DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router_conn_send: invalid args rconn=%p data=%p len=%zu",
(void*)rconn, (const void*)data, len);
return -1;
}
@@ -604,7 +604,7 @@ void etcp_router_conn_close_all_for_node(struct UTUN_INSTANCE* inst, uint64_t re
while ((f = queue_data_get(rconn->send_q)) != NULL) { queue_dgram_free(f); queue_entry_free(f); }
queue_free(rconn->send_q);
}
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "router_conn: closed by node remote=%016llx svc_id=%u",
DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "router_conn: closed by node remote=%016llx svc_id=%u",
(unsigned long long)rconn->remote_node_id, rconn->svc_id);
queue_entry_free(&rconn->ll);
} else {
src/proxy/icmp_proxy.c
+1 -1
View File
@@ -270,8 +270,8 @@ int icmp_proxy_deliver_reply(struct UTUN_INSTANCE* inst,
e->dgram = u_malloc(1 + pkt_len);
e->dgram[0] = 4; memcpy(e->dgram + 1, pkt, pkt_len); e->len = 1 + pkt_len;
u_free(pkt);
queue_data_put(tun->input_queue, e);
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "icmp_proxy: reply delivered to TUN id=0x%04x seq=%u", echo_id, echo_seq);
queue_data_put(tun->input_queue, e);
return 0;
}
src/route_bgp.c
+2 -2
View File
@@ -510,8 +510,8 @@ int route_bgp_add_path(struct NODEINFO_Q* nq, struct ETCP_CONN* conn, uint64_t*
path->hop_count = hop_count;
uint64_t* stored = (uint64_t*)((uint8_t*)path + sizeof(struct NODEINFO_PATH));
memcpy(stored, hop_list, hop_size);
queue_data_put(nq->paths, pe);
DEBUG_TRACE(DEBUG_CATEGORY_BGP, "Added path for node %016llx via conn %s with %d hops", (unsigned long long)nq->node.node_id, conn->log_name, hop_count);
queue_data_put(nq->paths, pe);
return 0;
}
@@ -923,8 +923,8 @@ static void route_bgp_add_to_senders(struct ROUTE_BGP* bgp, struct ETCP_CONN* co
struct ll_entry* item_entry = queue_entry_new(sizeof(struct ROUTE_BGP_CONN_ITEM));
if (item_entry) {
((struct ROUTE_BGP_CONN_ITEM*)item_entry->data)->conn = conn;
queue_data_put(bgp->senders_list, item_entry);
DEBUG_INFO(DEBUG_CATEGORY_BGP, "Added to senders_list: %s", conn->log_name);
queue_data_put(bgp->senders_list, item_entry);
}
}
}
src/route_ping.c
+4 -4
View File
@@ -186,6 +186,10 @@ int route_ping_send_req_addr(struct ROUTE_BGP* bgp, struct ETCP_CONN* to_conn,
e->dgram = (uint8_t*)req_pkt;
e->len = pkt_size;
DEBUG_INFO(DEBUG_CATEGORY_BGP, "request_id=%08x ip=%s port=%u pubkey=%s",
(unsigned)new_req_id,
ip_to_str(&target_ip, AF_INET).str, (unsigned)target_port, pubkey ? "yes" : "no");
int ret = etcp_send(to_conn, e);
if (ret != 0) {
u_free(req_pkt);
@@ -208,10 +212,6 @@ int route_ping_send_req_addr(struct ROUTE_BGP* bgp, struct ETCP_CONN* to_conn,
bgp->ping_pending = pending;
pending->timeout_timer = uasync_set_timeout(bgp->instance->ua, wait_timeout_ms * 10, pending, route_ping_pending_timeout, "route_ping");
DEBUG_INFO(DEBUG_CATEGORY_BGP, "request_id=%08x ip=%s port=%u pubkey=%s",
(unsigned)pending->request_id,
ip_to_str(&target_ip, AF_INET).str, (unsigned)target_port, pubkey ? "yes" : "no");
return 0;
}
src/routing.c
+3 -2
View File
@@ -165,17 +165,18 @@ void route_pkt(struct UTUN_INSTANCE* instance, struct ll_entry* entry, uint64_t
DEBUG_TRACE(DEBUG_CATEGORY_TRAFFIC, "NODE %016llx -> NODE %016llx", (unsigned long long)src_node_id, (unsigned long long)src_node_id);
}
DEBUG_TRACE(DEBUG_CATEGORY_ROUTING, "route_pkt: sending %zu bytes to TUN", ip_len);
int put_err = queue_data_put(instance->tun->input_queue, entry);
instance->routed_packets++;
if (put_err != 0) {
DEBUG_WARN(DEBUG_CATEGORY_ROUTING, "route_pkt: failed to put to TUN: dst=%s err=%d",
ip_to_str(&addr, AF_INET).str, put_err);
instance->dropped_packets++;
instance->routed_packets--;
queue_entry_free(entry);
queue_dgram_free(entry);
return;
}
instance->routed_packets++;
DEBUG_TRACE(DEBUG_CATEGORY_ROUTING, "route_pkt: sent %zu bytes to TUN", ip_len);
}
// Callback for packets from ETCP (via etcp_router_bind id=0)