logging: describe STCP state and endpoint on timeout and close

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; }

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);