From 15d460ee7cbc701ff4e22422e095db8ad2569224 Mon Sep 17 00:00:00 2001 From: evgeny Date: Wed, 7 Oct 2026 21:13:53 +0200 Subject: [PATCH] logging: explain BGP readiness, route selection and peer removal --- src/routing_layer/topo_group.c | 47 ++++++++++++++++++++++++---------- src/transport_layer/reality.c | 2 +- 2 files changed, 34 insertions(+), 15 deletions(-) diff --git a/src/routing_layer/topo_group.c b/src/routing_layer/topo_group.c index 3f423a2a..bc8155ef 100644 --- a/src/routing_layer/topo_group.c +++ b/src/routing_layer/topo_group.c @@ -100,9 +100,13 @@ int topo_group_peer_ready(const struct TOPO_GROUP* group, uint64_t peer_id) { static void topo_group_notify_ready(struct TOPO_GROUP_CONN_ITEM* peer, int ready) { if (peer->ready_notified == ready) return; peer->ready_notified = ready; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "group peer readiness: group=%016llx peer=%016llx ready=%d epoch=%016llx", + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP peer %s: group=%016llx peer=%016llx local_epoch=%016llx remote_epoch=%016llx " + "links_up=%u transport_down=%u accepted=%u table_sent=%u table_received=%u send_failed=%u", + ready ? "READY (group exchange complete)" : "NOT READY (group session unavailable)", (unsigned long long)peer->group->group_id, (unsigned long long)peer->node_id, - ready, (unsigned long long)peer->local_epoch); + (unsigned long long)peer->local_epoch, (unsigned long long)peer->remote_epoch, + peer->conn ? peer->conn->links_up : 0, peer->transport_down, peer->accepted, + peer->table_sent, peer->table_received, peer->tx_failed); for (struct topo_peer_ready_cbk* cb = peer->group->peer_ready_cbks; cb; cb = cb->next) cb->fn(peer->group, peer->node_id, ready, cb->arg); } @@ -1007,10 +1011,18 @@ int topo_group_new_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn) { void topo_group_remove_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn, enum topo_group_remove_reason reason) { if (!group || !conn) { DEBUG_ERROR(DEBUG_CATEGORY_BGP, "invalid args"); return; } if (!conn->instance) { DEBUG_ERROR(DEBUG_CATEGORY_BGP, "invalid instance"); return; } + const char* reason_text = "unknown"; + switch (reason) { + case TOPO_REMOVE_TRANSPORT_DOWN: reason_text = "transport-down"; break; + case TOPO_REMOVE_LOCAL_LEAVE: reason_text = "local-left-group"; break; + case TOPO_REMOVE_REMOTE_LEAVE: reason_text = "peer-left-group"; break; + case TOPO_REMOVE_MEMBER_INVALID: reason_text = "membership-invalid"; break; + case TOPO_REMOVE_REJECTED: reason_text = "group-join-rejected"; break; + } struct TOPO_GROUP_CONN_ITEM* pending = topo_group_peer(group, conn->peer_node_id); if (pending && !pending->conn && node_conn_direct_get_conn(pending->handle) == conn) { - DEBUG_INFO(DEBUG_CATEGORY_BGP, "group pending peer removed: peer=%016llx group=%016llx reason=%d", - (unsigned long long)pending->node_id, (unsigned long long)group->group_id, reason); + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP pending connection lost: peer=%016llx group=%016llx reason=%s", + (unsigned long long)pending->node_id, (unsigned long long)group->group_id, reason_text); if (reason == TOPO_REMOVE_TRANSPORT_DOWN && pending->requests) { pending->transport_down = 1; pending->retained = 0; topo_recovery_changed(group); topo_group_connect_changed(group); @@ -1023,9 +1035,10 @@ void topo_group_remove_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn, en while (e) { struct TOPO_GROUP_CONN_ITEM* item = (struct TOPO_GROUP_CONN_ITEM*)e->data; if (item->conn == conn) { found_in_list = true; break; } e = e->next; } if (!found_in_list) { DEBUG_WARN(DEBUG_CATEGORY_BGP, "topo_group_remove_conn: conn=%p peer=%016llx state=%d NOT in senders_list (already removed?), skip grp=%016llx ch=%s", (void*)conn, (unsigned long long)conn->peer_node_id, conn->state, (unsigned long long)group->group_id, group->channel_id); return; } - DEBUG_INFO(DEBUG_CATEGORY_BGP, "topo_group_remove_conn: conn=%p peer=%016llx state=%d name='%s' grp=%016llx ch=%s", - (void*)conn, (unsigned long long)conn->peer_node_id, conn->state, conn->log_name, - (unsigned long long)group->group_id, group->channel_id); + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP peer session lost; removing its routes: peer=%016llx group=%016llx channel=%s " + "reason=%s links_up=%u close_requested=%u reinit_pending=%u", + (unsigned long long)conn->peer_node_id, (unsigned long long)group->group_id, group->channel_id, + reason_text, conn->links_up, conn->close_requested, conn->reinit_pending); /* Больше не публикуем в закрываемую сессию, даже если общий транспорт ещё UP. */ pending->transport_down = 1; @@ -1061,8 +1074,10 @@ void topo_group_remove_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn, en topo_recovery_add_node(group, key, next_hop, lost_rtt); cascaded++; } nodes_removed++; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "node removed from group: node=%016llx grp=%016llx type=%u ch=%s (link_down)", - (unsigned long long)key, (unsigned long long)group->group_id, group->group_type, group->channel_id); + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP destination unreachable; no alternative path: node=%016llx group=%016llx " + "lost_peer=%016llx reason=%s", + (unsigned long long)key, (unsigned long long)group->group_id, + (unsigned long long)conn->peer_node_id, reason_text); // REINIT временно убирает путь, но end-to-end данные роутера остаются неподтверждёнными. if (!conn->reinit_pending) etcp_router_conn_close_all_for_node(group->instance, group->group_id, key); } @@ -1097,8 +1112,9 @@ void topo_group_remove_conn(struct TOPO_GROUP* group, struct ETCP_CONN* conn, en topo_group_connect_on_down(group, conn); - DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP peer removed: %s nodes=%d grp=%016llx reason=%d recovery=%d", - conn->log_name, nodes_removed, (unsigned long long)group->group_id, reason, cascaded); + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP peer removal complete: peer=%016llx group=%016llx reason=%s " + "destinations_without_paths=%d recovery_targets=%d", + (unsigned long long)conn->peer_node_id, (unsigned long long)group->group_id, reason_text, nodes_removed, cascaded); } @@ -1163,8 +1179,10 @@ static void topo_group_routes_changed(struct TOPO_GROUP* group, struct TOPO_GROU node->conn_presence |= NCONN_DIRECT; if (p->conn->links_up && !p->conn->close_requested) node->conn_up |= NCONN_DIRECT; } - DEBUG_INFO(DEBUG_CATEGORY_BGP, "route changed: group=%016llx node=%016llx paths=%d via=%016llx hops=%u", - (unsigned long long)group->group_id, (unsigned long long)id, node->paths ? queue_entry_count(node->paths) : 0, + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP route recomputed: group=%016llx node=%016llx result=%s stored_paths=%d via=%016llx hops=%u", + (unsigned long long)group->group_id, (unsigned long long)id, + best ? (best->conn->peer_node_id == id ? "direct" : "via-intermediary") : "unreachable-no-live-path", + node->paths ? queue_entry_count(node->paths) : 0, (unsigned long long)(best ? best->conn->peer_node_id : 0), best ? best->hop_count : 0); if (group->group_type != TOPO_GROUP_TYPE_CHAT && group->instance->rt) { if (best && node->subnets) route_insert(group->instance->rt, node); @@ -1427,7 +1445,8 @@ int topo_group_process_withdraw(struct TOPO_GROUP* group, struct ETCP_CONN* send if (!nq) { DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "WITHDRAW unknown node=%016llx", (unsigned long long)node_id); return 0; } int removed = topo_group_remove_path(nq, sender); int remaining = nq->paths ? queue_entry_count(nq->paths) : 0; - DEBUG_INFO(DEBUG_CATEGORY_BGP, "WITHDRAW group=%016llx node=%016llx source=%016llx removed=%d remaining=%d", + DEBUG_INFO(DEBUG_CATEGORY_BGP, "BGP WITHDRAW received (sender withdrew its route): group=%016llx node=%016llx " + "source=%016llx removed=%d remaining_stored_paths=%d", (unsigned long long)group->group_id, (unsigned long long)node_id, (unsigned long long)sender->peer_node_id, removed, remaining); if (removed) topo_group_routes_changed(group, nq, TOPO_NODE_EVENT_UPDATE); diff --git a/src/transport_layer/reality.c b/src/transport_layer/reality.c index 33386228..986e9547 100644 --- a/src/transport_layer/reality.c +++ b/src/transport_layer/reality.c @@ -401,7 +401,7 @@ static int client_hello_build(struct reality_session *session, const struct real memcpy(session->session_id, seal_out, 32); if (reality_transcript_add(session, hs, hs_len)) { rc = REALITY_ERR_CRYPTO; goto out; } } - DEBUG_INFO(DEBUG_CATEGORY_REALITY, "client hello built: total=%zu sni=%s version=%u.%u.%u", total, + DEBUG_TRACE(DEBUG_CATEGORY_REALITY, "client hello built: total=%zu sni=%s version=%u.%u.%u", total, cfg->server_name, cfg->version[0], cfg->version[1], cfg->version[2]); rc = REALITY_OK; out: