diff --git a/src/transport_layer/stcp_client.c b/src/transport_layer/stcp_client.c index 3a1e3f4a..cae54d20 100644 --- a/src/transport_layer/stcp_client.c +++ b/src/transport_layer/stcp_client.c @@ -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->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); } } @@ -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_keepalive_interval = ((uint16_t)enc_hs[44] << 8) | enc_hs[45]; 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); if (padding_size) stcp_recv_set(c, padding_size, 0, client_hs_padding_cb); 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) { struct stcp_client *cli = (struct stcp_client *)c; 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; if (cli->ping_cb) cli->ping_cb(1, rtt, cli->ping_arg); 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; } 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); } 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; int err = 0; socklen_t len = sizeof(err); - if (getsockopt(sock, SOL_SOCKET, SO_ERROR, (char *)&err, &len) < 0 || err != 0) { - DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_client connect failed err=%d", err); + if (getsockopt(sock, SOL_SOCKET, SO_ERROR, (char *)&err, &len) < 0) err = socket_get_error(); + 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; } - 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); 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; } @@ -219,7 +228,8 @@ static void client_socks_ready_cb(socket_t sock, int err, void *arg) { struct stcp_conn *c = &cli->conn; cli->socks_handle = NULL; 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); return; } @@ -265,6 +275,8 @@ struct stcp_client *stcp_client_connect(struct UASYNC *ua, const char *addr, uin cli->handshake_padding = padding; } 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->ua = ua; c->state = STCP_STATE_INIT; c->is_server = 0; c->my_keys = *keys; 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) { 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; } - 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; } diff --git a/src/transport_layer/stcp_server.c b/src/transport_layer/stcp_server.c index e015a37b..788d432a 100644 --- a/src/transport_layer/stcp_server.c +++ b/src/transport_layer/stcp_server.c @@ -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_keepalive_interval = ((uint16_t)enc_hs[44] << 8) | enc_hs[45]; 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); if (padding_size) stcp_recv_set(c, padding_size, 0, server_hs_phase2_cb); 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); server_gop = conn ? conn->got_initial_pkt : 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, 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 standby_log_rx("tcp ping", stcp_conn_peer_str(c)); #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); return; } 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); 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)); if (!c) { DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "stcp_server: calloc conn failed"); socket_close_wrapper(cli_sock); return; } 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->state = STCP_STATE_HS_SERVER_WAIT; 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; 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; } - 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 { 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_next = srv->conns; 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,