diff --git a/src/routing_layer/etcp_router.c b/src/routing_layer/etcp_router.c index ef07d725..bfa0dee0 100644 --- a/src/routing_layer/etcp_router.c +++ b/src/routing_layer/etcp_router.c @@ -29,6 +29,11 @@ in ---> {Q} -> [src, etcp] --> ... --> [dst,etcp] -> {asm_q} -> {buf q} ---> out #include "../lib/u_async.h" #include +/* Текущая диагностика файлового сервиса; остальные сервисы не засоряют debug. */ +#define MF_ROUTE_DEBUG(svc, fmt, ...) do { \ + if ((svc) == ETCP_RT_ID_MEMBER_FILES) DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "member_files route: " fmt, ##__VA_ARGS__); \ +} while (0) + // ==================================================================== // Внутренние forward declarations // ==================================================================== @@ -356,7 +361,11 @@ static int router_build_packet(struct ETCP_ROUTER_CONN* rconn, struct ll_entry* static void router_control(struct ETCP_ROUTER_CONN* rconn, struct ETCP_CONN* conn, uint8_t flags, uint64_t peer_id, uint64_t challenge) { if (!conn) conn = router_send_conn(rconn); - if (!conn) { DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router control: no route svc=%u", rconn->svc_id); return; } + if (!conn) { + MF_ROUTE_DEBUG(rconn->svc_id, "control waiting for route group=%llx peer=%llx flags=%02x", + (unsigned long long)rconn->group_id, (unsigned long long)rconn->remote_node_id, flags); + DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router control: no route svc=%u", rconn->svc_id); return; + } struct ll_entry* e = ll_alloc_lldgram(SVC_ROUTE_HDR_SIZE); if (!e) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "router control: allocation failed"); return; } struct SVC_ROUTE_HDR* h = (struct SVC_ROUTE_HDR*)e->dgram; @@ -365,6 +374,9 @@ static void router_control(struct ETCP_ROUTER_CONN* rconn, struct ETCP_CONN* con h->src_node_id = rconn->inst->node_id; h->dst_node_id = rconn->remote_node_id; h->svc_id = rconn->svc_id; h->flags = flags; h->reset_id = rconn->reset_id; h->peer_reset_id = peer_id; h->challenge = challenge; e->len = SVC_ROUTE_HDR_SIZE; + MF_ROUTE_DEBUG(rconn->svc_id, "control tx group=%llx peer=%llx via=%llx flags=%02x local=%llx remote=%llx", + (unsigned long long)rconn->group_id, (unsigned long long)rconn->remote_node_id, (unsigned long long)conn->peer_node_id, + flags, (unsigned long long)h->reset_id, (unsigned long long)peer_id); DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router control: tx group=%016llx peer=%016llx svc=%u flags=%02x local=%016llx remote=%016llx challenge=%016llx", (unsigned long long)rconn->group_id, (unsigned long long)rconn->remote_node_id, rconn->svc_id, flags, @@ -425,6 +437,9 @@ static void router_confirm_peer(struct ETCP_ROUTER_CONN* rconn, const struct SVC if (rconn->handshake_timer) { uasync_cancel_timeout(rconn->inst->ua, rconn->handshake_timer); rconn->handshake_timer = NULL; } rconn->peer_reset_id = peer_id; rconn->peer_sync_done = 1; + MF_ROUTE_DEBUG(rconn->svc_id, "session ready group=%llx peer=%llx local=%llx remote=%llx previous=%llx", + (unsigned long long)rconn->group_id, (unsigned long long)rconn->remote_node_id, (unsigned long long)rconn->reset_id, + (unsigned long long)peer_id, (unsigned long long)previous); DEBUG_INFO(DEBUG_CATEGORY_ETCPROUTE, "router session: group=%016llx peer=%016llx svc=%u local=%016llx remote=%016llx previous=%016llx", (unsigned long long)rconn->group_id, (unsigned long long)rconn->remote_node_id, rconn->svc_id, @@ -581,11 +596,20 @@ static void router_set_no_route(struct ETCP_ROUTER_CONN* rconn) { // Инвариант: send_q непуст ∧ !closed ∧ !no_route ∧ inflight свободен ⇒ waiter зарегистрирован. static void router_send_kick(struct ETCP_ROUTER_CONN* rconn) { if (rconn->closed || rconn->no_route) return; - if (!rconn->peer_reset_id) { if (queue_entry_count(rconn->send_q)) router_handshake_start(rconn); return; } + if (!rconn->peer_reset_id) { + if (queue_entry_count(rconn->send_q)) { + MF_ROUTE_DEBUG(rconn->svc_id, "send waiting for session peer=%llx queued=%d", + (unsigned long long)rconn->remote_node_id, queue_entry_count(rconn->send_q)); + router_handshake_start(rconn); + } + return; + } int retry = rconn->retrans_seq != rconn->retrans_end; if (!retry && queue_entry_count(rconn->send_q) == 0) return; if (!retry && queue_entry_count(rconn->inflight_q) >= (int)router_effective_max_inflight(rconn)) { rconn->send_blocked = 1; + MF_ROUTE_DEBUG(rconn->svc_id, "send blocked inflight=%d limit=%u pending=%d", + queue_entry_count(rconn->inflight_q), router_effective_max_inflight(rconn), queue_entry_count(rconn->send_q)); return; } struct ETCP_CONN* conn = router_send_conn(rconn); @@ -652,6 +676,9 @@ static void router_send_drain_cb(struct ll_queue* q, void* arg) { free_entry(queue_data_get(rconn->send_q)); if (rconn->closed || rconn->reset_id != local_id || rconn->peer_reset_id != peer_id) return; rconn->c_pkts_sent++; + MF_ROUTE_DEBUG(rconn->svc_id, "data tx peer=%llx via=%llx seq=%u bytes=%zu acked=%u inflight=%d pending=%d", + (unsigned long long)rconn->remote_node_id, (unsigned long long)conn->peer_node_id, seq, len, rconn->tx_acked, + queue_entry_count(rconn->inflight_q), queue_entry_count(rconn->send_q)); rconn->last_dgram_ts = get_current_timestamp(); if (!rconn->retrans_timer) router_retrans_schedule(rconn); router_track_inflight_state(rconn); @@ -961,6 +988,7 @@ static void router_send_ack(struct ETCP_ROUTER_CONN* rconn) { rconn->c_ack_sent++; rconn->last_sent_ack_seq = rconn->rx_seq; rconn->last_ack_sent_tb = get_time_tb(); + MF_ROUTE_DEBUG(rconn->svc_id, "ACK tx peer=%llx next_seq=%u", (unsigned long long)rconn->remote_node_id, rconn->rx_seq); } // Запланировать отправку ACK: снять idle-таймер, и либо отправить сразу (интервал истёк), @@ -1065,6 +1093,8 @@ static int router_deliver(struct ETCP_ROUTER_CONN* rconn, struct ETCP_CONN* conn rconn->svc_id, payload_len, rx_flags, (unsigned long long)rconn->remote_node_id, (unsigned long long)inst->node_id); rconn->c_pkts_rcvd++; + MF_ROUTE_DEBUG(rconn->svc_id, "deliver group=%llx peer=%llx seq=%u payload=%zu verified_flags=%02x handler=%p", + (unsigned long long)rconn->group_id, (unsigned long long)rconn->remote_node_id, hdr->seq, payload_len, rx_flags, (void*)cb); cb(conn, svc_entry); return 0; } @@ -1273,8 +1303,11 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry) free_entry(entry); return; } struct SVC_ROUTE_HDR* h = (struct SVC_ROUTE_HDR*)entry->dgram; + MF_ROUTE_DEBUG(h->svc_id, "wire rx group=%llx src=%llx dst=%llx via=%llx seq=%u flags=%02x bytes=%u", + (unsigned long long)h->group_id, (unsigned long long)h->src_node_id, (unsigned long long)h->dst_node_id, + (unsigned long long)conn->peer_node_id, h->seq, h->flags, entry->len); size_t body = router_path_check(conn, entry); - if (!body) { free_entry(entry); return; } + if (!body) { MF_ROUTE_DEBUG(h->svc_id, "wire rejected by path validation"); free_entry(entry); return; } if (h->dst_node_id != inst->node_id) { if (router_path_append(entry, inst->node_id, entry->dgram[entry->len - 1]) < 0) { inst->router_path_errors++; free_entry(entry); return; @@ -1286,6 +1319,8 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry) if (h->flags & (ROUTER_FLAG_ENCRYPTED | ROUTER_FLAG_SIGNED)) { uint8_t* decoded = NULL; size_t len = 0; uint8_t flags = 0; if (route_crypto_decode(inst, entry->dgram, entry->len, &decoded, &len, &flags) != 0) { + MF_ROUTE_DEBUG(h->svc_id, "wire rejected by crypto src=%llx seq=%u flags=%02x", + (unsigned long long)h->src_node_id, h->seq, h->flags); if (rconn) rconn->c_sign_fail++; free_entry(entry); return; } @@ -1316,12 +1351,17 @@ static void etcp_router_recv_cb(struct ETCP_CONN* conn, struct ll_entry* entry) } else if (control == (ROUTER_FLAG_START | ROUTER_FLAG_RST)) { router_confirm_peer(rconn, h); } else if (h->peer_reset_id != rconn->reset_id || h->reset_id != rconn->peer_reset_id) { + MF_ROUTE_DEBUG(h->svc_id, "epoch rejected peer=%llx seq=%u received=%llx/%llx expected=%llx/%llx", + (unsigned long long)h->src_node_id, h->seq, (unsigned long long)h->reset_id, (unsigned long long)h->peer_reset_id, + (unsigned long long)rconn->peer_reset_id, (unsigned long long)rconn->reset_id); DEBUG_DEBUG(DEBUG_CATEGORY_ETCPROUTE, "router epoch mismatch: peer=%016llx svc=%u seq=%u flags=%02x", (unsigned long long)h->src_node_id, h->svc_id, h->seq, h->flags); if (payload_len) router_challenge_peer(rconn, conn, h->reset_id); } else if (control == ROUTER_FLAG_CLOSE) { router_close_and_notify(rconn); } else if (!payload_len) { + MF_ROUTE_DEBUG(h->svc_id, "ACK rx peer=%llx next_seq=%u old_acked=%u sent=%u inflight=%d", + (unsigned long long)h->src_node_id, h->seq, rconn->tx_acked, rconn->tx_sent, queue_entry_count(rconn->inflight_q)); if (!h->challenge) router_handle_ack(inst, rconn, h->seq, h->src_node_id, h->timestamp); } else { rconn->last_recv_pkt_ts = h->timestamp; diff --git a/src/routing_layer/route_crypto.c b/src/routing_layer/route_crypto.c index 9d485983..ea324da2 100644 --- a/src/routing_layer/route_crypto.c +++ b/src/routing_layer/route_crypto.c @@ -7,6 +7,10 @@ #include "../lib/mem.h" #include +#define MF_CRYPTO_DEBUG(svc, fmt, ...) do { \ + if ((svc) == ETCP_RT_ID_MEMBER_FILES) DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "member_files crypto: " fmt, ##__VA_ARGS__); \ +} while (0) + // ECDH-контекст для пира (кэш в inst->e2e_ctx_cache). NULL = нет NODEINFO / ECDH не удался. static struct secure_channel* route_crypto_e2e_ctx(struct UTUN_INSTANCE* inst, uint64_t peer_node_id) { for (int i = 0; i < E2E_CTX_CACHE_SIZE; i++) { @@ -46,6 +50,9 @@ int route_crypto_encode(struct UTUN_INSTANCE* inst, uint64_t peer_node_id, } const uint8_t* pl = base + SVC_ROUTE_HDR_SIZE; size_t pl_len = base_len - SVC_ROUTE_HDR_SIZE; + const struct SVC_ROUTE_HDR* input = (const struct SVC_ROUTE_HDR*)base; + MF_CRYPTO_DEBUG(input->svc_id, "encode peer=%llx seq=%u mode=%02x plain=%zu", + (unsigned long long)peer_node_id, input->seq, mode, pl_len); const uint8_t* body = pl; size_t body_len = pl_len; @@ -53,7 +60,7 @@ int route_crypto_encode(struct UTUN_INSTANCE* inst, uint64_t peer_node_id, if (mode & ROUTE_CRYPTO_ENCRYPT) { struct secure_channel* e2e = route_crypto_e2e_ctx(inst, peer_node_id); - if (!e2e) return -1; + if (!e2e) { MF_CRYPTO_DEBUG(input->svc_id, "encode rejected: no ECDH context"); return -1; } size_t enc_cap = pl_len + SC_NONCE_SIZE + SC_CRC32_SIZE + SC_TAG_SIZE; enc_buf = u_malloc(enc_cap); if (!enc_buf) { DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "route_crypto_encode: enc_buf alloc fail"); return -1; } @@ -86,6 +93,7 @@ int route_crypto_encode(struct UTUN_INSTANCE* inst, uint64_t peer_node_id, if (enc_buf) u_free(enc_buf); *out = dgram; *out_len = total; + MF_CRYPTO_DEBUG(input->svc_id, "encode done seq=%u wire=%zu", input->seq, total); return 0; } @@ -99,6 +107,8 @@ int route_crypto_decode(struct UTUN_INSTANCE* inst, } struct SVC_ROUTE_HDR* hdr = (struct SVC_ROUTE_HDR*)wire; uint8_t fl = hdr->flags & (ROUTER_FLAG_ENCRYPTED | ROUTER_FLAG_SIGNED); + MF_CRYPTO_DEBUG(hdr->svc_id, "decode src=%llx seq=%u flags=%02x wire=%zu", + (unsigned long long)hdr->src_node_id, hdr->seq, fl, wire_len); *rx_flags = fl; const uint8_t* body = wire + SVC_ROUTE_HDR_SIZE; @@ -106,6 +116,7 @@ int route_crypto_decode(struct UTUN_INSTANCE* inst, if (fl & ROUTER_FLAG_SIGNED) { if (body_len < SC_SIGN_SIZE) { + MF_CRYPTO_DEBUG(hdr->svc_id, "decode rejected: signature truncated"); DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "route_crypto_decode: SIGNED packet too short len=%zu from %016llx", wire_len, (unsigned long long)hdr->src_node_id); return -1; @@ -114,31 +125,36 @@ int route_crypto_decode(struct UTUN_INSTANCE* inst, const uint8_t* sig = wire + signed_len; struct TOPO_NODE* sni = topo_node_registry_find(inst->topo_groups, hdr->src_node_id); if (!sni) { + MF_CRYPTO_DEBUG(hdr->svc_id, "decode rejected: source NODEINFO missing"); DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "route_crypto_decode: SIGNED from unknown node %016llx — dropping", (unsigned long long)hdr->src_node_id); return -1; } uint8_t zero[SC_PUBKEY_SIZE] = {0}; if (memcmp(sni->ed25519_public_key, zero, SC_PUBKEY_SIZE) == 0) { + MF_CRYPTO_DEBUG(hdr->svc_id, "decode rejected: source Ed25519 key missing"); DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "route_crypto_decode: no Ed25519 pubkey for node %016llx — dropping", (unsigned long long)hdr->src_node_id); return -1; } if (sc_ed25519_verify(sni->ed25519_public_key, wire, signed_len, sig) != SC_OK) { + MF_CRYPTO_DEBUG(hdr->svc_id, "decode rejected: Ed25519 signature invalid"); DEBUG_WARN(DEBUG_CATEGORY_ETCPROUTE, "route_crypto_decode: signature FAILED for node %016llx svc_id=%u — dropping", (unsigned long long)hdr->src_node_id, hdr->svc_id); return -1; } body_len -= SC_SIGN_SIZE; + MF_CRYPTO_DEBUG(hdr->svc_id, "signature verified src=%llx", (unsigned long long)hdr->src_node_id); } uint8_t* pt_buf = NULL; if (fl & ROUTER_FLAG_ENCRYPTED) { struct secure_channel* e2e = route_crypto_e2e_ctx(inst, hdr->src_node_id); - if (!e2e) return -1; + if (!e2e) { MF_CRYPTO_DEBUG(hdr->svc_id, "decode rejected: no ECDH context"); return -1; } pt_buf = u_malloc(body_len); size_t pt_len = 0; if (!pt_buf || sc_decrypt(e2e, body, body_len, pt_buf, &pt_len) != SC_OK) { + MF_CRYPTO_DEBUG(hdr->svc_id, "decode rejected: AES-CCM decrypt/authentication failed bytes=%zu", body_len); DEBUG_ERROR(DEBUG_CATEGORY_ETCPROUTE, "route_crypto_decode: decrypt FAIL src=%016llx svc=%u len=%zu", (unsigned long long)hdr->src_node_id, hdr->svc_id, body_len); if (pt_buf) u_free(pt_buf); @@ -156,5 +172,7 @@ int route_crypto_decode(struct UTUN_INSTANCE* inst, if (pt_buf) u_free(pt_buf); *out = dgram; *out_len = total; + MF_CRYPTO_DEBUG(hdr->svc_id, "decode done src=%llx seq=%u verified_flags=%02x plain=%zu", + (unsigned long long)hdr->src_node_id, hdr->seq, fl, body_len); return 0; }