diff --git a/src/etcp_connections.c b/src/etcp_connections.c index dd977e97..a0499009 100644 --- a/src/etcp_connections.c +++ b/src/etcp_connections.c @@ -971,9 +971,6 @@ int etcp_encrypt_send(struct ETCP_DGRAM* dgram) { DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "sendto failed, sock_err=%d dst=%s fd=%d", socket_get_error(), sockaddr_storage_to_str(addr).str, dgram->link->conn->fd); dgram->link->send_errors++; errcode=4; goto es_err; - } else { - DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "ETCP SEND %zd bytes to %s fd=%d ne_len=%d", sent, - sockaddr_storage_to_str(addr).str, dgram->link->conn->fd, dgram->noencrypt_len); } return (int)sent; es_err: @@ -1542,10 +1539,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { int errorcode=0; struct ETCP_LINK* link=etcp_link_find_by_addr(e_sock, &addr); - DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "RECV %zd bytes from %s link=%p session_ready=%d", - recv_len, sockaddr_storage_to_str(&addr).str, link, - link && link->etcp ? link->etcp->crypto_ctx.session_ready : -1); - + // Try normal decryption first if we have an established link with session keys // This is the common case for data packets and responses // if (link) { @@ -1555,7 +1549,6 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { if (link!=NULL && link->etcp!=NULL && link->etcp->crypto_ctx.session_ready) { sc_status_t dec_rc = sc_decrypt(&link->etcp->crypto_ctx, data, recv_len, (uint8_t*)&pkt->timestamp, &pkt_len); if (!dec_rc) { - DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "DECRYPT OK link=%p log=%s", link, link->etcp->log_name); goto process_decrypted; } DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "etcp: DECRYPT FAIL rc=%d link=%p log=%s session_ready=%d my_pub=%016llx peer_pub=%016llx", dec_rc, link, link->etcp->log_name, link->etcp->crypto_ctx.session_ready, *(uint64_t*)link->etcp->crypto_ctx.pk->public_key, *(uint64_t*)link->etcp->crypto_ctx.peer_public_key); diff --git a/src/topo_group.c b/src/topo_group.c index 737a9cab..1d8f57e1 100644 --- a/src/topo_group.c +++ b/src/topo_group.c @@ -364,7 +364,9 @@ void topo_group_new_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn) { struct TOPO_NODEQ* peer_nq = topo_node_find_by_id(group, conn->peer_node_id); topo_group_add_to_senders(group, conn); - if (peer_nq && peer_nq->alien) { DEBUG_INFO(DEBUG_CATEGORY_BGP, "peer 0x%016llx is alien, skipping route exchange", (unsigned long long)conn->peer_node_id); return; } + if (peer_nq && peer_nq->alien) { DEBUG_INFO(DEBUG_CATEGORY_BGP, "peer 0x%016llx is alien, skipping route exchange", (unsigned long long)conn->peer_node_id); DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "topo_group_new_conn: peer=%016llx group=%016llx type=%d ch=%s ALIEN=1 — SKIP", (unsigned long long)conn->peer_node_id, (unsigned long long)group->group_id, group->group_type, group->channel_id); return; } + + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "topo_group_new_conn: peer=%016llx group=%016llx type=%d ch=%s alien=%d", (unsigned long long)conn->peer_node_id, (unsigned long long)group->group_id, group->group_type, group->channel_id, peer_nq ? peer_nq->alien : -1); struct ll_entry* entry = conn->instance->connections->head; while (entry) { struct conn_queue_entry* ce = (struct conn_queue_entry*)entry->data; struct ETCP_LINK* l = ce->conn->links; while (l) { if (l->initialized && l->conn && l->nat_check_status < NAT_CHECK_IN_PROGRESS) topo_group_start_link_nat_check(group, l); l = l->next; } entry = entry->next; } @@ -558,6 +560,7 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from uint8_t new_ver = ni->ver; if (nodeinfo1 && (int8_t)(nodeinfo1->last_ver - new_ver) >= 0) { + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "NODEINFO skip (stale ver): node=%016llx cur_ver=%d new_ver=%d from=%s", (unsigned long long)node_id, nodeinfo1->last_ver, new_ver, from->log_name); int new_hops = ni->hop_count + 1; if (new_hops <= MAX_HOPS) { uint64_t hop_list[MAX_HOPS]; @@ -639,12 +642,15 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from sqlite3* sdb = group->instance->topo_groups->topo_sqlite_db; if (sdb) { topo_node_sqlite_node_put(sdb, nodeinfo1); - if (group->group_type == TOPO_GROUP_TYPE_CHAT && group->channel_id[0]) + if (group->group_type == TOPO_GROUP_TYPE_CHAT && group->channel_id[0]) { topo_node_sqlite_member_put(sdb, group->channel_id, node_id, NULL, NULL); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "SQLite member_put: ch=%s node=%016llx", group->channel_id, (unsigned long long)node_id); + } } } if (group->instance->control_srv) control_server_notify_node_change(group->instance->control_srv, nodeinfo1); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "node_updated_cb: node=%016llx has_cb=%d ch=%s type=%d", (unsigned long long)node_id, group->instance->topo_groups->node_updated_cb ? 1 : 0, group->channel_id, group->group_type); if (group->instance->topo_groups->node_updated_cb) group->instance->topo_groups->node_updated_cb(group->instance, node_id, ni->public_key, ni->ed25519_public_key); diff --git a/tools/chatgui/transport/chat_sync.c b/tools/chatgui/transport/chat_sync.c index b8a196c1..82afe7f8 100644 --- a/tools/chatgui/transport/chat_sync.c +++ b/tools/chatgui/transport/chat_sync.c @@ -494,6 +494,8 @@ static void cs_on_conn_up(struct ETCP_CONN* conn, void* arg) { if (peer == 0 || peer == g_cs->inst->node_id) return; if (!conn->initialized) { DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: conn_up SKIP — not initialized peer=%016llx", CS_ID, (unsigned long long)peer); return; } + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: conn_up peer=%016llx pending_invite=%llu links_up=%d", CS_ID, (unsigned long long)peer, (unsigned long long)g_cs->pending_invite_ch_id, conn->links_up); + if (g_cs->pending_invite_ch_id != 0 && !g_cs->info_req_timer) { DEBUG_INFO(DEBUG_CATEGORY_CONNECTIVITY, "%s: conn_up invite path peer=%016llx ch=%llu", CS_ID, (unsigned long long)peer, (unsigned long long)g_cs->pending_invite_ch_id); diff --git a/tools/chatgui/transport/member_sync.c b/tools/chatgui/transport/member_sync.c index b1b225fe..8075ed61 100644 --- a/tools/chatgui/transport/member_sync.c +++ b/tools/chatgui/transport/member_sync.c @@ -228,6 +228,7 @@ static void _on_node_updated(struct UTUN_INSTANCE* inst, uint64_t node_id, (void)x25519; (void)ed25519; if (!inst) return; sqlite3* db = _db(inst); if (!db) return; + int rc = 0; sqlite3_stmt* cs = NULL; if (sqlite3_prepare_v2(db, "SELECT channel_id FROM channels", -1, &cs, NULL) != SQLITE_OK) return; while (sqlite3_step(cs) == SQLITE_ROW) { @@ -238,12 +239,15 @@ static void _on_node_updated(struct UTUN_INSTANCE* inst, uint64_t node_id, sqlite3_stmt* ps = NULL; if (sqlite3_prepare_v2(db, buf, -1, &ps, NULL) == SQLITE_OK) { sqlite3_bind_int64(ps, 1, (sqlite3_int64)node_id); - if (sqlite3_step(ps) == SQLITE_ROW) + if (sqlite3_step(ps) == SQLITE_ROW) { merkle_sync_recompute_path(inst, ch, node_id); + rc++; + } sqlite3_finalize(ps); } } sqlite3_finalize(cs); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: _on_node_updated node=%016llx channels_recomputed=%d", MS_ID, (unsigned long long)node_id, rc); } /* ── Public API ── */ @@ -253,7 +257,7 @@ int member_sync_init(struct UTUN_INSTANCE* inst) { int rc = merkle_sync_init(inst, 0x31, &g_member_ops, inst); if (rc != 0) return rc; topo_groups_set_node_updated_cb(inst->topo_groups, _on_node_updated); - DEBUG_INFO(DEBUG_CATEGORY_CONNECTIVITY, "%s: initialized", MS_ID); + DEBUG_INFO(DEBUG_CATEGORY_CONNECTIVITY, "%s: initialized, merkle_rc=%d cb_registered=%d", MS_ID, rc, inst->topo_groups && inst->topo_groups->node_updated_cb ? 1 : 0); return 0; } diff --git a/tools/chatgui/transport/merkle_sync.c b/tools/chatgui/transport/merkle_sync.c index 96b2f685..80f58a0b 100644 --- a/tools/chatgui/transport/merkle_sync.c +++ b/tools/chatgui/transport/merkle_sync.c @@ -174,12 +174,12 @@ static int _get_level_hashes(struct merkle_sync* ms, const char* ns, /* ── Send helpers ── */ static struct ETCP_CONN* ms_find_conn_for_node(struct UTUN_INSTANCE* inst, uint64_t node_id) { - if (!inst->connections) return NULL; + if (!inst->connections) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: find_conn — inst->connections is NULL", MS_ID); return NULL; } struct ll_entry* e = queue_find_data_by_index(inst->connections, (const uint8_t*)&node_id); - if (e) { - struct conn_queue_entry* ce = (struct conn_queue_entry*)e->data; - if (ce->conn->initialized && ce->conn->links_up) return ce->conn; - } + if (!e) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: find_conn — node=%016llx NOT FOUND in connections", MS_ID, (unsigned long long)node_id); return NULL; } + struct conn_queue_entry* ce = (struct conn_queue_entry*)e->data; + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: find_conn — node=%016llx found=%d initialized=%d links_up=%d", MS_ID, (unsigned long long)node_id, 1, ce->conn->initialized, ce->conn->links_up); + if (ce->conn->initialized && ce->conn->links_up) return ce->conn; return NULL; } @@ -197,6 +197,7 @@ static int _send_msg(struct merkle_sync* ms, uint64_t peer, if (!conn) { DEBUG_ERROR(DEBUG_CATEGORY_CONNECTIVITY, "%s: no conn for node %016llx", MS_ID, (unsigned long long)peer); u_free(buf); queue_entry_free(entry); return -1; } int r = etcp_send(conn, entry); if (r != 0) { u_free(buf); queue_entry_free(entry); } + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: send OK peer=%016llx len=%zu rc=%d", MS_ID, (unsigned long long)peer, len, r); return r; } @@ -601,6 +602,7 @@ int merkle_sync_start(struct UTUN_INSTANCE* inst, uint64_t peer, _ensure_table(ms); struct ms_session* s = _session_find(ms, peer, ns); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "%s: start peer=%016llx ns=%s new=%d initialized=%d", MS_ID, (unsigned long long)peer, ns, s ? 0 : 1, ms->initialized); if (!s) { s = u_calloc(1, sizeof(*s)); if (!s) return -1;