diff --git a/src/transport_layer/stcp.c b/src/transport_layer/stcp.c index c8c6d7aa..0cef10b8 100644 --- a/src/transport_layer/stcp.c +++ b/src/transport_layer/stcp.c @@ -44,6 +44,30 @@ const char* stcp_conn_peer_str(struct stcp_conn *c) { return "?"; } +struct stcp_log_context stcp_conn_describe(const struct stcp_conn *c) { + static const char* const states[] = {"connecting", "waiting-server-handshake", "waiting-client-handshake", + "data", "closed", "error"}; + struct stcp_log_context out; + struct sockaddr_storage local = {0}; + socklen_t len = sizeof(local); + ip_str_t local_text = {0}; + if (c->sock != SOCKET_INVALID && getsockname(c->sock, (struct sockaddr*)&local, &len) == 0) + local_text = sockaddr_storage_to_str(&local); + const char* state = (unsigned)c->state < sizeof(states) / sizeof(states[0]) ? states[c->state] : "unknown"; + const char* purpose = c->is_server && !c->peer_ed25519_set ? "unknown-before-handshake" : + ((c->is_server ? c->peer_flags : c->hs_flags) & STCP_HANDSHAKE_FLAG_PING ? "reachability-probe" : "data-link"); + snprintf(out.text, sizeof(out.text), + "role=%s purpose=%s state=%s target=%s local=%s peer=%016llx peer_identity=%s socket=%d age_ms=%llu " + "outer=%s recv_buffered=%zu recv_needed=%zu wire_queued=%zu finishing=%u", + c->is_server ? "server" : "client", purpose, state, c->log_target[0] ? c->log_target : "unknown", + local_text.str[0] ? local_text.str : "unavailable", + (unsigned long long)(c->peer_pubkey_set ? sc_derive_node_id_from_pubkey(c->peer_pubkey) : 0), + c->peer_pubkey_set ? "known-key" : "unknown", + (int)c->sock, (unsigned long long)(c->log_started_tb ? (get_time_tb() - c->log_started_tb) / 10 : 0), + c->reality_io ? "REALITY" : "plain-STCP", c->recv_buf_len, c->recv_need, c->wire_bytes, c->finish_requested); + return out; +} + void stcp_conn_free(struct stcp_conn *c) { if (!c) return; if (c->recv_active || c->close_callback_active) { @@ -384,7 +408,8 @@ void hs_timeout_cb(void *arg) { struct stcp_conn *c = (struct stcp_conn *)arg; c->hs_timer = NULL; if (c->state == STCP_STATE_CLOSED || c->state == STCP_STATE_ERROR) return; - DEBUG_WARN(DEBUG_CATEGORY_ETCP, "stcp timeout is_server=%d state=%d closing=%u", c->is_server, c->state, c->close_after_send); + DEBUG_WARN(DEBUG_CATEGORY_ETCP, "STCP %s timed out; closing connection: %s", + c->finish_requested ? "graceful shutdown" : "connection establishment", stcp_conn_describe(c).text); stcp_conn_do_close(c, ETIMEDOUT); } @@ -410,8 +435,11 @@ void stcp_conn_do_close(struct stcp_conn *c, int err) { if (!c) return; if (c->state == STCP_STATE_CLOSED || c->state == STCP_STATE_ERROR) return; callring_put(CR_CONN_DOCLOSE_IN, (uintptr_t)c, 0); + int level = err ? DEBUG_LEVEL_WARN : c->state == STCP_STATE_DATA ? DEBUG_LEVEL_INFO : DEBUG_LEVEL_TRACE; + if (debug_should_output(level, DEBUG_CATEGORY_ETCP)) + debug_output(level, DEBUG_CATEGORY_ETCP, __func__, __FILE__, __LINE__, + "STCP connection closed: close_code=%d %s", err, stcp_conn_describe(c).text); reality_io_cleanup(c); - int prev = c->state; c->state = STCP_STATE_CLOSED; stcp_server_remove_conn(c); @@ -419,8 +447,6 @@ void stcp_conn_do_close(struct stcp_conn *c, int err) { if (c->hs_timer) { uasync_cancel_timeout(c->ua, c->hs_timer); c->hs_timer = NULL; } if (c->close_call_soon) { uasync_call_soon_cancel(c->ua, c->close_call_soon); c->close_call_soon = NULL; } - DEBUG_INFO(DEBUG_CATEGORY_ETCP, "stcp_conn close is_server=%d prev_state=%d err=%d sock=%d", c->is_server, prev, err, (int)c->sock); - if (c->socket_id) { uasync_remove_socket_t(c->ua, c->sock); c->socket_id = NULL; } if (c->sock != SOCKET_INVALID) { socket_close_wrapper(c->sock); c->sock = SOCKET_INVALID; } if (c->recv_buf) { u_free(c->recv_buf); c->recv_buf = NULL; c->recv_buf_len = 0; c->recv_buf_cap = 0; } diff --git a/src/transport_layer/stcp.h b/src/transport_layer/stcp.h index 2bc93bdf..ddf0f0d6 100644 --- a/src/transport_layer/stcp.h +++ b/src/transport_layer/stcp.h @@ -77,6 +77,9 @@ struct stcp_conn { socket_t sock; struct UASYNC *ua; void *socket_id; + // Снимок назначения сохраняется и при неудачном connect, когда getpeername уже недоступен. + char log_target[320]; + uint64_t log_started_tb; struct UTUN_INSTANCE *inst; // сервер: диапазон padding и поиск ETCP_CONN по ключу пира struct ETCP_CONN *etcp_conn; // клиент: родительский conn для live-чтения gop/reset_id при handshake @@ -162,6 +165,8 @@ struct stcp_conn { void stcp_conn_free(struct stcp_conn *c); /* Адрес пира соединения для логов (статический буфер). "?" если недоступен. */ const char* stcp_conn_peer_str(struct stcp_conn *c); +struct stcp_log_context { char text[768]; }; +struct stcp_log_context stcp_conn_describe(const struct stcp_conn *c); void stcp_conn_set_tx_queue(struct stcp_conn *c, struct ll_queue *q); void stcp_conn_set_rx_queue(struct stcp_conn *c, struct ll_queue *q); void stcp_conn_set_on_close(struct stcp_conn *c, void (*cb)(struct stcp_conn *conn, int err, void *arg), void *arg);