Browse Source

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)
topo_upd
Evgeny 2 months ago
parent
commit
2b10f53466
  1. 7
      lib/u_async.c
  2. 5
      src/routing_layer/conn_mgr_core.c
  3. 12
      src/transport_layer/node_conn_direct.c
  4. 8
      src/transport_layer/stcp_client.c

7
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 // Calculate expiration time in milliseconds
struct timeval now; struct timeval now;
get_current_time(&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); timeval_add_tb(&now, timeout_tb);
node->expiration_ms = timeval_to_ms(&now); 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 // Add to heap
if (timeout_heap_push(ua->timeout_heap, node->expiration_ms, node, &node->heap_index) != 0) { if (timeout_heap_push(ua->timeout_heap, node->expiration_ms, node, &node->heap_index) != 0) {

5
src/routing_layer/conn_mgr_core.c

@ -804,6 +804,9 @@ void cm_invite_overall_timeout(void* arg) {
* через handle и освобождает его. Вызывается также из conn_mgr_destroy. */ * через handle и освобождает его. Вызывается также из conn_mgr_destroy. */
void cm_invite_fail(struct cm_invite_pending* inv) { void cm_invite_fail(struct cm_invite_pending* inv) {
if (!inv) return; 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->overall_timer) { uasync_cancel_timeout(inv->mgr->instance->ua, inv->overall_timer); inv->overall_timer = NULL; }
if (inv->tcp_link) { if (inv->tcp_link) {
struct ll_entry* e = queue_find_data_by_index(inv->mgr->instance->tcp_connections, (const uint8_t*)&inv->node_id); 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; stcp_link_close(inv->tcp_link); inv->tcp_link = NULL;
} }
if (inv->ncd_handle) { if (inv->ncd_handle) {
/* проверяем: есть ли зарегистрированные хендлы на этом соединении */
struct TOPO_GROUP_NODE* nq = topo_node_find_by_id(inv->mgr->group, inv->node_id); struct TOPO_GROUP_NODE* nq = topo_node_find_by_id(inv->mgr->group, inv->node_id);
if (nq && nq->handle != NULL) { if (nq && nq->handle != NULL) {
DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "conn_mgr: invite fail node=0x%016llx — handle registered, skip NCD close", DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "conn_mgr: invite fail node=0x%016llx — handle registered, skip NCD close",
(unsigned long long)inv->node_id); (unsigned long long)inv->node_id);
} else { } else {
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "cm_invite_fail: CLOSE NCD, nq=%p", (void*)nq);
node_conn_direct_close(inv->ncd_handle); node_conn_direct_close(inv->ncd_handle);
} }
inv->ncd_handle = NULL; inv->ncd_handle = NULL;

12
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; struct ncd_entry* entry = (struct ncd_entry*)arg;
if (!entry || entry->timed_out) return; if (!entry || entry->timed_out) return;
entry->connect_timer = NULL; entry->connect_timer = NULL;
DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] connect timeout node=0x%016llx handles=%d", DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] connect TIMEOUT: node=0x%016llx now_tb=%llu handles=%d",
(unsigned long long)entry->node_id, entry->handle_count); (unsigned long long)entry->node_id, (unsigned long long)get_time_tb(), entry->handle_count);
ncd_event_dispatch(entry, NCD_EVENT_TIMEOUT); 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); { 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); } 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"); 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); 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) if (link_count == 0)
DEBUG_WARN(DEBUG_CATEGORY_NCD, "[ncd] no links created for node=0x%016llx", (unsigned long long)node_id); 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"); 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", 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); (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); 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 { } else {
ncd_create_links(entry, ni, specific_sock); 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"); 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); 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) 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_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"); 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", 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); (unsigned long long)node_id, (void*)conn, link_count, entry->handle_count);

8
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); c->sock = socket(res->ai_family, res->ai_socktype, res->ai_protocol);
if (c->sock == SOCKET_INVALID) { freeaddrinfo(res); u_free(cli); return NULL; } if (c->sock == SOCKET_INVALID) { freeaddrinfo(res); u_free(cli); return NULL; }
socket_set_nonblocking(c->sock); socket_set_nonblocking(c->sock);
if (connect(c->sock, res->ai_addr, res->ai_addrlen) < 0 && socket_get_error() != EINPROGRESS) { { int sock_err = socket_get_error();
DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "stcp_client connect to %s:%u failed err=%d", addr, port, socket_get_error()); if (connect(c->sock, res->ai_addr, res->ai_addrlen) < 0 && sock_err != EINPROGRESS && sock_err != ERR_WOULDBLOCK) {
socket_close_wrapper(c->sock); freeaddrinfo(res); u_free(cli); return NULL; 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); freeaddrinfo(res);
c->socket_id = uasync_add_socket_t(ua, c->sock, NULL, client_connect_write_cb, NULL, cli); c->socket_id = uasync_add_socket_t(ua, c->sock, NULL, client_connect_write_cb, NULL, cli);

Loading…
Cancel
Save