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

Trace file router sessions and crypto decisions in debug

master
evgeny 6 days ago
parent
0706ccce8a
commit
c259a7330b
2 changed files with 63 additions and 5 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. 46
      src/routing_layer/etcp_router.c
  2. 22
      src/routing_layer/route_crypto.c

46
src/routing_layer/etcp_router.c
Unescape View File

@ -29,6 +29,11 @@ in ---> {Q} -> [src, etcp] --> ... --> [dst,etcp] -> {asm_q} -> {buf q} ---> out
#include "../lib/u_async.h"
#include <string.h>
/* Текущая диагностика файлового сервиса; остальные сервисы не засоряют 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;

22
src/routing_layer/route_crypto.c
Unescape View File

@ -7,6 +7,10 @@
#include "../lib/mem.h"
#include <string.h>
#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;
}

Write Preview
Loading…
Cancel
Save