jeka
/
utun2
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity
Browse Source

logging: cleanup connection establishment logs 

- Fix wrong categories: BGP/DEBUG -> ETCP for connection lifecycle events
- Fix level: WARN -> DEBUG for normal out-of-order pkts before init
- Fix level: INFO -> DEBUG for per-packet TX DATA spam
- Remove duplicate socket init logs (GENERAL duplicates of ETCP)
- Add missing INFO: INIT_RESPONSE received (client), INIT_RESPONSE sent (server)
- Unify all connection establishment messages under ETCP category
- Remove redundant DEBUG address prints in INIT send (info already in INFO msg)
- PING/PONG operations: BGP -> CONNECTION
- DIRECT IP detection: BGP -> NAT
topo_upd
Evgeny 3 months ago
parent
3cd494bead
commit
de4099a26b
2 changed files with 46 additions and 63 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Unified View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 15
      src/etcp.c
  2. 94
      src/etcp_connections.c

15
src/etcp.c
Unescape View File

@ -285,7 +285,7 @@ struct ETCP_CONN* etcp_connection_create(struct UTUN_INSTANCE* instance, char* n
static void etcp_on_up(struct ETCP_CONN* etcp) { static void etcp_on_up(struct ETCP_CONN* etcp) {
DEBUG_WARN(DEBUG_CATEGORY_BGP, "[%s] UP links_up=%d initialized=%d", etcp->log_name, etcp->links_up, etcp->initialized); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Connection UP (links_up=%d initialized=%d)", etcp->log_name, etcp->links_up, etcp->initialized);
etcp->callbacks_running = 1; etcp->callbacks_running = 1;
struct etcp_cbk_entry* cbe = etcp->up_cbks; struct etcp_cbk_entry* cbe = etcp->up_cbks;
while (cbe) { struct etcp_cbk_entry* n = cbe->next; cbe->fn(etcp, cbe->arg); cbe = n; } while (cbe) { struct etcp_cbk_entry* n = cbe->next; cbe->fn(etcp, cbe->arg); cbe = n; }
@ -293,7 +293,7 @@ static void etcp_on_up(struct ETCP_CONN* etcp) {
} }
static void etcp_on_down(struct ETCP_CONN* etcp) { static void etcp_on_down(struct ETCP_CONN* etcp) {
DEBUG_WARN(DEBUG_CATEGORY_BGP, "[%s] DOWN links_up=%d", etcp->log_name, etcp->links_up); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Connection DOWN (links_up=%d)", etcp->log_name, etcp->links_up);
etcp->callbacks_running = 1; etcp->callbacks_running = 1;
struct etcp_cbk_entry* cbe = etcp->down_cbks; struct etcp_cbk_entry* cbe = etcp->down_cbks;
while (cbe) { struct etcp_cbk_entry* n = cbe->next; cbe->fn(etcp, cbe->arg); cbe = n; } while (cbe) { struct etcp_cbk_entry* n = cbe->next; cbe->fn(etcp, cbe->arg); cbe = n; }
@ -537,7 +537,7 @@ void etcp_links_reset(struct ETCP_CONN* etcp) {// Если сбой в обме
} }
void etcp_conn_reinit(struct ETCP_CONN* etcp) {// Если сбой в обмене или ребутнулась одна из сторон -> необходимо заново переинициализировать соединение void etcp_conn_reinit(struct ETCP_CONN* etcp) {// Если сбой в обмене или ребутнулась одна из сторон -> необходимо заново переинициализировать соединение
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "[%s] REINIT: initialized=%d links_up=%d reinit_count=%u tx_state=%d", 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); etcp->log_name, etcp->initialized, etcp->links_up, etcp->reinit_count, etcp->tx_state);
etcp->reinit_count++; etcp->reinit_count++;
@ -584,7 +584,7 @@ void etcp_conn_queue_set_ready(struct ETCP_CONN* conn) {
if (!conn || conn->state != 0) return; if (!conn || conn->state != 0) return;
// Reindex: remove old entry (key=0), add new entry with real peer_node_id // Reindex: remove old entry (key=0), add new entry with real peer_node_id
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "[%s] queue_set_ready: removing old entry=%p key=0 -> new key=0x%llx", DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] queue_set_ready: removing old entry=%p key=0 -> new key=0x%llx",
conn->log_name, (void*)conn->conn_queue_entry, (unsigned long long)conn->peer_node_id); conn->log_name, (void*)conn->conn_queue_entry, (unsigned long long)conn->peer_node_id);
if (conn->conn_queue && conn->conn_queue_entry) { if (conn->conn_queue && conn->conn_queue_entry) {
queue_remove_data(conn->conn_queue, conn->conn_queue_entry); queue_remove_data(conn->conn_queue, conn->conn_queue_entry);
@ -600,7 +600,7 @@ void etcp_conn_queue_set_ready(struct ETCP_CONN* conn) {
conn->conn_queue = conn->instance->connections; conn->conn_queue = conn->instance->connections;
conn->state = 1; conn->state = 1;
queue_data_put_with_index(conn->instance->connections, qe); queue_data_put_with_index(conn->instance->connections, qe);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "[%s] queue_set_ready: new entry=%p put in queue, count=%d", DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] queue_set_ready: new entry=%p put in queue, count=%d",
conn->log_name, (void*)qe, queue_entry_count(conn->instance->connections)); conn->log_name, (void*)qe, queue_entry_count(conn->instance->connections));
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] moved to ready queue, state=%d peer_node_id=0x%llx", DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] moved to ready queue, state=%d peer_node_id=0x%llx",
@ -1233,7 +1233,7 @@ struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
} }
} }
// фрейм data (0) обязательно в конец // фрейм data (0) обязательно в конец
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] TX DATA: seq=%u len=%u retry=%d; Qlen: in=%d snd=%d wait=%d", etcp->log_name, inf_pkt->seq, inf_pkt->ll.len, inf_pkt->send_count, etcp->input_queue->count, etcp->input_send_q->count, etcp->input_wait_ack->count); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] TX DATA: seq=%u len=%u retry=%d; Qlen: in=%d snd=%d wait=%d", etcp->log_name, inf_pkt->seq, inf_pkt->ll.len, inf_pkt->send_count, etcp->input_queue->count, etcp->input_send_q->count, etcp->input_wait_ack->count);
dgram->data[ptr++]=0;// payload dgram->data[ptr++]=0;// payload
dgram->data[ptr++]=inf_pkt->seq; dgram->data[ptr++]=inf_pkt->seq;
@ -1539,7 +1539,8 @@ void etcp_conn_input(struct ETCP_DGRAM* pkt) {
if (etcp->got_initial_pkt == 0) { if (etcp->got_initial_pkt == 0) {
if (seq==1) { etcp->got_initial_pkt = 1; DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Initial packet seq=1 received", etcp->log_name); } if (seq==1) { etcp->got_initial_pkt = 1; DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Initial packet seq=1 received", etcp->log_name); }
else { else {
DEBUG_WARN(DEBUG_CATEGORY_ETCP, "[%s] Waiting for initial packet but recv seq=%d, ignoring", etcp->log_name, seq); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] Out-of-order pkt before init seq=%d, waiting seq=1",
etcp->log_name, seq);
len=0; len=0;
break; break;
} }

