From 2bf7dcc6f0a78e60dc82f5501f4bb9ee4eb7c1a1 Mon Sep 17 00:00:00 2001 From: Evgeny Date: Wed, 15 Jul 2026 11:46:44 +0300 Subject: [PATCH] =?UTF-8?q?debug:=20comprehensive=20connection=20diagnosti?= =?UTF-8?q?cs=20=E2=80=94=20recv/send/reinit=20paths?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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) --- src/etcp.c | 3 ++- src/etcp_connections.c | 42 +++++++++++++++++++++++++++--------------- 2 files changed, 29 insertions(+), 16 deletions(-) diff --git a/src/etcp.c b/src/etcp.c index 1dc6e5d2..6cd5c8d4 100644 --- a/src/etcp.c +++ b/src/etcp.c @@ -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++; diff --git a/src/etcp_connections.c b/src/etcp_connections.c index aa05de04..1a28cc27 100644 --- a/src/etcp_connections.c +++ b/src/etcp_connections.c @@ -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; idata[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); }