From 2b10f534664e9321a24468c2b0c1f2ca55da454c Mon Sep 17 00:00:00 2001 From: Evgeny Date: Tue, 4 Aug 2026 18:16:53 +0300 Subject: [PATCH] diagnostics: ncd connect timer SET/FIRE logs + WSAEWOULDBLOCK fix + cm_invite_fail details - u_async.c: log ncd_connect timer expiration calculation (tb, now_tb, exp_tb, exp_ms, delta_tb) - node_conn_direct.c: SET logs at 4 timer creation points with value_tb/now_tb/path; TIMEOUT log with now_tb - conn_mgr_core.c: cm_invite_fail entry log + CLOSE/SKIP branch detail - stcp_client.c: fix WSAEWOULDBLOCK (10035) treated as error on Windows (add ERR_WOULDBLOCK check) --- lib/u_async.c | 7 +++++++ src/routing_layer/conn_mgr_core.c | 5 ++++- src/transport_layer/node_conn_direct.c | 12 ++++++++++-- src/transport_layer/stcp_client.c | 8 +++++--- 4 files changed, 26 insertions(+), 6 deletions(-) diff --git a/lib/u_async.c b/lib/u_async.c index 7f88d199..3cbad949 100644 --- a/lib/u_async.c +++ b/lib/u_async.c @@ -553,8 +553,15 @@ void* uasync_set_timeout(struct UASYNC* ua, int timeout_tb, void* arg, timeout_c // Calculate expiration time in milliseconds struct timeval now; get_current_time(&now); + uint64_t now_tb = (uint64_t)now.tv_sec * 10000ULL + (uint64_t)now.tv_usec / 100ULL; timeval_add_tb(&now, timeout_tb); node->expiration_ms = timeval_to_ms(&now); + if (name && strncmp(name, "ncd_connect", 11) == 0) { + uint64_t exp_tb = (uint64_t)now.tv_sec * 10000ULL + (uint64_t)now.tv_usec / 100ULL; + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[uasync] set_timeout: name=%s tb=%d now_tb=%llu exp_tb=%llu exp_ms=%llu delta_tb=%llu", + name, timeout_tb, (unsigned long long)now_tb, (unsigned long long)exp_tb, + (unsigned long long)node->expiration_ms, (unsigned long long)(exp_tb - now_tb)); + } // Add to heap if (timeout_heap_push(ua->timeout_heap, node->expiration_ms, node, &node->heap_index) != 0) { diff --git a/src/routing_layer/conn_mgr_core.c b/src/routing_layer/conn_mgr_core.c index 5e6f0cce..f48ad5ab 100644 --- a/src/routing_layer/conn_mgr_core.c +++ b/src/routing_layer/conn_mgr_core.c @@ -804,6 +804,9 @@ void cm_invite_overall_timeout(void* arg) { * через handle и освобождает его. Вызывается также из conn_mgr_destroy. */ void cm_invite_fail(struct cm_invite_pending* inv) { if (!inv) return; + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "cm_invite_fail: node=0x%016llx state=%d ncd=%p tcp=%p", + (unsigned long long)inv->node_id, (int)inv->state, + (void*)inv->ncd_handle, (void*)inv->tcp_link); if (inv->overall_timer) { uasync_cancel_timeout(inv->mgr->instance->ua, inv->overall_timer); inv->overall_timer = NULL; } if (inv->tcp_link) { struct ll_entry* e = queue_find_data_by_index(inv->mgr->instance->tcp_connections, (const uint8_t*)&inv->node_id); @@ -811,12 +814,12 @@ void cm_invite_fail(struct cm_invite_pending* inv) { stcp_link_close(inv->tcp_link); inv->tcp_link = NULL; } if (inv->ncd_handle) { - /* проверяем: есть ли зарегистрированные хендлы на этом соединении */ struct TOPO_GROUP_NODE* nq = topo_node_find_by_id(inv->mgr->group, inv->node_id); if (nq && nq->handle != NULL) { DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "conn_mgr: invite fail node=0x%016llx — handle registered, skip NCD close", (unsigned long long)inv->node_id); } else { + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "cm_invite_fail: CLOSE NCD, nq=%p", (void*)nq); node_conn_direct_close(inv->ncd_handle); } inv->ncd_handle = NULL; diff --git a/src/transport_layer/node_conn_direct.c b/src/transport_layer/node_conn_direct.c index a03df1c6..18aed54f 100644 --- a/src/transport_layer/node_conn_direct.c +++ b/src/transport_layer/node_conn_direct.c @@ -341,8 +341,8 @@ static void ncd_connect_timeout_cb(void* arg) { struct ncd_entry* entry = (struct ncd_entry*)arg; if (!entry || entry->timed_out) return; entry->connect_timer = NULL; - DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] connect timeout node=0x%016llx handles=%d", - (unsigned long long)entry->node_id, entry->handle_count); + DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] connect TIMEOUT: node=0x%016llx now_tb=%llu handles=%d", + (unsigned long long)entry->node_id, (unsigned long long)get_time_tb(), entry->handle_count); ncd_event_dispatch(entry, NCD_EVENT_TIMEOUT); } @@ -555,6 +555,8 @@ int node_conn_direct_open(struct UTUN_INSTANCE* inst, uint64_t node_id, { struct TOPO_NODE* ni = ncd_lookup_node(inst, node_id); if (ni) { ncd_create_links(entry, ni, specific_sock); topo_node_registry_unref(inst->topo_groups, ni->node_id); } } + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=REUSED_entry_pending", + (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect"); DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open REUSED new-entry (pending) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn); } @@ -627,6 +629,8 @@ int node_conn_direct_open(struct UTUN_INSTANCE* inst, uint64_t node_id, if (link_count == 0) DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] no links created for node=0x%016llx", (unsigned long long)node_id); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=NEW_node_conn_direct_open", + (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect"); DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open NEW node=0x%016llx conn=%p links=%d handles=%d", (unsigned long long)node_id, (void*)conn, link_count, entry->handle_count); @@ -702,6 +706,8 @@ int node_conn_direct_open_node(struct UTUN_INSTANCE* inst, uint64_t node_id, DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node REUSED new-entry (ready) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn); } else { ncd_create_links(entry, ni, specific_sock); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=REUSED_conn_pending", + (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect_node"); DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node REUSED new-entry (pending) node=0x%016llx conn=%p", (unsigned long long)node_id, (void*)conn); } @@ -765,6 +771,8 @@ int node_conn_direct_open_node(struct UTUN_INSTANCE* inst, uint64_t node_id, if (link_count == 0) DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] open_node no links created for node=0x%016llx", (unsigned long long)node_id); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "[ncd] connect timer SET: node=0x%016llx value_tb=%u now_tb=%llu path=NEW_node_conn_direct_open_node", + (unsigned long long)node_id, inst->etcp_connect_timeout_tb, (unsigned long long)get_time_tb()); entry->connect_timer = uasync_set_timeout(inst->ua, (int)inst->etcp_connect_timeout_tb, entry, ncd_connect_timeout_cb, "ncd_connect_node"); DEBUG_INFO(DEBUG_CATEGORY_NCD, "[ncd] open_node NEW node=0x%016llx conn=%p links=%d handles=%d", (unsigned long long)node_id, (void*)conn, link_count, entry->handle_count); diff --git a/src/transport_layer/stcp_client.c b/src/transport_layer/stcp_client.c index 9a489e91..b1105aea 100644 --- a/src/transport_layer/stcp_client.c +++ b/src/transport_layer/stcp_client.c @@ -275,9 +275,11 @@ struct stcp_client *stcp_client_connect(struct UASYNC *ua, const char *addr, uin c->sock = socket(res->ai_family, res->ai_socktype, res->ai_protocol); if (c->sock == SOCKET_INVALID) { freeaddrinfo(res); u_free(cli); return NULL; } socket_set_nonblocking(c->sock); - if (connect(c->sock, res->ai_addr, res->ai_addrlen) < 0 && socket_get_error() != EINPROGRESS) { - DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "stcp_client connect to %s:%u failed err=%d", addr, port, socket_get_error()); - socket_close_wrapper(c->sock); freeaddrinfo(res); u_free(cli); return NULL; + { int sock_err = socket_get_error(); + if (connect(c->sock, res->ai_addr, res->ai_addrlen) < 0 && sock_err != EINPROGRESS && sock_err != ERR_WOULDBLOCK) { + DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "stcp_client connect to %s:%u failed err=%d(%s)", addr, port, sock_err, socket_strerror(sock_err)); + socket_close_wrapper(c->sock); freeaddrinfo(res); u_free(cli); return NULL; + } } freeaddrinfo(res); c->socket_id = uasync_add_socket_t(ua, c->sock, NULL, client_connect_write_cb, NULL, cli);