94
src/etcp_connections.c
Unescape View File

@ -177,16 +177,7 @@ static void etcp_link_send_init(struct ETCP_LINK* link, uint8_t reset, uint8_t c
dgram->data_len = offset; dgram->data_len = offset;
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "Sending INIT request to link, node_id=%016llx, retry=%d", (unsigned long long)link->etcp->instance->node_id, link->init_retry_count); 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);
// Debug: print remote address before sending
if (link->remote_addr.ss_family == AF_INET) {
struct sockaddr_in* sin = (struct sockaddr_in*)&link->remote_addr;
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[ETCP] INIT sending to %s:%d, link=%p, rst_req=%d", ip_to_str(&sin->sin_addr, AF_INET).str, ntohs(sin->sin_port), link, reset);
} else if (link->remote_addr.ss_family == AF_INET6) {
struct sockaddr_in6* sin6 = (struct sockaddr_in6*)&link->remote_addr;
DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[ETCP] INIT sending to %s:%d, link=%p, rst_req=%d", ip_to_str(&sin6->sin6_addr, AF_INET6).str, ntohs(sin6->sin6_port), link, reset);
}
etcp_encrypt_send(dgram); etcp_encrypt_send(dgram);
u_free(dgram); u_free(dgram);
@ -632,11 +623,9 @@ struct ETCP_SOCKET* etcp_socket_add(struct UTUN_INSTANCE* instance, struct CFG_S
if (ip->ss_family == AF_INET) { if (ip->ss_family == AF_INET) {
struct sockaddr_in* sin = (struct sockaddr_in*)ip; struct sockaddr_in* sin = (struct sockaddr_in*)ip;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[ETCP] Successfully bound socket to local address, family=AF_INET %s:%d", ip_to_str(&sin->sin_addr, AF_INET).str, ntohs(sin->sin_port)); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[ETCP] Successfully bound socket to local address, family=AF_INET %s:%d", ip_to_str(&sin->sin_addr, AF_INET).str, ntohs(sin->sin_port));
DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "Listen socket initialized: name=%s fd=%d addr=%s:%d", e_sock->name, e_sock->fd, ip_to_str(&sin->sin_addr, AF_INET).str, ntohs(sin->sin_port));
} else if (ip->ss_family == AF_INET6) { } else if (ip->ss_family == AF_INET6) {
struct sockaddr_in6* sin6 = (struct sockaddr_in6*)ip; struct sockaddr_in6* sin6 = (struct sockaddr_in6*)ip;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[ETCP] Successfully bound socket to local address, family=AF_INET6 %s:%d", ip_to_str(&sin6->sin6_addr, AF_INET6).str, ntohs(sin6->sin6_port)); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[ETCP] Successfully bound socket to local address, family=AF_INET6 %s:%d", ip_to_str(&sin6->sin6_addr, AF_INET6).str, ntohs(sin6->sin6_port));
DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "Listen socket initialized: name=%s fd=%d addr=%s:%d", e_sock->name, e_sock->fd, ip_to_str(&sin6->sin6_addr, AF_INET6).str, ntohs(sin6->sin6_port));
} }
} }
// Определяем interface_addr: IP интерфейса или из конфига // Определяем interface_addr: IP интерфейса или из конфига
@ -704,7 +693,7 @@ struct ETCP_SOCKET* etcp_socket_add(struct UTUN_INSTANCE* instance, struct CFG_S
if (e_sock->interface_addr.ss_family != 0) { if (e_sock->interface_addr.ss_family != 0) {
snprintf(netif_str, sizeof(netif_str), "%s", sockaddr_storage_to_str(&e_sock->interface_addr).str); snprintf(netif_str, sizeof(netif_str), "%s", sockaddr_storage_to_str(&e_sock->interface_addr).str);
} }
DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "Listen socket initialized: name=%s fd=%d config=%s, netif=%s", e_sock->name, e_sock->fd, config_str, netif_str); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "Listen socket initialized: name=%s fd=%d config=%s, netif=%s", e_sock->name, e_sock->fd, config_str, netif_str);
e_sock->instance = instance; e_sock->instance = instance;
e_sock->errorcode = 0; e_sock->errorcode = 0;
@ -714,7 +703,7 @@ struct ETCP_SOCKET* etcp_socket_add(struct UTUN_INSTANCE* instance, struct CFG_S
e_sock->nat_type = NAT_TYPE_UNKNOWN; // только результат детекции NAT, серверные сокеты стартуют с unknown e_sock->nat_type = NAT_TYPE_UNKNOWN; // только результат детекции NAT, серверные сокеты стартуют с unknown
e_sock->mtu = mtu; e_sock->mtu = mtu;
e_sock->only_local = only_local; e_sock->only_local = only_local;
DEBUG_INFO(DEBUG_CATEGORY_BGP, "Add Socket type=%d", type); DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "Add Socket type=%d", type);
e_sock->next = instance->etcp_sockets; e_sock->next = instance->etcp_sockets;
instance->etcp_sockets = e_sock; instance->etcp_sockets = e_sock;
e_sock->socket_id = uasync_add_socket_t(instance->ua, e_sock->fd, etcp_connections_read_callback_socket, NULL, NULL, e_sock); e_sock->socket_id = uasync_add_socket_t(instance->ua, e_sock->fd, etcp_connections_read_callback_socket, NULL, NULL, e_sock);
@ -851,10 +840,9 @@ struct ETCP_LINK* etcp_link_new(struct ETCP_CONN* etcp, struct ETCP_SOCKET* conn
etcp_link_update_inflight_lim(link, link->inflight_lim_bytes); etcp_link_update_inflight_lim(link, link->inflight_lim_bytes);
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "NEW link initialized on etcp=[%s] link=%p socket=%s id=%d is_server=%d mtu=%d", etcp->log_name, link, conn->name, link->local_link_id, link->is_server, link->mtu); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "NEW link initialized on etcp=[%s] link=%p socket=%s id=%d is_server=%d mtu=%d", etcp->log_name, link, conn->name, link->local_link_id, link->is_server, link->mtu);
if (is_server == 0) { if (is_server == 0) {
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "client link, calling etcp_link_send_init");
etcp_link_enter_init(link); etcp_link_enter_init(link);
} }
@ -989,12 +977,12 @@ es_err:
static int etcp_send_ping_raw(struct ETCP_DGRAM* dgram, socket_t fd, sc_context_t* sc, const struct sockaddr_storage* addr) { static int etcp_send_ping_raw(struct ETCP_DGRAM* dgram, socket_t fd, sc_context_t* sc, const struct sockaddr_storage* addr) {
if (!dgram || !sc || !addr) { if (!dgram || !sc || !addr) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "Null pointer in ping send"); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "Null pointer in ping send");
return -1; return -1;
} }
int len = dgram->data_len - dgram->noencrypt_len; int len = dgram->data_len - dgram->noencrypt_len;
if (len < 0 || len > PACKET_DATA_SIZE - UDP_HDR_SIZE) { if (len < 0 || len > PACKET_DATA_SIZE - UDP_HDR_SIZE) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "ping packet data invalid len=%d", len); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "ping packet data invalid len=%d", len);
return -1; return -1;
} }
uint8_t enc_buf[1600]; uint8_t enc_buf[1600];
@ -1003,11 +991,11 @@ static int etcp_send_ping_raw(struct ETCP_DGRAM* dgram, socket_t fd, sc_context_
dgram->flag_up = 1; dgram->flag_up = 1;
sc_encrypt(sc, (uint8_t*)&dgram->timestamp, 3 + len, enc_buf, &enc_buf_len); sc_encrypt(sc, (uint8_t*)&dgram->timestamp, 3 + len, enc_buf, &enc_buf_len);
if (enc_buf_len == 0) { if (enc_buf_len == 0) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "encryption failed for ping"); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "encryption failed for ping");
return -1; return -1;
} }
if (enc_buf_len + dgram->noencrypt_len > (size_t)(PACKET_DATA_SIZE - UDP_HDR_SIZE)) { if (enc_buf_len + dgram->noencrypt_len > (size_t)(PACKET_DATA_SIZE - UDP_HDR_SIZE)) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "ping packet too long enc=%zu ne=%d", enc_buf_len, dgram->noencrypt_len); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "ping packet too long enc=%zu ne=%d", enc_buf_len, dgram->noencrypt_len);
return -1; return -1;
} }
memcpy(enc_buf + enc_buf_len, dgram->data + len, dgram->noencrypt_len); memcpy(enc_buf + enc_buf_len, dgram->data + len, dgram->noencrypt_len);
@ -1017,10 +1005,10 @@ static int etcp_send_ping_raw(struct ETCP_DGRAM* dgram, socket_t fd, sc_context_
//xaddr[0]=192; xaddr[1]=168; xaddr[2]=10; xaddr[3]=1; //xaddr[0]=192; xaddr[1]=168; xaddr[2]=10; xaddr[3]=1;
sent = socket_sendto(fd, enc_buf, enc_buf_len + dgram->noencrypt_len, (struct sockaddr*)addr, addr_len); sent = socket_sendto(fd, enc_buf, enc_buf_len + dgram->noencrypt_len, (struct sockaddr*)addr, addr_len);
if (sent < 0) { if (sent < 0) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "sendto failed for ping, err=%d addr=%s fd=%d len=%d", socket_get_error(), sockaddr_storage_to_str(addr).str, fd, enc_buf_len + dgram->noencrypt_len); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "sendto failed for ping, err=%d addr=%s fd=%d len=%d", socket_get_error(), sockaddr_storage_to_str(addr).str, fd, enc_buf_len + dgram->noencrypt_len);
return -1; return -1;
} }
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "ping sendto succeeded to %s sent=%zd bytes fd=%d", sockaddr_storage_to_str(addr).str, sent, fd); DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "ping sendto succeeded to %s sent=%zd bytes fd=%d", sockaddr_storage_to_str(addr).str, sent, fd);
return (int)sent; return (int)sent;
} }
@ -1055,16 +1043,16 @@ int etcp_send_ping_to_socket(struct UTUN_INSTANCE* instance, struct ETCP_SOCKET*
int timeout_ms, etcp_ping_callback_t cb, void* user_arg, int timeout_ms, etcp_ping_callback_t cb, void* user_arg,
const uint8_t* user_data, size_t user_data_len) { const uint8_t* user_data, size_t user_data_len) {
if (!instance || !e_sock || !peer_pubkey_bin || !addr || timeout_ms <= 0 || !cb) { if (!instance || !e_sock || !peer_pubkey_bin || !addr || timeout_ms <= 0 || !cb) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "bad args"); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "bad args");
return -1; return -1;
} }
if (user_data_len > PACKET_DATA_SIZE - 24 - 2 - SC_PUBKEY_ENC_SIZE) { if (user_data_len > PACKET_DATA_SIZE - 24 - 2 - SC_PUBKEY_ENC_SIZE) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "user_data too long"); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "user_data too long");
return -2; return -2;
} }
struct PING_CONTEXT* ctx = u_malloc(sizeof(struct PING_CONTEXT)); struct PING_CONTEXT* ctx = u_malloc(sizeof(struct PING_CONTEXT));
if (!ctx) { if (!ctx) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "malloc ctx"); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "malloc ctx");
return -3; return -3;
} }
ctx->next = NULL; ctx->next = NULL;
@ -1080,7 +1068,7 @@ int etcp_send_ping_to_socket(struct UTUN_INSTANCE* instance, struct ETCP_SOCKET*
ctx->user_data = u_malloc(user_data_len); ctx->user_data = u_malloc(user_data_len);
if (!ctx->user_data) { if (!ctx->user_data) {
u_free(ctx); u_free(ctx);
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "malloc user_data"); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "malloc user_data");
return -3; return -3;
} }
memcpy(ctx->user_data, user_data, user_data_len); memcpy(ctx->user_data, user_data, user_data_len);
@ -1090,7 +1078,7 @@ int etcp_send_ping_to_socket(struct UTUN_INSTANCE* instance, struct ETCP_SOCKET*
if (!dgram) { if (!dgram) {
if (ctx->user_data) u_free(ctx->user_data); if (ctx->user_data) u_free(ctx->user_data);
u_free(ctx); u_free(ctx);
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "malloc dgram"); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "malloc dgram");
return -4; return -4;
} }
dgram->link = NULL; dgram->link = NULL;
@ -1124,7 +1112,7 @@ int etcp_send_ping_to_socket(struct UTUN_INSTANCE* instance, struct ETCP_SOCKET*
DEBUG_ERROR(DEBUG_CATEGORY_CRYPTO, "set key failed"); DEBUG_ERROR(DEBUG_CATEGORY_CRYPTO, "set key failed");
return -5; return -5;
} }
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "ping sent nonce=%016llx timeout=%d ulen=%zu", DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "ping sent nonce=%016llx timeout=%d ulen=%zu",
(unsigned long long)ctx->nonce, timeout_ms, user_data_len); (unsigned long long)ctx->nonce, timeout_ms, user_data_len);
etcp_send_ping_raw(dgram, e_sock->fd, &sc, addr); etcp_send_ping_raw(dgram, e_sock->fd, &sc, addr);
u_free(dgram); u_free(dgram);
@ -1144,7 +1132,7 @@ int etcp_send_ping(struct UTUN_INSTANCE* instance, const uint8_t* peer_pubkey_bi
etcp_ping_callback_t cb, void* user_arg, etcp_ping_callback_t cb, void* user_arg,
const uint8_t* user_data, size_t user_data_len) { const uint8_t* user_data, size_t user_data_len) {
if (!instance || !peer_pubkey_bin || !addr || timeout_ms <= 0 || !cb) { if (!instance || !peer_pubkey_bin || !addr || timeout_ms <= 0 || !cb) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "bad args: inst=%p pubkey=%p addr=%p timeout=%d cb=%p udata=%p udata_len=%zu", DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "bad args: inst=%p pubkey=%p addr=%p timeout=%d cb=%p udata=%p udata_len=%zu",
(void*)instance, (void*)peer_pubkey_bin, (void*)addr, timeout_ms, (void*)instance, (void*)peer_pubkey_bin, (void*)addr, timeout_ms,
(void*)(uintptr_t)cb, (void*)user_data, user_data_len); (void*)(uintptr_t)cb, (void*)user_data, user_data_len);
return -1; return -1;
@ -1152,10 +1140,10 @@ int etcp_send_ping(struct UTUN_INSTANCE* instance, const uint8_t* peer_pubkey_bi
struct ETCP_SOCKET* e_sock = instance->etcp_sockets; struct ETCP_SOCKET* e_sock = instance->etcp_sockets;
while (e_sock && e_sock->local_addr.ss_family != addr->ss_family) e_sock = e_sock->next; while (e_sock && e_sock->local_addr.ss_family != addr->ss_family) e_sock = e_sock->next;
if (!e_sock) { if (!e_sock) {
DEBUG_ERROR(DEBUG_CATEGORY_BGP, "no socket for addr_family=%d", addr->ss_family); DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "no socket for addr_family=%d", addr->ss_family);
return -2; return -2;
} }
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "ping N1 [%s]", sockaddr_storage_to_str(addr).str); DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "ping N1 [%s]", sockaddr_storage_to_str(addr).str);
return etcp_send_ping_to_socket(instance, e_sock, peer_pubkey_bin, addr, timeout_ms, return etcp_send_ping_to_socket(instance, e_sock, peer_pubkey_bin, addr, timeout_ms,
cb, user_arg, user_data, user_data_len); cb, user_arg, user_data, user_data_len);
} }
@ -1194,7 +1182,7 @@ static int handle_ping(struct ETCP_SOCKET* e_sock, struct ETCP_DGRAM* pkt, const
sc_context_t resp_sc; sc_context_t resp_sc;
sc_init_ctx(&resp_sc, &e_sock->instance->my_keys); sc_init_ctx(&resp_sc, &e_sock->instance->my_keys);
if (sc_set_peer_public_key(&resp_sc, decrypted_pubkey, SC_PEER_PUBKEY_BIN) == SC_OK) { if (sc_set_peer_public_key(&resp_sc, decrypted_pubkey, SC_PEER_PUBKEY_BIN) == SC_OK) {
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "PONG send nonce=%016llx to=%s fd=%d", DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "PONG send nonce=%016llx to=%s fd=%d",
(unsigned long long)nonce, sockaddr_storage_to_str(addr).str, e_sock->fd); (unsigned long long)nonce, sockaddr_storage_to_str(addr).str, e_sock->fd);
etcp_send_ping_raw(resp, e_sock->fd, &resp_sc, addr); etcp_send_ping_raw(resp, e_sock->fd, &resp_sc, addr);
} }
@ -1218,7 +1206,7 @@ static int handle_pong(struct ETCP_SOCKET* e_sock, struct ETCP_DGRAM* pkt, const
udata = pkt->data + 19; udata = pkt->data + 19;
} }
} }
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "PONG recv nonce=%016llx data_len=%u from=%s socket=%s", DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "PONG recv nonce=%016llx data_len=%u from=%s socket=%s",
(unsigned long long)nonce, (unsigned)pkt->data_len, (unsigned long long)nonce, (unsigned)pkt->data_len,
sockaddr_storage_to_str(addr).str, e_sock->name); sockaddr_storage_to_str(addr).str, e_sock->name);
struct PING_CONTEXT* ctx = e_sock->instance->pending_pings; struct PING_CONTEXT* ctx = e_sock->instance->pending_pings;
@ -1235,7 +1223,7 @@ static int handle_pong(struct ETCP_SOCKET* e_sock, struct ETCP_DGRAM* pkt, const
} }
uint64_t now = get_time_tb(); uint64_t now = get_time_tb();
uint16_t rtt = (now >= ctx->send_time) ? (uint16_t)(now - ctx->send_time) : 0; uint16_t rtt = (now >= ctx->send_time) ? (uint16_t)(now - ctx->send_time) : 0;
DEBUG_DEBUG(DEBUG_CATEGORY_BGP, "PONG matched nonce=%016llx rtt=%u", DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "PONG matched nonce=%016llx rtt=%u",
(unsigned long long)nonce, (unsigned)rtt); (unsigned long long)nonce, (unsigned)rtt);
ctx->cb(1, rtt, ctx->arg, nonce, udata, ulen); ctx->cb(1, rtt, ctx->arg, nonce, udata, ulen);
if (ctx->user_data) u_free(ctx->user_data); if (ctx->user_data) u_free(ctx->user_data);
@ -1246,7 +1234,7 @@ static int handle_pong(struct ETCP_SOCKET* e_sock, struct ETCP_DGRAM* pkt, const
ctx = ctx->next; ctx = ctx->next;
} }
if (!found) { if (!found) {
DEBUG_WARN(DEBUG_CATEGORY_BGP, "PONG nonce=%016llx NOT FOUND in pending (timeout?)", DEBUG_WARN(DEBUG_CATEGORY_CONNECTION, "PONG nonce=%016llx NOT FOUND in pending (timeout?)",
(unsigned long long)nonce); (unsigned long long)nonce);
} }
memory_pool_free(e_sock->instance->pkt_pool, pkt); memory_pool_free(e_sock->instance->pkt_pool, pkt);
@ -1303,7 +1291,7 @@ static void send_init_response(struct ETCP_SOCKET* e_sock, struct ETCP_DGRAM* pk
link->remote_socket_id, link->remote_socket_id,
link->nat_ip, link->nat_port, NAT_TYPE_DIRECT); link->nat_ip, link->nat_port, NAT_TYPE_DIRECT);
} }
DEBUG_INFO(DEBUG_CATEGORY_BGP, "DIRECT IP: %s:%u for %s", DEBUG_INFO(DEBUG_CATEGORY_NAT, "DIRECT IP: %s:%u for %s",
ip_to_str(&link->nat_ip, AF_INET).str, link->nat_port, ip_to_str(&link->nat_ip, AF_INET).str, link->nat_port,
link->etcp->log_name); link->etcp->log_name);
} }
@ -1361,9 +1349,9 @@ static void send_init_response(struct ETCP_SOCKET* e_sock, struct ETCP_DGRAM* pk
for (int i=0; i<to_add; i++) pkt->data[xoffset++]=rand();// fill pad for (int i=0; i<to_add; i++) pkt->data[xoffset++]=rand();// fill pad
// padding end // padding end
pkt->data_len=xoffset; pkt->data_len=xoffset;
DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "Sending INIT RESPONSE, link=%p, local_link_id=%d, remote_link_id=%d, dst=%s fd=%d", DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] INIT_RESPONSE sent (link=%d, mtu=%d, dst=%s)",
link, link->local_link_id, link->remote_link_id, link->etcp->log_name, link->local_link_id, link->mtu_local,
sockaddr_storage_to_str(&link->remote_addr).str, link->conn->fd); sockaddr_storage_to_str(&link->remote_addr).str);
etcp_encrypt_send(pkt); etcp_encrypt_send(pkt);
memory_pool_free(e_sock->instance->pkt_pool, pkt); memory_pool_free(e_sock->instance->pkt_pool, pkt);
@ -1375,9 +1363,9 @@ static void send_init_response(struct ETCP_SOCKET* e_sock, struct ETCP_DGRAM* pk
} }
if (link->etcp->initialized == 0) { if (link->etcp->initialized == 0) {
etcp_conn_ready(link->etcp); etcp_conn_ready(link->etcp);
DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "Connection established: log_name=%s socket=%s link_id=%d status=UP", link->etcp->log_name, e_sock->name, link->local_link_id); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Connection established (socket=%s, link=%d)", link->etcp->log_name, e_sock->name, link->local_link_id);
} }
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "[%s] Link %p (local_id=%d) initialized and marked as UP (server)", link->etcp->log_name, link, link->local_link_id); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Link %d UP (server, mtu=%d)", link->etcp->log_name, link->local_link_id, link->mtu_local);
start_keepalive_timer(link); start_keepalive_timer(link);
loadbalancer_link_ready(link); loadbalancer_link_ready(link);
// Restart NAT check after link is up (e.g. after address change or reinit) // Restart NAT check after link is up (e.g. after address change or reinit)
@ -1410,6 +1398,7 @@ static int handle_init_response_client(struct ETCP_SOCKET* e_sock, struct ETCP_D
link->remote_socket_id = resp->remote_socket_id; link->remote_socket_id = resp->remote_socket_id;
link->remote_only_local = resp->only_local; link->remote_only_local = resp->only_local;
link->remote_type = resp->type; link->remote_type = resp->type;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] INIT_RESPONSE received (link=%d, mtu=%d, session=%08x)", link->etcp->log_name, link->remote_link_id, link->mtu, resp_session_id);
// Parse NAT IP:port from response (new format includes 4+2 bytes) // Parse NAT IP:port from response (new format includes 4+2 bytes)
if (pkt_len >= ETCP_INIT_RESP_SIZE) { if (pkt_len >= ETCP_INIT_RESP_SIZE) {
@ -1464,10 +1453,8 @@ static int handle_init_response_client(struct ETCP_SOCKET* e_sock, struct ETCP_D
memcpy(link->remote_ed25519_pubkey, resp->ed25519_pubkey, SC_PUBKEY_SIZE); memcpy(link->remote_ed25519_pubkey, resp->ed25519_pubkey, SC_PUBKEY_SIZE);
memcpy(link->etcp->peer_ed25519_pubkey, resp->ed25519_pubkey, SC_PUBKEY_SIZE); memcpy(link->etcp->peer_ed25519_pubkey, resp->ed25519_pubkey, SC_PUBKEY_SIZE);
DEBUG_INFO(DEBUG_CATEGORY_CRYPTO, "[%s] Received Ed25519 pubkey from peer", link->etcp->log_name); DEBUG_DEBUG(DEBUG_CATEGORY_CRYPTO, "[%s] Received Ed25519 pubkey from peer", link->etcp->log_name);
// DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "Received INIT_RESPONSE from server_node_id=%llu, mtu=%d", (unsigned long long)server_node_id, link->mtu);
etcp_conn_set_peer_node_id(link->etcp, server_node_id); etcp_conn_set_peer_node_id(link->etcp, server_node_id);
@ -1479,7 +1466,7 @@ static int handle_init_response_client(struct ETCP_SOCKET* e_sock, struct ETCP_D
} }
if (pkt_code == ETCP_INIT_RESPONSE && !link->etcp->reset_done) { if (pkt_code == ETCP_INIT_RESPONSE && !link->etcp->reset_done) {
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "[%s] REINIT from client: INIT_RESPONSE(0x03) received, reinit conn=%p", DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] REINIT from client: INIT_RESPONSE(0x03) received, reinit conn=%p",
link->etcp->log_name, link->etcp); link->etcp->log_name, link->etcp);
etcp_conn_reinit(link->etcp); etcp_conn_reinit(link->etcp);
} }
@ -1489,8 +1476,7 @@ static int handle_init_response_client(struct ETCP_SOCKET* e_sock, struct ETCP_D
} }
loadbalancer_link_ready(link); loadbalancer_link_ready(link);
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "[%s] Link %p (local_id=%d) initialized and marked as UP (client): rk=%d lk=%d up=%d ki=%d", DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Link %d UP (client, mtu=%d)", link->etcp->log_name, link->local_link_id, link->mtu);
link->etcp->log_name, link, link->local_link_id, link->recv_keepalive, link->remote_keepalive, link->link_status, link->keepalive_interval);
// Start keepalive timer // Start keepalive timer
etcp_link_send_keepalive(link); etcp_link_send_keepalive(link);
@ -1682,13 +1668,9 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
uint32_t session_id = be32toh(*(uint32_t*)req->session_id); uint32_t session_id = be32toh(*(uint32_t*)req->session_id);
uint16_t mtu = be16toh(*(uint16_t*)req->mtu); uint16_t mtu = be16toh(*(uint16_t*)req->mtu);
uint16_t src_port = be16toh(*(uint16_t*)req->src_port); uint16_t src_port = be16toh(*(uint16_t*)req->src_port);
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, DEBUG_INFO(DEBUG_CATEGORY_ETCP, "INIT received: peer=0x%016llx mtu=%u link=%u sock=%u session=%08x src=%s",
"INIT accepted: peer=0x%016llx mtu=%u link=%u sock=%u type=%d local=%d"
" src_ip=%d.%d.%d.%d:%u session=%08x src=%s",
(unsigned long long)peer_id, mtu, req->link_id, req->socket_id, (unsigned long long)peer_id, mtu, req->link_id, req->socket_id,
req->type, req->only_local, session_id, sockaddr_storage_to_str(&addr).str);
req->src_ipv4[0], req->src_ipv4[1], req->src_ipv4[2], req->src_ipv4[3],
src_port, session_id, sockaddr_storage_to_str(&addr).str);
struct ETCP_CONN* conn = NULL; struct ETCP_CONN* conn = NULL;
{ {
@ -1714,7 +1696,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
if (!conn) { errorcode=55; DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "failed to create connection"); goto ec_fr; } if (!conn) { errorcode=55; DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "failed to create connection"); goto ec_fr; }
memcpy(&conn->crypto_ctx, &sc, sizeof(sc)); memcpy(&conn->crypto_ctx, &sc, sizeof(sc));
etcp_conn_set_peer_node_id(conn, peer_id); etcp_conn_set_peer_node_id(conn, peer_id);
DEBUG_INFO(DEBUG_CATEGORY_GENERAL, "New connection received on socket %s: log_name=%s peer_id=%lu peer:%s", e_sock->name, conn->log_name, (unsigned long)peer_id, sockaddr_storage_to_str(&addr).str); DEBUG_INFO(DEBUG_CATEGORY_ETCP, "New connection received on socket %s: log_name=%s peer_id=%lu peer:%s", e_sock->name, conn->log_name, (unsigned long)peer_id, sockaddr_storage_to_str(&addr).str);
DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "New connection from %s peer_id=%ld etcp=%p total=%d", DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "New connection from %s peer_id=%ld etcp=%p total=%d",
ip_to_str(&addr, addr.ss_family).str, peer_id, conn, ip_to_str(&addr, addr.ss_family).str, peer_id, conn,
queue_entry_count(e_sock->instance->connections)); queue_entry_count(e_sock->instance->connections));
@ -1890,8 +1872,8 @@ process_decrypted:
/* restore recv_keepalive BEFORE computing link_status = remote && local */ /* restore recv_keepalive BEFORE computing link_status = remote && local */
if (link->recv_keepalive != 1) { if (link->recv_keepalive != 1) {
link->recv_keepalive = 1; link->recv_keepalive = 1;
DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "[%s] Link %p (local_id=%d) status changed to UP - packet received", DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] Link %d status changed to UP - packet received",
link->etcp->log_name, link, link->local_link_id); link->etcp->log_name, link->local_link_id);
} }
int was_up = link->link_status; int was_up = link->link_status;

Write Preview
Loading…
Cancel
Save