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

logging: distinguish STCP probes from data link lifecycle

Browse Source
This commit is contained in:
evgeny committed 2026-10-07 21:11:12 +02:00
1 parent adc8b2a670
commit 6d54a7c102
2 files changed
+34 -15
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

src/transport_layer/stcp_client.c
+22 -9
View File
@@ -97,7 +97,8 @@ static void client_send_handshake(struct stcp_conn *c, const uint8_t *server_pub
c->hs_send_time = get_time_tb(); c->hs_send_time = get_time_tb();
c->state = STCP_STATE_HS_CLIENT_SENT; c->state = STCP_STATE_HS_CLIENT_SENT;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_client: handshake sent (%zu bytes) gop=%d rid=%016llx flags=%02x, entering HS_CLIENT_SENT", total, gop, (unsigned long long)rid, c->hs_flags); DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "STCP client handshake queued: bytes=%zu got_initial_packet=%u local_epoch=%016llx flags=%02x %s",
total, gop, (unsigned long long)rid, c->hs_flags, stcp_conn_describe(c).text);
if (stcp_try_send(c, hs, total) < 0) { u_free(hs); stcp_conn_do_close(c, ECANCELED); } if (stcp_try_send(c, hs, total) < 0) { u_free(hs); stcp_conn_do_close(c, ECANCELED); }
} }
@@ -140,7 +141,7 @@ static void client_hs_cb(struct stcp_conn *c, uint8_t *data, size_t len) {
c->peer_device_type = enc_hs[43]; c->peer_device_type = enc_hs[43];
c->peer_keepalive_interval = ((uint16_t)enc_hs[44] << 8) | enc_hs[45]; c->peer_keepalive_interval = ((uint16_t)enc_hs[44] << 8) | enc_hs[45];
c->peer_flags = enc_hs[46]; c->peer_flags = enc_hs[46];
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_client: server response OK gop=%d rid=%016llx padding=%u dev=%d ka=%u flags=%02x", DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "stcp_client: server response OK gop=%d rid=%016llx padding=%u dev=%d ka=%u flags=%02x",
c->peer_got_initial_pkt, (unsigned long long)c->peer_reset_id, padding_size, c->peer_device_type, c->peer_keepalive_interval, c->peer_flags); c->peer_got_initial_pkt, (unsigned long long)c->peer_reset_id, padding_size, c->peer_device_type, c->peer_keepalive_interval, c->peer_flags);
if (padding_size) stcp_recv_set(c, padding_size, 0, client_hs_padding_cb); if (padding_size) stcp_recv_set(c, padding_size, 0, client_hs_padding_cb);
else client_hs_padding_cb(c, NULL, 0); else client_hs_padding_cb(c, NULL, 0);
@@ -152,7 +153,8 @@ static void client_hs_padding_cb(struct stcp_conn *c, uint8_t *data, size_t len)
if (c->hs_flags & STCP_HANDSHAKE_FLAG_PING) { if (c->hs_flags & STCP_HANDSHAKE_FLAG_PING) {
struct stcp_client *cli = (struct stcp_client *)c; struct stcp_client *cli = (struct stcp_client *)c;
uint16_t rtt = (uint16_t)(get_time_tb() - c->hs_send_time); uint16_t rtt = (uint16_t)(get_time_tb() - c->hs_send_time);
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_client: ping OK rtt=%u sock=%d", (unsigned)rtt, (int)c->sock); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "STCP reachability probe succeeded: handshake_rtt_ms=%.1f %s",
rtt / 10.0, stcp_conn_describe(c).text);
cli->ping_done = 1; cli->ping_done = 1;
if (cli->ping_cb) cli->ping_cb(1, rtt, cli->ping_arg); if (cli->ping_cb) cli->ping_cb(1, rtt, cli->ping_arg);
if (c->reality_io) stcp_conn_finish(c); if (c->reality_io) stcp_conn_finish(c);
@@ -160,7 +162,10 @@ static void client_hs_padding_cb(struct stcp_conn *c, uint8_t *data, size_t len)
return; return;
} }
c->state = STCP_STATE_DATA; c->state = STCP_STATE_DATA;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_client: handshake OK, entering DATA state"); DEBUG_INFO(DEBUG_CATEGORY_ETCP,
"STCP data link established: peer_epoch=%016llx peer_got_initial_packet=%u peer_device_type=%u peer_keepalive_ms=%u %s",
(unsigned long long)c->peer_reset_id, c->peer_got_initial_pkt, c->peer_device_type,
c->peer_keepalive_interval, stcp_conn_describe(c).text);
if (c->on_ready) { void (*cb)(struct stcp_conn*, void*) = c->on_ready; c->on_ready = NULL; cb(c, c->ready_arg); } if (c->on_ready) { void (*cb)(struct stcp_conn*, void*) = c->on_ready; c->on_ready = NULL; cb(c, c->ready_arg); }
stcp_recv_set(c, 0, 1, client_data_cb); stcp_recv_set(c, 0, 1, client_data_cb);
} }
@@ -202,11 +207,15 @@ static void client_connect_write_cb(socket_t sock, void *arg) {
struct stcp_conn *c = &cli->conn; struct stcp_conn *c = &cli->conn;
int err = 0; int err = 0;
socklen_t len = sizeof(err); socklen_t len = sizeof(err);
if (getsockopt(sock, SOL_SOCKET, SO_ERROR, (char *)&err, &len) < 0 || err != 0) { if (getsockopt(sock, SOL_SOCKET, SO_ERROR, (char *)&err, &len) < 0) err = socket_get_error();
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_client connect failed err=%d", err); if (err != 0) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "STCP TCP connection failed: error=%d (%s) expected_peer=%016llx %s",
err, socket_strerror(err), (unsigned long long)sc_derive_node_id_from_pubkey(cli->peer_pubkey),
stcp_conn_describe(c).text);
stcp_conn_do_close(c, err); return; stcp_conn_do_close(c, err); return;
} }
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_client: TCP connected, starting handshake"); DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "STCP TCP connected; starting %s handshake: %s",
cli->reality_enabled ? "REALITY" : "STCP", stcp_conn_describe(c).text);
uasync_remove_socket_t(cli->ua, sock); uasync_remove_socket_t(cli->ua, sock);
c->socket_id = uasync_add_socket_t(cli->ua, sock, client_conn_read_cb, stcp_write_cb, NULL, "stcp_client_conn", c); c->socket_id = uasync_add_socket_t(cli->ua, sock, client_conn_read_cb, stcp_write_cb, NULL, "stcp_client_conn", c);
if (!c->socket_id) { stcp_conn_do_close(c, ENOMEM); return; } if (!c->socket_id) { stcp_conn_do_close(c, ENOMEM); return; }
@@ -219,7 +228,8 @@ static void client_socks_ready_cb(socket_t sock, int err, void *arg) {
struct stcp_conn *c = &cli->conn; struct stcp_conn *c = &cli->conn;
cli->socks_handle = NULL; cli->socks_handle = NULL;
if (err != 0 || sock == SOCKET_INVALID) { if (err != 0 || sock == SOCKET_INVALID) {
DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_client: SOCKS dial failed err=%d", err); DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "STCP SOCKS dial failed: error=%d returned_socket=%d %s",
err, (int)sock, stcp_conn_describe(c).text);
stcp_conn_do_close(c, err ? err : ECONNREFUSED); stcp_conn_do_close(c, err ? err : ECONNREFUSED);
return; return;
} }
@@ -265,6 +275,8 @@ struct stcp_client *stcp_client_connect(struct UASYNC *ua, const char *addr, uin
cli->handshake_padding = padding; cli->handshake_padding = padding;
} }
struct stcp_conn *c = &cli->conn; struct stcp_conn *c = &cli->conn;
snprintf(c->log_target, sizeof(c->log_target), "[%s]:%u", addr, port);
c->log_started_tb = get_time_tb();
c->sock = SOCKET_INVALID; c->sock = SOCKET_INVALID;
c->ua = ua; c->state = STCP_STATE_INIT; c->is_server = 0; c->my_keys = *keys; c->ua = ua; c->state = STCP_STATE_INIT; c->is_server = 0; c->my_keys = *keys;
c->on_ready = ready_cb; c->ready_arg = arg; c->on_ready = ready_cb; c->ready_arg = arg;
@@ -282,7 +294,8 @@ struct stcp_client *stcp_client_connect(struct UASYNC *ua, const char *addr, uin
if (socks) { if (socks) {
cli->socks_handle = socks_dial(ua, socks, addr, port, client_socks_ready_cb, cli, cli->hs_timeout_tb); cli->socks_handle = socks_dial(ua, socks, addr, port, client_socks_ready_cb, cli, cli->hs_timeout_tb);
if (!cli->socks_handle) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_client: socks_dial init failed for %s:%u", addr, port); u_free(cli); return NULL; } if (!cli->socks_handle) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_client: socks_dial init failed for %s:%u", addr, port); u_free(cli); return NULL; }
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_client: connecting %s:%u via SOCKS5 %s:%u", addr, port, socks->host, socks->port); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "STCP connecting via SOCKS5 proxy=%s:%u %s",
socks->host, socks->port, stcp_conn_describe(c).text);
return cli; return cli;
} }
src/transport_layer/stcp_server.c
+12 -6
View File
@@ -106,7 +106,7 @@ static void server_hs_phase1_cb(struct stcp_conn *c, uint8_t *data, size_t len)
c->peer_device_type = enc_hs[43]; c->peer_device_type = enc_hs[43];
c->peer_keepalive_interval = ((uint16_t)enc_hs[44] << 8) | enc_hs[45]; c->peer_keepalive_interval = ((uint16_t)enc_hs[44] << 8) | enc_hs[45];
c->peer_flags = enc_hs[46]; c->peer_flags = enc_hs[46];
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_server: client handshake OK gop=%d rid=%016llx padding=%u dev=%d ka=%u flags=%02x", DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "stcp_server: client handshake OK gop=%d rid=%016llx padding=%u dev=%d ka=%u flags=%02x",
c->peer_got_initial_pkt, (unsigned long long)c->peer_reset_id, padding_size, c->peer_device_type, c->peer_keepalive_interval, c->peer_flags); c->peer_got_initial_pkt, (unsigned long long)c->peer_reset_id, padding_size, c->peer_device_type, c->peer_keepalive_interval, c->peer_flags);
if (padding_size) stcp_recv_set(c, padding_size, 0, server_hs_phase2_cb); if (padding_size) stcp_recv_set(c, padding_size, 0, server_hs_phase2_cb);
else server_hs_phase2_cb(c, NULL, 0); else server_hs_phase2_cb(c, NULL, 0);
@@ -124,7 +124,7 @@ static void server_hs_phase2_cb(struct stcp_conn *c, uint8_t *data, size_t len)
struct ETCP_CONN *conn = instance_find_conn(c->inst, node_id); struct ETCP_CONN *conn = instance_find_conn(c->inst, node_id);
server_gop = conn ? conn->got_initial_pkt : 0; server_gop = conn ? conn->got_initial_pkt : 0;
server_rid = conn ? conn->reset_id : 0; server_rid = conn ? conn->reset_id : 0;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_server: node=0x%016llx conn=%p server_gop=%d server_rid=%016llx client_gop=%d client_rid=%016llx", DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "stcp_server: node=0x%016llx conn=%p server_gop=%d server_rid=%016llx client_gop=%d client_rid=%016llx",
(unsigned long long)node_id, (void*)conn, server_gop, (unsigned long long)server_rid, (unsigned long long)node_id, (void*)conn, server_gop, (unsigned long long)server_rid,
c->peer_got_initial_pkt, (unsigned long long)c->peer_reset_id); c->peer_got_initial_pkt, (unsigned long long)c->peer_reset_id);
} }
@@ -178,12 +178,16 @@ static void server_hs_phase2_cb(struct stcp_conn *c, uint8_t *data, size_t len)
#ifdef UTUN_HAVE_STANDBY #ifdef UTUN_HAVE_STANDBY
standby_log_rx("tcp ping", stcp_conn_peer_str(c)); standby_log_rx("tcp ping", stcp_conn_peer_str(c));
#endif #endif
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_server: ping answered, graceful close sock=%d", (int)c->sock); DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "STCP reachability probe answered; closing probe connection: %s", stcp_conn_describe(c).text);
stcp_conn_finish(c); stcp_conn_finish(c);
return; return;
} }
c->state = STCP_STATE_DATA; c->state = STCP_STATE_DATA;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_server: handshake OK, entering DATA state"); DEBUG_INFO(DEBUG_CATEGORY_ETCP,
"STCP data link established: local_epoch=%016llx peer_epoch=%016llx peer_got_initial_packet=%u "
"peer_device_type=%u peer_keepalive_ms=%u %s",
(unsigned long long)server_rid, (unsigned long long)c->peer_reset_id, c->peer_got_initial_pkt,
c->peer_device_type, c->peer_keepalive_interval, stcp_conn_describe(c).text);
if (c->on_ready) c->on_ready(c, c->ready_arg); if (c->on_ready) c->on_ready(c, c->ready_arg);
stcp_recv_set(c, 0, 1, server_data_cb); stcp_recv_set(c, 0, 1, server_data_cb);
} }
@@ -237,6 +241,8 @@ static void server_accept_cb(socket_t listen_sock, void *arg) {
struct stcp_conn *c = u_calloc(1, sizeof(struct stcp_conn)); struct stcp_conn *c = u_calloc(1, sizeof(struct stcp_conn));
if (!c) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_server: calloc conn failed"); socket_close_wrapper(cli_sock); return; } if (!c) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_server: calloc conn failed"); socket_close_wrapper(cli_sock); return; }
c->sock = cli_sock; c->sock = cli_sock;
snprintf(c->log_target, sizeof(c->log_target), "%s", sockaddr_storage_to_str(&cli_addr).str);
c->log_started_tb = get_time_tb();
c->ua = srv->ua; c->ua = srv->ua;
c->state = STCP_STATE_HS_SERVER_WAIT; c->state = STCP_STATE_HS_SERVER_WAIT;
c->is_server = 1; c->is_server = 1;
@@ -263,7 +269,7 @@ static void server_accept_cb(socket_t listen_sock, void *arg) {
c->reality_srv = srv->reality_srv; c->reality_srv = srv->reality_srv;
snprintf(c->reality_dest, sizeof(c->reality_dest), "%s", srv->reality_dest); snprintf(c->reality_dest, sizeof(c->reality_dest), "%s", srv->reality_dest);
if (reality_io_server_start(c, server_start_stcp)) { stcp_conn_do_close(c, ENOMEM); return; } if (reality_io_server_start(c, server_start_stcp)) { stcp_conn_do_close(c, ENOMEM); return; }
DEBUG_INFO(DEBUG_CATEGORY_REALITY, "stcp_server: reality enabled on accepted conn, waiting ClientHello"); DEBUG_TRACE(DEBUG_CATEGORY_REALITY, "STCP accepted TCP; waiting for REALITY ClientHello: %s", stcp_conn_describe(c).text);
} else { } else {
stcp_recv_set(c, SC_PUBKEY_ENC_SIZE + STCP_HS_ENC_CLIENT, 0, server_hs_phase1_cb); stcp_recv_set(c, SC_PUBKEY_ENC_SIZE + STCP_HS_ENC_CLIENT, 0, server_hs_phase1_cb);
} }
@@ -272,7 +278,7 @@ static void server_accept_cb(socket_t listen_sock, void *arg) {
c->srv = srv; c->srv = srv;
c->srv_next = srv->conns; c->srv_next = srv->conns;
srv->conns = c; srv->conns = c;
DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_server: accepted connection fd=%d", (int)cli_sock); DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "STCP accepted TCP connection: %s", stcp_conn_describe(c).text);
} }
struct stcp_server *stcp_server_create(struct UASYNC *ua, uint16_t port, struct stcp_server *stcp_server_create(struct UASYNC *ua, uint16_t port,