diff --git a/src/etcp.c b/src/etcp.c index 99527832..46efddcc 100644 --- a/src/etcp.c +++ b/src/etcp.c @@ -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) { - 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; struct etcp_cbk_entry* cbe = etcp->up_cbks; 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) { - 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; struct etcp_cbk_entry* cbe = etcp->down_cbks; 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) {// Если сбой в обмене или ребутнулась одна из сторон -> необходимо заново переинициализировать соединение - 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->reinit_count++; @@ -584,7 +584,7 @@ void etcp_conn_queue_set_ready(struct ETCP_CONN* conn) { if (!conn || conn->state != 0) return; // 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); if (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->state = 1; 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)); 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) обязательно в конец - 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++]=inf_pkt->seq; @@ -1539,7 +1539,8 @@ void etcp_conn_input(struct ETCP_DGRAM* pkt) { 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); } 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; break; } diff --git a/src/etcp_connections.c b/src/etcp_connections.c index 1daf387a..7560ba50 100644 --- a/src/etcp_connections.c +++ b/src/etcp_connections.c @@ -177,16 +177,7 @@ static void etcp_link_send_init(struct ETCP_LINK* link, uint8_t reset, uint8_t c 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: 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); - } + 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); etcp_encrypt_send(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) { 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_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) { 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_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 интерфейса или из конфига @@ -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) { 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->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->mtu = mtu; 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; 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); @@ -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); - 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) { - DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, "client link, calling etcp_link_send_init"); 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) { 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; } int len = dgram->data_len - dgram->noencrypt_len; 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; } 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; sc_encrypt(sc, (uint8_t*)&dgram->timestamp, 3 + len, enc_buf, &enc_buf_len); 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; } 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; } 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; sent = socket_sendto(fd, enc_buf, enc_buf_len + dgram->noencrypt_len, (struct sockaddr*)addr, addr_len); 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; } - 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; } @@ -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, const uint8_t* user_data, size_t user_data_len) { 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; } 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; } struct PING_CONTEXT* ctx = u_malloc(sizeof(struct PING_CONTEXT)); if (!ctx) { - DEBUG_ERROR(DEBUG_CATEGORY_BGP, "malloc ctx"); + DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "malloc ctx"); return -3; } 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); if (!ctx->user_data) { u_free(ctx); - DEBUG_ERROR(DEBUG_CATEGORY_BGP, "malloc user_data"); + DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "malloc user_data"); return -3; } 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 (ctx->user_data) u_free(ctx->user_data); u_free(ctx); - DEBUG_ERROR(DEBUG_CATEGORY_BGP, "malloc dgram"); + DEBUG_ERROR(DEBUG_CATEGORY_CONNECTION, "malloc dgram"); return -4; } 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"); 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); etcp_send_ping_raw(dgram, e_sock->fd, &sc, addr); 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, const uint8_t* user_data, size_t user_data_len) { 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*)(uintptr_t)cb, (void*)user_data, user_data_len); 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; while (e_sock && e_sock->local_addr.ss_family != addr->ss_family) e_sock = e_sock->next; 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; } - 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, 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_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) { - 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); 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; } } - 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, sockaddr_storage_to_str(addr).str, e_sock->name); 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(); 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); ctx->cb(1, rtt, ctx->arg, nonce, udata, ulen); 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; } 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); } 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->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, 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; 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, dst=%s fd=%d", - link, link->local_link_id, link->remote_link_id, - sockaddr_storage_to_str(&link->remote_addr).str, link->conn->fd); + DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] INIT_RESPONSE sent (link=%d, mtu=%d, dst=%s)", + link->etcp->log_name, link->local_link_id, link->mtu_local, + sockaddr_storage_to_str(&link->remote_addr).str); etcp_encrypt_send(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) { 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); loadbalancer_link_ready(link); // 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_only_local = resp->only_local; 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) 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->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); @@ -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) { - 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); 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); - 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", - link->etcp->log_name, link, link->local_link_id, link->recv_keepalive, link->remote_keepalive, link->link_status, link->keepalive_interval); + DEBUG_INFO(DEBUG_CATEGORY_ETCP, "[%s] Link %d UP (client, mtu=%d)", link->etcp->log_name, link->local_link_id, link->mtu); // Start keepalive timer 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); uint16_t mtu = be16toh(*(uint16_t*)req->mtu); uint16_t src_port = be16toh(*(uint16_t*)req->src_port); - DEBUG_INFO(DEBUG_CATEGORY_CONNECTION, - "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", + DEBUG_INFO(DEBUG_CATEGORY_ETCP, "INIT received: peer=0x%016llx mtu=%u link=%u sock=%u session=%08x src=%s", (unsigned long long)peer_id, mtu, req->link_id, req->socket_id, - req->type, req->only_local, - 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); + session_id, sockaddr_storage_to_str(&addr).str); 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; } memcpy(&conn->crypto_ctx, &sc, sizeof(sc)); 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", ip_to_str(&addr, addr.ss_family).str, peer_id, conn, queue_entry_count(e_sock->instance->connections)); @@ -1890,8 +1872,8 @@ process_decrypted: /* restore recv_keepalive BEFORE computing link_status = remote && local */ if (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", - link->etcp->log_name, link, link->local_link_id); + DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "[%s] Link %d status changed to UP - packet received", + link->etcp->log_name, link->local_link_id); } int was_up = link->link_status;