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

debug: comprehensive connection diagnostics — recv/send/reinit paths

Browse Source 
- RECV: log every packet (src addr, link found, session_ready, decrypt result)
- RECV: log init decrypt rejection with packet code (catches 0x03 INIT_RESPONSE
  silently dropped by init path)
- SEND: log destination addr+fd in send_init_response and etcp_encrypt_send
- REINIT: log full reason in server and client paths (code, session, got_init,
  initialized, links_up state before reinit)
This commit is contained in:
Evgeny committed 2026-07-15 11:46:44 +03:00
1 parent f7d88e5532
commit 2bf7dcc6f0
2 files changed
+29 -16
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

src/etcp.c
+2 -1
View File
@@ -499,7 +499,8 @@ void etcp_links_reset(struct ETCP_CONN* etcp) {// Если сбой в обме
}
void etcp_conn_reinit(struct ETCP_CONN* etcp) {// Если сбой в обмене или ребутнулась одна из сторон -> необходимо заново переинициализировать соединение
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "Reinitializing ETCP connection [%s]", etcp->log_name);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "[%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->reinit_count++;
src/etcp_connections.c
+27 -15
View File
@@ -967,11 +967,13 @@ int etcp_encrypt_send(struct ETCP_DGRAM* dgram) {
ssize_t sent = etcp_udp_send(dgram->link, dgram->link->conn->fd, enc_buf, enc_buf_len + dgram->noencrypt_len,
(struct sockaddr*)addr, addr_len);
if (sent < 0) {
DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "sendto failed, sock_err=%d", socket_get_error());
if (sent < 0) {
DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "sendto failed, sock_err=%d dst=%s fd=%d",
socket_get_error(), sockaddr_storage_to_str(addr).str, dgram->link->conn->fd);
dgram->link->send_errors++; errcode=4; goto es_err;
} else {
DEBUG_TRACE(DEBUG_CATEGORY_CONNECTION, "sendto succeeded, sent=%zd bytes to port %d fd=%d", sent, ntohs(((struct sockaddr_in*)addr)->sin_port), dgram->link->conn->fd);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "ETCP SEND %zd bytes to %s fd=%d ne_len=%d", sent,
sockaddr_storage_to_str(addr).str, dgram->link->conn->fd, dgram->noencrypt_len);
}
return (int)sent;
es_err:
@@ -1352,8 +1354,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
// padding end
pkt->data_len=xoffset;
DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "Sending INIT RESPONSE, link=%p, local_link_id=%d, remote_link_id=%d", link, link->local_link_id, link->remote_link_id);
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[ETCP DEBUG] Send INIT RESPONSE");
DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "Sending INIT RESPONSE, link=%p, local_link_id=%d, remote_link_id=%d, dst=%s fd=%d",
link, link->local_link_id, link->remote_link_id,
sockaddr_storage_to_str(&link->remote_addr).str, link->conn->fd);
etcp_encrypt_send(pkt);
memory_pool_free(e_sock->instance->pkt_pool, pkt);
@@ -1471,7 +1474,8 @@ static int handle_init_response_client(struct ETCP_SOCKET* e_sock, struct ETCP_D
}
if (pkt_code == ETCP_INIT_RESPONSE) {
DEBUG_TRACE(DEBUG_CATEGORY_CONNECTION, "do reinit 3 %p", link->etcp);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "[%s] REINIT from client: INIT_RESPONSE(0x03) received, reinit conn=%p",
link->etcp->log_name, link->etcp);
etcp_conn_reinit(link->etcp);
}
@@ -1529,7 +1533,7 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "recvfrom failed, error=%zd, sock_err=%d", recv_len, socket_get_error());
return;
}
// DUMP: Show received packet content
if (debug_should_output(DEBUG_LEVEL_DEBUG, DEBUG_CATEGORY_CRYPTO)) log_dump(DEBUG_LEVEL_DEBUG, DEBUG_CATEGORY_CRYPTO, "RECV in:", data, recv_len);
@@ -1539,6 +1543,9 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
int errorcode=0;
struct ETCP_LINK* link=etcp_link_find_by_addr(e_sock, &addr);
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "RECV %zd bytes from %s link=%p session_ready=%d",
recv_len, sockaddr_storage_to_str(&addr).str, link,
link && link->etcp ? link->etcp->crypto_ctx.session_ready : -1);
// Try normal decryption first if we have an established link with session keys
// This is the common case for data packets and responses
@@ -1547,13 +1554,15 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
// }
if (link!=NULL && link->etcp!=NULL && link->etcp->crypto_ctx.session_ready) {
// DEBUG_INFO(DEBUG_CATEGORY_ETCP, "Decrypt start (normal)");
if (!sc_decrypt(&link->etcp->crypto_ctx, data, recv_len, (uint8_t*)&pkt->timestamp, &pkt_len)) {
// Normal decryption succeeded - process packet normally
sc_status_t dec_rc = sc_decrypt(&link->etcp->crypto_ctx, data, recv_len, (uint8_t*)&pkt->timestamp, &pkt_len);
if (!dec_rc) {
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "DECRYPT OK link=%p log=%s", link, link->etcp->log_name);
goto process_decrypted;
}
// Normal decryption failed - might be INIT packet, fall through to INIT handling
DEBUG_DEBUG(DEBUG_CATEGORY_CONNECTION, "Normal decryption failed, trying INIT decryption");
DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "DECRYPT FAIL link=%p log=%s rc=%d — trying init decrypt", link, link->etcp->log_name, dec_rc);
} else {
DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "SKIP normal decrypt: link=%p session_ready=%d — trying init decrypt",
link, link && link->etcp ? link->etcp->crypto_ctx.session_ready : -1);
}
// Try INIT decryption (for incoming connection requests)
@@ -1616,7 +1625,8 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
return;
}
if (code!=ETCP_INIT_REQUEST && code!=ETCP_INIT_REQUEST_NOINIT) {
DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "not an init packet, code=%02x", code);
DEBUG_ERROR(DEBUG_CATEGORY_DEBUG, "not an init packet: code=0x%02x (expected 0x02/0x04) from %s — packet dropped",
code, sockaddr_storage_to_str(&addr).str);
errorcode=4;
goto ec_fr;
}// не init
@@ -1738,7 +1748,8 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
// Check session_id: if same - no reinit, if different - client restarted, do reinit
if (code == ETCP_INIT_REQUEST || conn->session_id != session_id || !conn->got_initial_pkt) {
send_reset = 1; // Client explicitly requested reset, or new session, or server waiting for first packet
DEBUG_TRACE(DEBUG_CATEGORY_CONNECTION, "do reinit (code=%02x session was %08x now %08x got_init=%d)", code, conn->session_id, session_id, conn->got_initial_pkt);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "[%s] REINIT existing 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);
conn->session_id = session_id;
etcp_conn_reinit(conn);
} else {
@@ -1764,7 +1775,8 @@ void etcp_connections_read_callback_socket(socket_t sock, void* arg) {
// For new links: reset if client requested or session changed
if (code == ETCP_INIT_REQUEST || conn->session_id != session_id || !conn->got_initial_pkt) {
send_reset = 1;
DEBUG_TRACE(DEBUG_CATEGORY_CONNECTION, "do reinit for new link (code=%02x session was %08x now %08x got_init=%d)", code, conn->session_id, session_id, conn->got_initial_pkt);
DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "[%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);
conn->session_id = session_id;
etcp_conn_reinit(conn);
}