diff --git a/lib/debug_config.c b/lib/debug_config.c index 91e9c201..3f5d2171 100644 --- a/lib/debug_config.c +++ b/lib/debug_config.c @@ -127,6 +127,7 @@ static const struct { {"general", DEBUG_CATEGORY_GENERAL}, {"nat", DEBUG_CATEGORY_NAT}, {"keepalive", DEBUG_CATEGORY_KEEPALIVE}, + {"etcp_route", DEBUG_CATEGORY_ETCPROUTE}, {"all", DEBUG_CATEGORY_ALL}, {NULL, DEBUG_CATEGORY_NONE} }; @@ -220,6 +221,7 @@ const char* debug_get_category_name(debug_category_t category_idx) { case DEBUG_CATEGORY_GENERAL: return "GENERAL"; case DEBUG_CATEGORY_NAT: return "NAT"; case DEBUG_CATEGORY_KEEPALIVE: return "KEEPALIVE"; + case DEBUG_CATEGORY_ETCPROUTE: return "ETCPROUTE"; case DEBUG_CATEGORY_NONE: return "NONE"; default: return "UNKNOWN"; } diff --git a/lib/debug_config.h b/lib/debug_config.h index e0991993..9b98e5b4 100644 --- a/lib/debug_config.h +++ b/lib/debug_config.h @@ -59,7 +59,8 @@ typedef int debug_category_t; #define DEBUG_CATEGORY_GENERAL 19 // Messages for user (common log) #define DEBUG_CATEGORY_NAT 20 // EIM NAT module #define DEBUG_CATEGORY_KEEPALIVE 21 // Link keepalive logic -#define DEBUG_CATEGORY_COUNT 22 // Total number of categories +#define DEBUG_CATEGORY_ETCPROUTE 22 // ETCP routing +#define DEBUG_CATEGORY_COUNT 23 // Total number of categories #define DEBUG_CATEGORY_ALL (-1) // special value for all categories /* Debug configuration structure */ diff --git a/src/dummynet.c b/src/dummynet.c index b6c69317..dd728126 100644 --- a/src/dummynet.c +++ b/src/dummynet.c @@ -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; diff --git a/src/etcp.c b/src/etcp.c index e8e5cb46..8eee94b4 100644 --- a/src/etcp.c +++ b/src/etcp.c @@ -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++; diff --git a/src/etcp_api.c b/src/etcp_api.c index a562bc52..17f4528f 100644 --- a/src/etcp_api.c +++ b/src/etcp_api.c @@ -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; } diff --git a/src/etcp_connections.c b/src/etcp_connections.c index e8f5d84e..0e3d56ca 100644 --- a/src/etcp_connections.c +++ b/src/etcp_connections.c @@ -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; } diff --git a/src/etcp_loadbalancer.c b/src/etcp_loadbalancer.c index 40ca7cf6..7bae431e 100644 --- a/src/etcp_loadbalancer.c +++ b/src/etcp_loadbalancer.c @@ -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 diff --git a/src/etcp_router.c b/src/etcp_router.c index 517f06b7..88b3f07e 100644 --- a/src/etcp_router.c +++ b/src/etcp_router.c @@ -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 { diff --git a/src/proxy/icmp_proxy.c b/src/proxy/icmp_proxy.c index dee23536..c5a29234 100644 --- a/src/proxy/icmp_proxy.c +++ b/src/proxy/icmp_proxy.c @@ -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; } diff --git a/src/route_bgp.c b/src/route_bgp.c index f2387059..75348fea 100644 --- a/src/route_bgp.c +++ b/src/route_bgp.c @@ -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); } } } diff --git a/src/route_ping.c b/src/route_ping.c index e6048784..0a276226 100644 --- a/src/route_ping.c +++ b/src/route_ping.c @@ -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; } diff --git a/src/routing.c b/src/routing.c index 23ee548b..e2704551 100644 --- a/src/routing.c +++ b/src/routing.c @@ -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)