From e51d8ddda23053047b70d4e353953b721b3c2509 Mon Sep 17 00:00:00 2001 From: evgeny Date: Wed, 5 Aug 2026 14:15:43 +0300 Subject: [PATCH] =?UTF-8?q?chatgui:=20fix=20ERROR=E2=86=92WARN/DEBUG=20for?= =?UTF-8?q?=20normal=20situations?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - member_sync apply_items: empty payload is normal sync completion, not error - topo_node_sqlite node_load: no addresses is normal for stub/seed nodes - conn_mgr_core: node skipped when not in routing (normal for nodes w/o addrs) - topo_group send_nodeinfo: downgrade ERROR→WARN in DEBUG category - db_sync INIT_RESP: protocol details belong in DEBUG, not INFO --- src/chat/db_sync.c | 2 +- src/chat/member_sync.c | 2 +- src/routing_layer/conn_mgr_core.c | 2 +- src/routing_layer/topo_group.c | 16 +++++++------- src/routing_layer/topo_group_connect.c | 20 ++++++++--------- src/routing_layer/topo_node.c | 8 +++++-- src/routing_layer/topo_node_sqlite.c | 2 +- src/transport_layer/etcp.c | 16 +++++++++----- src/transport_layer/etcp.h | 3 ++- src/transport_layer/etcp_connections.c | 30 ++++++++++++++++---------- src/transport_layer/etcp_dump.c | 4 ++-- src/transport_layer/pkt_normalizer.c | 4 ++-- tests/test_etcp_reconnect.c | 2 +- tests/test_pkt_normalizer_standalone.c | 4 ++-- 14 files changed, 66 insertions(+), 49 deletions(-) diff --git a/src/chat/db_sync.c b/src/chat/db_sync.c index 71cea6a9..b807b60b 100644 --- a/src/chat/db_sync.c +++ b/src/chat/db_sync.c @@ -837,7 +837,7 @@ static void db_handle_init_resp(struct DB_SYNC_INSTANCE* si, uint64_t src, const uint64_t my_ch8 = 0; uint32_t mc = db_count(si); if (mc > 0 && tp < mc) db_chain_hash8_at(si, tp, &my_ch8); - DEBUG_INFO(DEBUG_CATEGORY_CHAT_SYNC, "sync [%s:%04llX] ← INIT_RESP: tp=%u my=%u my_ch8=%016llX peer_ch8=%016llX has_tail=%u sc=%d", + DEBUG_DEBUG(DEBUG_CATEGORY_CHAT_SYNC, "sync [%s:%04llX] ← INIT_RESP: tp=%u my=%u my_ch8=%016llX peer_ch8=%016llX has_tail=%u sc=%d", SI_SHRT(si), (unsigned long long)(src >> 16), tp, mc, my_ch8, peer_ch8, has_tail, sc); struct SI_PEER* sp = si_peer_find(si, src); diff --git a/src/chat/member_sync.c b/src/chat/member_sync.c index 86ecaa71..f018fed1 100644 --- a/src/chat/member_sync.c +++ b/src/chat/member_sync.c @@ -294,7 +294,7 @@ void member_sync_remove_props_cbk(node_props_changed_fn fn, void* arg) { static int _member_apply_items(void* ctx, const char* ns, uint64_t from_peer, const uint8_t* data, size_t len) { struct UTUN_INSTANCE* inst = (struct UTUN_INSTANCE*)ctx; - if (len < 2) { DEBUG_ERROR(DEBUG_CATEGORY_MEMBER_SYNC, "%s: apply_items — len=%zu < 2", MS_ID, len); return -1; } + if (len < 2) { DEBUG_DEBUG(DEBUG_CATEGORY_MEMBER_SYNC, "%s: apply_items — no items from peer=%016llx ns=%.*s (empty, sync complete)", MS_ID, (unsigned long long)from_peer, (int)strnlen(ns, 32), ns); return 0; } uint16_t count; memcpy(&count, data, 2); DEBUG_TRACE(DEBUG_CATEGORY_MEMBER_SYNC, "%s: apply_items ns=%s count=%u from=%016llx", MS_ID, ns, count, (unsigned long long)from_peer); diff --git a/src/routing_layer/conn_mgr_core.c b/src/routing_layer/conn_mgr_core.c index c487cc2d..4f683c87 100644 --- a/src/routing_layer/conn_mgr_core.c +++ b/src/routing_layer/conn_mgr_core.c @@ -396,7 +396,7 @@ int conn_mgr_open(struct CONN_MGR* mgr, uint64_t node_id, uint32_t idle_timeout_ } else DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "conn_mgr: failed to alloc TOPO_GROUP_NODE for DB node 0x%016llx", (unsigned long long)node_id); } } - if (!target) { DEBUG_ERROR(DEBUG_CATEGORY_GENERAL, "node 0x%016llx not found", (unsigned long long)node_id); return -1; } + if (!target) { DEBUG_WARN(DEBUG_CATEGORY_GENERAL, "node 0x%016llx skipped — not in routing, no active connections", (unsigned long long)node_id); return -1; } struct CONN_MGR_ENTRY* entry = cm_find_entry(mgr, node_id); diff --git a/src/routing_layer/topo_group.c b/src/routing_layer/topo_group.c index e82e24cf..a34acc14 100644 --- a/src/routing_layer/topo_group.c +++ b/src/routing_layer/topo_group.c @@ -35,7 +35,7 @@ static void topo_group_send_table_request(struct TOPO_GROUP* group, struct ETCP_CONN* conn) { if (!group || !conn) return; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "Sending table request to %s", conn->log_name); + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "Sending table request to %s grp=%016llx", conn->log_name, (unsigned long long)group->group_id); struct TOPOMSG_TABLE_REQ* req = u_calloc(1, sizeof(struct TOPOMSG_TABLE_REQ)); if (!req) return; req->cmd = ETCP_ID_TOPO_ENTRY; @@ -167,17 +167,17 @@ static void topo_group_receive_cbk(struct ETCP_CONN* from_conn, struct ll_entry* struct TOPO_GROUP* group = topo_groups_find(instance->topo_groups, pkt_group_id); if (!group) { - DEBUG_WARN(DEBUG_CATEGORY_BGP, "BGP recv %s from %s: group %016llx not found, dropping", group_subcmd_name(subcmd), from_conn->log_name, (unsigned long long)pkt_group_id); + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "BGP recv %s from %s: group %016llx not found, dropping", group_subcmd_name(subcmd), from_conn->log_name, (unsigned long long)pkt_group_id); queue_dgram_free(entry); queue_entry_free(entry); return; } - DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP recv %s from %s len=%zu group=%016llx", group_subcmd_name(subcmd), from_conn->log_name, entry->len, (unsigned long long)pkt_group_id); + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "BGP recv %s from %s len=%zu group=%016llx", group_subcmd_name(subcmd), from_conn->log_name, entry->len, (unsigned long long)pkt_group_id); if (subcmd == TOPO_SUBCMD_NODEINFO) { DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BGP recv NODEINFO from=%s nid=%016llx ver=%d grp=%016llx", from_conn->log_name, (unsigned long long)((struct TOPOMSG_NODEINFO_PKT*)data)->node.node_id, ((struct TOPOMSG_NODEINFO_PKT*)data)->node.ver, (unsigned long long)((struct TOPOMSG_NODEINFO_PKT*)data)->node.group_id); } if (subcmd == TOPO_SUBCMD_NODEINFO) { nodeinfo_dump_log(data, entry->len); topo_group_process_nodeinfo(group, from_conn, data, entry->len); } else if (subcmd == TOPO_SUBCMD_WITHDRAW) topo_group_process_withdraw(group, from_conn, data, entry->len); else if (subcmd == TOPO_SUBCMD_REQUEST_TABLE) topo_group_handle_request_table(group, from_conn); - else if (subcmd == TOPO_SUBCMD_TABLE_COMPLETE) { etcp_set_routing_exchange_state(from_conn, 3); DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP initial sync complete with %s", from_conn->log_name); } + else if (subcmd == TOPO_SUBCMD_TABLE_COMPLETE) { etcp_set_routing_exchange_state(from_conn, 3); DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP sync complete with %s: %d nodes grp=%016llx", from_conn->log_name, queue_entry_count(group->nodes), (unsigned long long)group->group_id); } else if (subcmd == TOPO_SUBCMD_ERR_GROUP_MISMATCH) { if (entry->len >= sizeof(struct TOPOMSG_ERR_GROUP_MISMATCH)) { struct TOPOMSG_ERR_GROUP_MISMATCH* err = (struct TOPOMSG_ERR_GROUP_MISMATCH*)data; @@ -482,7 +482,7 @@ void topo_group_remove_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn) { topo_group_connect_on_down(group, conn); - DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP peer removed: %s nodes=%d", conn->log_name, nodes_removed); + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP peer removed: %s nodes=%d grp=%016llx", conn->log_name, nodes_removed, (unsigned long long)group->group_id); } @@ -607,7 +607,7 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from return 0; } - DEBUG_INFO(DEBUG_CATEGORY_BGP, "NODEINFO: node=%016llx ver=%d v4s=%d v4a=%d v6s=%d v6a=%d hops=%d from=%s", + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "NODEINFO: node=%016llx ver=%d v4s=%d v4a=%d v6s=%d v6a=%d hops=%d from=%s", (unsigned long long)node_id, new_ver, ni->local_v4_sockets, ni->local_v4_addrs, ni->local_v6_sockets, ni->local_v6_addrs, ni->hop_count, from->log_name); @@ -631,7 +631,7 @@ int topo_group_process_nodeinfo(struct TOPO_GROUP* group, struct ETCP_CONN* from } { int v4c = topo_list_count((struct _topo_head*)new_ni->v4_addrs); int v6c = topo_list_count((struct _topo_head*)new_ni->v6_addrs); - DEBUG_INFO(DEBUG_CATEGORY_BGP, "NODEINFO deser: nid=%016llx v4a=%d v6a=%d from=%s", + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "NODEINFO deser: nid=%016llx v4a=%d v6a=%d from=%s", (unsigned long long)node_id, v4c, v6c, from->log_name); } DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "NODEINFO deserialized: nid=%016llx new_ver=%d flags=0x%02x ed=%016llx", (unsigned long long)node_id, new_ni->ver, new_ni->flags, *(uint64_t*)new_ni->ed25519_public_key); @@ -794,7 +794,7 @@ void topo_group_send_nodeinfo(struct TOPO_GROUP* group, struct TOPO_GROUP_NODE* p[0] = ETCP_ID_TOPO_ENTRY; p[1] = TOPO_SUBCMD_NODEINFO; struct TOPO_NODE* sni = topo_node_registry_find(group->instance->topo_groups, node->node_id); - if (!sni) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: node %016llx NOT in registry — skip forward to %s", (unsigned long long)node->node_id, conn->log_name); u_free(p); return; } + if (!sni) { DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: node %016llx NOT in registry — skip forward to %s", (unsigned long long)node->node_id, conn->log_name); u_free(p); return; } DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: node %016llx ver=%d grp=%016llx to conn=%s", (unsigned long long)node->node_id, sni->ver, (unsigned long long)sni->group_id, conn->log_name); int ser_len = topo_node_serialize(sni, node, p + 2, max_sz - 2, cumulative_rtt); if (ser_len < 0) { DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "send_nodeinfo: serialize failed for node %016llx", (unsigned long long)node->node_id); u_free(p); return; } diff --git a/src/routing_layer/topo_group_connect.c b/src/routing_layer/topo_group_connect.c index 2915b108..12376bf4 100644 --- a/src/routing_layer/topo_group_connect.c +++ b/src/routing_layer/topo_group_connect.c @@ -82,7 +82,7 @@ int topo_group_connect_init(struct TOPO_GROUP* group) { } gc->phase = TGC_PHASE_ONE; gc->pending = count; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: ch=%s Phase 1 launching %d connects", TGC_ID, group->channel_id, count); + DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase 1 launching %d connects ch=%s grp=%016llx", TGC_ID, count, group->channel_id, (unsigned long long)group->group_id); for (int i = 0; i < count && gc->handle_count < TGC_MAX_HANDLES; i++) { DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "%s: Phase1 connect to 0x%016llx (%d/%d)", TGC_ID, (unsigned long long)ids[i], i + 1, count); conn_mgr_open_invite(group->instance, group->group_id, NULL, ids[i], tgc_callback, gc, @@ -144,8 +144,8 @@ void topo_group_connect_on_up(struct TOPO_GROUP* group, struct ETCP_CONN* conn) gc->active_conn_count++; sqlite3* db = group->instance->topo_sqlite_db; if (db) topo_node_sqlite_set_connected(db, group->channel_id, peer, 1); - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: UP peer=0x%016llx ch=%s active=%d", - TGC_ID, (unsigned long long)peer, group->channel_id, gc->active_conn_count); + DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: UP peer=0x%016llx ch=%s grp=%016llx active=%d", + TGC_ID, (unsigned long long)peer, group->channel_id, (unsigned long long)group->group_id, gc->active_conn_count); } void topo_group_connect_on_down(struct TOPO_GROUP* group, struct ETCP_CONN* conn) { @@ -213,7 +213,7 @@ static void tgc_callback(struct CONN_MGR_HANDLE* h, uint64_t node_id, uint64_t g case TGC_PHASE_ONE: gc->pending--; if (ok) gc->connected_count++; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase1 result node=0x%016llx %s pending=%d connected=%d", + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "%s: Phase1 result node=0x%016llx %s pending=%d connected=%d", TGC_ID, (unsigned long long)node_id, ok ? "OK" : "FAIL", gc->pending, gc->connected_count); break; case TGC_PHASE_TWO: @@ -245,8 +245,6 @@ static void tgc_phase1_timeout(void* arg) { struct TOPO_GROUP_CONNECT* gc = (struct TOPO_GROUP_CONNECT*)arg; gc->phase_timer = NULL; if (gc->phase != TGC_PHASE_ONE) return; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase1 timeout connected=%d pending=%d ch=%s", - TGC_ID, gc->connected_count, gc->pending, gc->group->channel_id); sqlite3* db = gc->group->instance->topo_sqlite_db; uint64_t* ids = NULL; int count = 0; @@ -284,17 +282,17 @@ static void tgc_phase2_try_next(struct TOPO_GROUP_CONNECT* gc) { topo_node_sqlite_get_public_peers(db, gc->group->channel_id, &gc->candidate_ids, &gc->candidate_count, gc->group->instance->node_id); gc->cursor = 0; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase2 loaded %d public peers for ch=%s", + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "%s: Phase2 loaded %d public peers for ch=%s", TGC_ID, gc->candidate_count, gc->group->channel_id); } while (gc->cursor < gc->candidate_count) { uint64_t nid = gc->candidate_ids[gc->cursor++]; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase2 trying 0x%016llx (%d/%d)", TGC_ID, + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "%s: Phase2 trying 0x%016llx (%d/%d)", TGC_ID, (unsigned long long)nid, gc->cursor, gc->candidate_count); conn_mgr_open_invite(gc->group->instance, gc->group->group_id, NULL, nid, tgc_callback, gc, NULL); return; } - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase2 exhausted — no connections, ch=%s", TGC_ID, gc->group->channel_id); + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "%s: Phase2 exhausted — no connections, ch=%s", TGC_ID, gc->group->channel_id); gc->phase = TGC_PHASE_THREE; gc->candidate_count = 0; tgc_phase3_try_next(gc); } @@ -310,12 +308,12 @@ static void tgc_phase3_try_next(struct TOPO_GROUP_CONNECT* gc) { topo_node_sqlite_get_local_peers(db, gc->group->channel_id, &gc->candidate_ids, &gc->candidate_count, gc->group->instance->node_id); gc->cursor = 0; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase3 loaded %d local peers for ch=%s", + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "%s: Phase3 loaded %d local peers for ch=%s", TGC_ID, gc->candidate_count, gc->group->channel_id); } while (gc->cursor < gc->candidate_count) { uint64_t nid = gc->candidate_ids[gc->cursor++]; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "%s: Phase3 trying 0x%016llx (%d/%d)", TGC_ID, + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "%s: Phase3 trying 0x%016llx (%d/%d)", TGC_ID, (unsigned long long)nid, gc->cursor, gc->candidate_count); conn_mgr_open_invite(gc->group->instance, gc->group->group_id, NULL, nid, tgc_callback, gc, NULL); return; diff --git a/src/routing_layer/topo_node.c b/src/routing_layer/topo_node.c index f76a2de0..364498ac 100644 --- a/src/routing_layer/topo_node.c +++ b/src/routing_layer/topo_node.c @@ -760,8 +760,12 @@ int topo_group_update_my_nodeinfo(struct UTUN_INSTANCE* instance, struct TOPO_GR lq->subnets = r; } - DEBUG_INFO(DEBUG_CATEGORY_BGP, "my_nodeinfo updated: v4s=%d v4a=%d v6s=%d v6a=%d tcp4=%d tcp6=%d v4sub=%d v6sub=%d ver=%d", - sock_count, addr_count, sock6_count, addr6_count, tcp4_count, tcp6_count, vc, vc6, ni->ver); + if (group->group_type == TOPO_GROUP_TYPE_CHAT) + DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "my_nodeinfo updated: v4s=%d v4a=%d v6s=%d v6a=%d tcp4=%d tcp6=%d v4sub=%d v6sub=%d ver=%d grp=%016llx", + sock_count, addr_count, sock6_count, addr6_count, tcp4_count, tcp6_count, vc, vc6, ni->ver, (unsigned long long)group->group_id); + else + DEBUG_INFO(DEBUG_CATEGORY_BGP, "my_nodeinfo updated: v4s=%d v4a=%d v6s=%d v6a=%d tcp4=%d tcp6=%d v4sub=%d v6sub=%d ver=%d grp=%016llx", + sock_count, addr_count, sock6_count, addr6_count, tcp4_count, tcp6_count, vc, vc6, ni->ver, (unsigned long long)group->group_id); if (group->group_type != TOPO_GROUP_TYPE_CHAT && instance->rt && !route_insert(instance->rt, lq)) DEBUG_WARN(DEBUG_CATEGORY_ROUTING, "failed to insert local routes"); } else { diff --git a/src/routing_layer/topo_node_sqlite.c b/src/routing_layer/topo_node_sqlite.c index 3b418456..4c40de64 100644 --- a/src/routing_layer/topo_node_sqlite.c +++ b/src/routing_layer/topo_node_sqlite.c @@ -674,7 +674,7 @@ struct TOPO_NODE* topo_node_sqlite_node_load(sqlite3* db, struct TOPO_GROUPS* gr sqlite3_finalize(s); } } - if (!v4_head && !v6_head) { u_free(name); DEBUG_ERROR(DEBUG_CATEGORY_BGP, "node_load: node 0x%016llx has no addresses", (unsigned long long)node_id); return NULL; } + if (!v4_head && !v6_head) { u_free(name); DEBUG_WARN(DEBUG_CATEGORY_BGP, "node_load: node 0x%016llx has no addresses (may be stub/seed — will retry when addresses arrive)", (unsigned long long)node_id); return NULL; } struct TOPO_NODE* ni = u_calloc(1, sizeof(struct TOPO_NODE)); if (!ni) { u_free(name); return NULL; } diff --git a/src/transport_layer/etcp.c b/src/transport_layer/etcp.c index 27be7ce5..7a47eef2 100644 --- a/src/transport_layer/etcp.c +++ b/src/transport_layer/etcp.c @@ -218,6 +218,7 @@ struct ETCP_CONN* etcp_connection_create(struct UTUN_INSTANCE* instance, char* n etcp->optimal_inflight=100000; etcp->initialized=0; etcp->links_up=0; + etcp->setup_start_tb = get_time_tb(); etcp->reset_done=0; etcp->callbacks_running=0; etcp->ref_count=0; @@ -306,7 +307,10 @@ void etcp_cbk_fire(struct ETCP_CONN* conn, int event) { } static void etcp_on_up(struct ETCP_CONN* etcp) { - DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "[%s] Connection UP (links_up=%d initialized=%d)", etcp->log_name, etcp->links_up, etcp->initialized); + int total_links = 0; for (struct ETCP_LINK* l = etcp->links; l; l = l->next) total_links++; + uint64_t elapsed_ms = (get_time_tb() - etcp->setup_start_tb) / 10; + DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "[%s] Connection UP (%d/%d links up, mtu=%d, setup=%llums, reinit=%u)", + etcp->log_name, etcp->links_up, total_links, etcp->mtu, (unsigned long long)elapsed_ms, etcp->reinit_count); DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CRYPTO_ON_UP_BEFORE: log=%s seskey=%02x%02x%02x%02x peer_pub=%02x%02x%02x%02x", etcp->log_name, etcp->crypto_ctx.session_key[0], etcp->crypto_ctx.session_key[1], @@ -549,7 +553,8 @@ void etcp_conn_reset(struct ETCP_CONN* etcp) { } else { DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "links not up - skip on_down/on_up"); if (etcp->links_up) { - etcp->links_up=0; + etcp->links_up=0; + etcp->setup_start_tb = get_time_tb(); etcp_on_down(etcp); } } @@ -571,10 +576,11 @@ void etcp_links_reset(struct ETCP_CONN* etcp) {// Если сбой в обме } } -void etcp_conn_reinit(struct ETCP_CONN* etcp) {// Если сбой в обмене или ребутнулась одна из сторон -> необходимо заново переинициализировать соединение - DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] REINIT: initialized=%d links_up=%d reinit_count=%u tx_state=%d", - etcp->log_name, etcp->initialized, etcp->links_up, etcp->reinit_count, etcp->tx_state); +void etcp_conn_reinit(struct ETCP_CONN* etcp, const char* reason) {// Если сбой в обмене или ребутнулась одна из сторон -> необходимо заново переинициализировать соединение + DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] REINIT: %s (init=%d links=%d reinit=%u tx=%d)", + etcp->log_name, reason, etcp->initialized, etcp->links_up, etcp->reinit_count, etcp->tx_state); + etcp->setup_start_tb = get_time_tb(); etcp->reinit_count++; etcp->reinit_pending = 1; etcp->reset_done = 0; diff --git a/src/transport_layer/etcp.h b/src/transport_layer/etcp.h index 4e656ff5..f6d64957 100644 --- a/src/transport_layer/etcp.h +++ b/src/transport_layer/etcp.h @@ -198,6 +198,7 @@ struct ETCP_CONN { // uint32_t bytes_received_total; // Not used uint32_t retransmissions_count; uint32_t reinit_count; + uint64_t setup_start_tb; // время начала/рестарта подключения (0.1ms) uint32_t reset_count; // uint32_t bytes_sent_norx; // сколько отправили байт без единого ответного пакета (для детекции запроса реконнекта) @@ -286,7 +287,7 @@ void etcp_conn_ref_free(struct ETCP_CONN* conn); void etcp_conn_reset(struct ETCP_CONN* etcp); void etcp_links_reset(struct ETCP_CONN* etcp); -void etcp_conn_reinit(struct ETCP_CONN* etcp); +void etcp_conn_reinit(struct ETCP_CONN* etcp, const char* reason); void etcp_connection_ready(struct ETCP_CONN* etcp);// вызывается когда подключение инициализировано diff --git a/src/transport_layer/etcp_connections.c b/src/transport_layer/etcp_connections.c index 3c46d7a1..0c321bb8 100644 --- a/src/transport_layer/etcp_connections.c +++ b/src/transport_layer/etcp_connections.c @@ -177,7 +177,10 @@ static void etcp_link_send_init(struct ETCP_LINK* link, uint8_t reset, uint8_t c dgram->data_len = offset; - DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] INIT sent to %s (link=%d, retry=%d, reset=%d)", link->etcp->log_name, sockaddr_storage_to_str(&link->remote_addr).str, link->local_link_id, link->init_retry_count, reset); + if (link->init_retry_count == 0) + DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] INIT sent to %s (link=%d, retry=%d, reset=%d)", link->etcp->log_name, sockaddr_storage_to_str(&link->remote_addr).str, link->local_link_id, link->init_retry_count, reset); + else + DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] INIT sent to %s (link=%d, retry=%d, reset=%d)", link->etcp->log_name, sockaddr_storage_to_str(&link->remote_addr).str, link->local_link_id, link->init_retry_count, reset); etcp_encrypt_send(dgram); u_free(dgram); @@ -229,7 +232,7 @@ void etcp_link_enter_reinit(struct ETCP_LINK* link) { etcp_fire_link_status_cbk(link, old_state, link->link_status); etcp_on_link_down(link->etcp); if (link->is_server != 0) return; - etcp_conn_reinit(link->etcp); + etcp_conn_reinit(link->etcp, "link recovery"); etcp_link_send_init(link,1,0); if (link->keepalive_timer) {// keepalive заменяяется reinit запросами @@ -1005,6 +1008,9 @@ void etcp_link_close(struct ETCP_LINK* link) { remove_link_from_queue(link); etcp_conn_on_inflight_lim_changed(link->etcp); + DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "[%s] Link %d closed: rcvd=%zub ack=%llub infl=%ub/%upkt", + link->etcp->log_name, link->local_link_id, link->total_decrypted, + (unsigned long long)link->acked_bytes, link->inflight_bytes, link->inflight_packets); u_free(link->bbr); u_free(link); } @@ -1596,7 +1602,7 @@ static int handle_init_response_client(struct ETCP_SOCKET* e_sock, struct ETCP_D if (pkt_code == ETCP_INIT_RESPONSE && link->etcp->got_initial_pkt) { DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] REINIT from client: INIT_RESPONSE(0x03) received, reinit conn=%p", link->etcp->log_name, (void*)link->etcp); - etcp_conn_reinit(link->etcp); + etcp_conn_reinit(link->etcp, "server requested"); } if (link->etcp->initialized == 0) { @@ -1699,7 +1705,8 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { // Try INIT decryption (for incoming connection requests) // This handles: no link found, or link without session, or normal decrypt failed if (recv_len <= SC_PUBKEY_ENC_SIZE + UDP_SC_HDR_SIZE) { - DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "packet too small for init, size=%zd from %s", recv_len, sockaddr_storage_to_str(&addr).str); + if (e_sock->pkt_format_errors < 2) + DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "packet too small for init, size=%zd from %s", recv_len, sockaddr_storage_to_str(&addr).str); errorcode=1; goto ec_fr; } @@ -1732,8 +1739,8 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { link->etcp ? link->etcp->log_name : "null", link->link_state, link->etcp ? link->etcp->crypto_ctx.session_ready : -1); - } else { - DEBUG_ERROR(DEBUG_CATEGORY_CRYPTO, + } else if (e_sock->pkt_format_errors < 2) { + DEBUG_WARN(DEBUG_CATEGORY_CRYPTO, "packet undecryptable (normal+init fail) from=%s — no link for this address", sockaddr_storage_to_str(&addr).str); } @@ -1952,7 +1959,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[%s] INIT collision=1 from peer=%016llx — remote is master, becoming slave", conn->log_name, (unsigned long long)peer_id); conn->session_id = session_id; - etcp_conn_reinit(conn); + etcp_conn_reinit(conn, "collision yield"); send_reset = 1; } else { // Check if WE have an outbound (master) link on this conn @@ -1976,7 +1983,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { /* Sync session_id; reset if remote is clean and we're dirty, or request reset if we're clean and remote is dirty */ conn->session_id = session_id; if (req->code == ETCP_INIT_REQUEST) { - if (conn->got_initial_pkt) etcp_conn_reinit(conn); + if (conn->got_initial_pkt) etcp_conn_reinit(conn, "duplicate INIT"); send_reset = 0; } else { if (conn->got_initial_pkt == 0) send_reset = 1; @@ -2003,7 +2010,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "[%s] INIT collision=1 from peer=%016llx — remote is master, becoming slave", conn->log_name, (unsigned long long)peer_id); conn->session_id = session_id; - etcp_conn_reinit(conn); + etcp_conn_reinit(conn, "collision yield"); send_reset = 1; } else { // Check if WE have an outbound (master) link @@ -2024,7 +2031,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) { send_reset = 1; DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] REINIT new link: code=0x%02x sess=%08x→%08x got_init=%d initialized=%d links_up=%d", conn->log_name, code, conn->session_id, session_id, conn->got_initial_pkt, conn->initialized, conn->links_up); - etcp_conn_reinit(conn); + etcp_conn_reinit(conn, "session changed"); } } } link->keepalive_interval=(req->keepalive[0]<<8) | req->keepalive[1]; @@ -2117,8 +2124,9 @@ process_decrypted: return; ec_fr: - DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "error %d, from %s", errorcode, sockaddr_storage_to_str(&addr).str); e_sock->pkt_format_errors++; + if (e_sock->pkt_format_errors < 3 || (e_sock->pkt_format_errors % 500 == 0)) + DEBUG_WARN(DEBUG_CATEGORY_ETCP, "error %d, from %s (count=%zu)", errorcode, sockaddr_storage_to_str(&addr).str, e_sock->pkt_format_errors); e_sock->errorcode=errorcode; memory_pool_free(e_sock->instance->pkt_pool, pkt); return; diff --git a/src/transport_layer/etcp_dump.c b/src/transport_layer/etcp_dump.c index b2211d34..2e300239 100644 --- a/src/transport_layer/etcp_dump.c +++ b/src/transport_layer/etcp_dump.c @@ -9,8 +9,8 @@ #include #include -#define DLOG(fmt, ...) DEBUG_INFO(DEBUG_CATEGORY_DEBUG, " " fmt, ##__VA_ARGS__) -#define DHDR(fmt, ...) DEBUG_INFO(DEBUG_CATEGORY_DEBUG, fmt, ##__VA_ARGS__) +#define DLOG(fmt, ...) DEBUG_DEBUG(DEBUG_CATEGORY_ETCP_DUMP, " " fmt, ##__VA_ARGS__) +#define DHDR(fmt, ...) DEBUG_DEBUG(DEBUG_CATEGORY_ETCP_DUMP, fmt, ##__VA_ARGS__) static void dump_queue(const char* name, struct ll_queue* q) { if (!q) { DLOG("%-14s NULL", name); return; } diff --git a/src/transport_layer/pkt_normalizer.c b/src/transport_layer/pkt_normalizer.c index 9fb2db96..fa38cf2c 100644 --- a/src/transport_layer/pkt_normalizer.c +++ b/src/transport_layer/pkt_normalizer.c @@ -364,7 +364,7 @@ static void pn_unpacker_cb(struct ll_queue* q, void* arg) { // Incomplete header, reset DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "reset state"); // pn_unpacker_reset_state(pn); - etcp_conn_reinit(pn->etcp); + etcp_conn_reinit(pn->etcp, "normalizer desync"); break; } uint16_t part_size = payload[ptr] | (payload[ptr + 1] << 8); @@ -374,7 +374,7 @@ static void pn_unpacker_cb(struct ll_queue* q, void* arg) { if (part_size<1 || part_size>16384) { pn->logic_errors++; DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "PART_SIZE ERROR!!! %d", part_size); - etcp_conn_reinit(pn->etcp); + etcp_conn_reinit(pn->etcp, "bad fragment size"); break; } diff --git a/tests/test_etcp_reconnect.c b/tests/test_etcp_reconnect.c index ceb2e13f..efec18c0 100644 --- a/tests/test_etcp_reconnect.c +++ b/tests/test_etcp_reconnect.c @@ -212,7 +212,7 @@ static void monitor(void* arg) { printf("Server recreated (node_id=%llx)\n", (unsigned long long)server_instance->node_id); // Force client to reinit — otherwise conn_ok stays true on old initialized=1 { struct ll_entry* e = client_instance->connections->head; - while (e) { struct conn_queue_entry* ce = (struct conn_queue_entry*)e->data; etcp_conn_reinit(ce->conn); e = e->next; } } + while (e) { struct conn_queue_entry* ce = (struct conn_queue_entry*)e->data; etcp_conn_reinit(ce->conn, "test force reinit"); e = e->next; } } restart_action_done = 1; } drain_received(0); diff --git a/tests/test_pkt_normalizer_standalone.c b/tests/test_pkt_normalizer_standalone.c index 953b9770..189a744a 100644 --- a/tests/test_pkt_normalizer_standalone.c +++ b/tests/test_pkt_normalizer_standalone.c @@ -14,8 +14,8 @@ // Weak stub for etcp_conn_reinit — overridden if real ETCP is linked // Weak stub for etcp_conn_reinit - can be overridden by real ETCP implementation -__attribute__((weak)) void etcp_conn_reinit(struct ETCP_CONN* etcp) { - (void)etcp; +__attribute__((weak)) void etcp_conn_reinit(struct ETCP_CONN* etcp, const char* reason) { + (void)etcp; (void)reason; fprintf(stderr, "FAIL: etcp_conn_reinit called - ETCP not initialized in standalone test!\n"); exit(1); }