chatgui: диагностические логи ADDR_SYNC во всех точках записи/удаления адресов в БД

- chat_core_sync_my_addresses: DELETE + INSERT с подсчётом строк, CHECK verify
- chat_core_connect_from_invite: DELETE + INSERT с IP:port
- member_sync_put: DELETE + INSERT с IP:port, warn если addrs_data=NULL
- cs_handle_channel_info_resp: адрес инвайтера из ETCP link
- cs_handle_channel_join: адреса джойнера
- cs_handle_peer_upsert: адреса пира
- cs_handle_welcome: адреса из WELCOME

Все логи с префиксом [ADDR_SYNC] в DEBUG_CATEGORY_DEBUG

tools/chatgui/transport/chat_core.c

@@ -312,21 +312,34 @@ void chat_core_update_my_name(const char* name) {
 void chat_core_sync_my_addresses(void) {
     if (!g_cc.initialized || !g_cc.db || !g_cc.inst) return;
 
+    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] sync_my_addresses START my_node=0x%016llx", CC_ID, (unsigned long long)g_cc.my_node_id);
+
     sqlite3_stmt* del = NULL;
     sqlite3_prepare_v2(g_cc.db, "DELETE FROM node_addresses WHERE node_id=? AND addr_type=0", -1, &del, NULL);
-    if (del) { sqlite3_bind_int64(del, 1, (sqlite3_int64)g_cc.my_node_id); sqlite3_step(del); sqlite3_finalize(del); }
+    if (del) {
+        sqlite3_bind_int64(del, 1, (sqlite3_int64)g_cc.my_node_id);
+        sqlite3_step(del);
+        int deleted = sqlite3_changes(g_cc.db);
+        DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] DELETE addr_type=0 for my_node=0x%016llx: %d rows deleted", CC_ID, (unsigned long long)g_cc.my_node_id, deleted);
+        sqlite3_finalize(del);
+    }
 
     sqlite3_stmt* ins = NULL;
     sqlite3_prepare_v2(g_cc.db,
         "INSERT OR REPLACE INTO node_addresses(node_id,family,protocol,address,port,addr_type,socket_id)"
         " VALUES(?,?,1,?,?,0,?)", -1, &ins, NULL);
-    if (!ins) return;
+    if (!ins) {
+        DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] FAIL prepare INSERT stmt my_node=0x%016llx", CC_ID, (unsigned long long)g_cc.my_node_id);
+        return;
+    }
 
     struct ETCP_SOCKET* sock = g_cc.inst->etcp_sockets;
+    int sock_count = 0, written = 0;
     while (sock) {
+        sock_count++;
         struct sockaddr_storage* sa = sock->interface_addr.ss_family ? &sock->interface_addr : NULL;
         if (!sa) sa = sock->local_addr.ss_family ? &sock->local_addr : NULL;
-        if (!sa) { sock = sock->next; continue; }
+        if (!sa) { DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] socket %d — no interface/local addr", CC_ID, sock_count); sock = sock->next; continue; }
 
         if (sa->ss_family == AF_INET) {
             struct sockaddr_in* sin = (struct sockaddr_in*)sa;
@@ -336,6 +349,10 @@ void chat_core_sync_my_addresses(void) {
             sqlite3_bind_int(ins, 4, (int)ntohs(sin->sin_port));
             sqlite3_bind_int(ins, 5, (int)sock->sock_id);
             sqlite3_step(ins); sqlite3_reset(ins);
+            uint8_t* ip = (uint8_t*)&sin->sin_addr;
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] INSERT my_node=0x%016llx sock=%d %d.%d.%d.%d:%d",
+                       CC_ID, (unsigned long long)g_cc.my_node_id, sock->sock_id, ip[0], ip[1], ip[2], ip[3], (int)ntohs(sin->sin_port));
+            written++;
         } else if (sa->ss_family == AF_INET6) {
             struct sockaddr_in6* sin6 = (struct sockaddr_in6*)sa;
             sqlite3_bind_int64(ins, 1, (sqlite3_int64)g_cc.my_node_id);
@@ -344,10 +361,32 @@ void chat_core_sync_my_addresses(void) {
             sqlite3_bind_int(ins, 4, (int)ntohs(sin6->sin6_port));
             sqlite3_bind_int(ins, 5, (int)sock->sock_id);
             sqlite3_step(ins); sqlite3_reset(ins);
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] INSERT v6 my_node=0x%016llx sock=%d port=%d",
+                       CC_ID, (unsigned long long)g_cc.my_node_id, sock->sock_id, (int)ntohs(sin6->sin6_port));
+            written++;
         }
         sock = sock->next;
     }
     sqlite3_finalize(ins);
+
+    if (sock_count == 0)
+        DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] etcp_sockets is NULL — NO sockets, addresses NOT written!", CC_ID);
+    else if (written == 0)
+        DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] %d sockets found but 0 addresses written (all have no interface_addr nor local_addr)", CC_ID, sock_count);
+    else
+        DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] DONE: %d of %d sockets written, my_node=0x%016llx",
+                   CC_ID, written, sock_count, (unsigned long long)g_cc.my_node_id);
+
+    /* verify */
+    sqlite3_stmt* chk = NULL;
+    sqlite3_prepare_v2(g_cc.db, "SELECT COUNT(*) FROM node_addresses WHERE node_id=? AND addr_type=0", -1, &chk, NULL);
+    if (chk) {
+        sqlite3_bind_int64(chk, 1, (sqlite3_int64)g_cc.my_node_id);
+        int cnt = sqlite3_step(chk) == SQLITE_ROW ? sqlite3_column_int(chk, 0) : -1;
+        DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] VERIFY: total addr_type=0 rows for my_node=0x%016llx = %d",
+                   CC_ID, (unsigned long long)g_cc.my_node_id, cnt);
+        sqlite3_finalize(chk);
+    }
 }
 
 void chat_core_update_my_name_trampoline(void* arg) {
@@ -605,17 +644,22 @@ void chat_core_connect_from_invite(struct chat_invite* inv) {
 
     /* save addresses to node_addresses */
     {
+        DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] save_invite_addr node=0x%016llx addr_count=%d", CC_ID, (unsigned long long)node_id, inv->addr_count);
         sqlite3_stmt* ds = NULL;
         if (sqlite3_prepare_v2(g_cc.db,
                 "DELETE FROM node_addresses WHERE node_id=?", -1, &ds, NULL) == SQLITE_OK) {
             sqlite3_bind_int64(ds, 1, (sqlite3_int64)node_id);
-            sqlite3_step(ds); sqlite3_finalize(ds);
+            sqlite3_step(ds);
+            int deleted = sqlite3_changes(g_cc.db);
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] invite DELETE ALL for node=0x%016llx: %d rows deleted", CC_ID, (unsigned long long)node_id, deleted);
+            sqlite3_finalize(ds);
         }
         sqlite3_stmt* is = NULL;
         if (sqlite3_prepare_v2(g_cc.db,
                 "INSERT INTO node_addresses(node_id,family,protocol,address,port,addr_type,socket_id)"
                 " VALUES(?,?,1,?,?,0,?)", -1, &is, NULL) == SQLITE_OK) {
             const uint8_t* src = inv->addrs_data;
+            int written = 0;
             for (int i = 0; i < inv->addr_count; i++) {
                 uint8_t family = *src++;
                 uint8_t sid = *src++;
@@ -627,11 +671,19 @@ void chat_core_connect_from_invite(struct chat_invite* inv) {
                     sqlite3_bind_int(is, 4, (int)port);
                     sqlite3_bind_int(is, 5, (int)sid);
                     sqlite3_step(is); sqlite3_reset(is);
+                    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] invite INSERT node=0x%016llx sock=%d %d.%d.%d.%d:%d",
+                               CC_ID, (unsigned long long)node_id, sid, src[-6], src[-5], src[-4], src[-3], port);
+                    written++;
                 } else {
                     src += 18;
+                    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] invite SKIP v6 addr for node=0x%016llx", CC_ID, (unsigned long long)node_id);
                 }
             }
             sqlite3_finalize(is);
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] invite DONE: %d v4 addresses written for node=0x%016llx",
+                       CC_ID, written, (unsigned long long)node_id);
+        } else {
+            DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] invite FAIL prepare INSERT node=0x%016llx", CC_ID, (unsigned long long)node_id);
         }
     }
 

tools/chatgui/transport/chat_sync.c

@@ -1013,8 +1013,10 @@ static void cs_handle_channel_info_resp(struct chat_sync* cs, uint64_t peer,
           sqlite3_step(ns); sqlite3_finalize(ns); }
       }
       /* save inviter's address from ETCP connection */
-      { struct ETCP_LINK* lk = inv_conn->links;
+      { DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] INFO_RESP save inviter peer=%016llx", CS_ID, (unsigned long long)peer);
-        while (lk) {
+        struct ETCP_LINK* lk = inv_conn->links;
+        int lk_count = 0, lk_written = 0;
+        while (lk) { lk_count++;
           if (lk->initialized && lk->remote_addr.ss_family == AF_INET) {
             struct sockaddr_in* sin = (struct sockaddr_in*)&lk->remote_addr;
             uint8_t ip[4]; memcpy(ip, &sin->sin_addr, 4); uint16_t port = ntohs(sin->sin_port);
@@ -1027,12 +1029,17 @@ static void cs_handle_channel_info_resp(struct chat_sync* cs, uint64_t peer,
               sqlite3_bind_int(as, 3, port);
               sqlite3_bind_int(as, 4, (int)lk->conn->sock_id);
               sqlite3_step(as); sqlite3_finalize(as);
-              DEBUG_DEBUG(DEBUG_CATEGORY_DB_SYNC, "%s: saved inviter addr peer=%016llx %d.%d.%d.%d:%d", CS_ID,
+              lk_written++;
-                          (unsigned long long)peer, ip[0], ip[1], ip[2], ip[3], port);
+              DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] INFO_RESP INSERT peer=%016llx sock=%d %d.%d.%d.%d:%d",
+                         CS_ID, (unsigned long long)peer, (int)lk->conn->sock_id, ip[0], ip[1], ip[2], ip[3], port);
             }
+          } else if (lk->initialized) {
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] INFO_RESP SKIP non-IPv4 link for peer=%016llx", CS_ID, (unsigned long long)peer);
           }
           lk = lk->next;
         }
+        DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] INFO_RESP DONE peer=%016llx: %d links, %d written",
+                   CS_ID, (unsigned long long)peer, lk_count, lk_written);
       }
       int rc = topo_node_sqlite_member_put(vdb, ch_id, peer, inviter_join_sig, inviter_join_ts, inviter_update_sig, inviter_update_ts, inv_x25519, inv_ed, inv_name, inviter_join_sig);
       if (rc != 0) DEBUG_ERROR(DEBUG_CATEGORY_DB_SYNC, "%s: member_put(inviter) FAILED ch=%s peer=%016llx rc=%d", CS_ID, ch_id, (unsigned long long)peer, rc);
@@ -1155,6 +1162,7 @@ static void cs_handle_channel_join(struct chat_sync* cs, uint64_t peer,
     }
 
     /* save/update node addresses */
+    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] JOIN save addrs node=0x%016llx addr_cnt=%d", CS_ID, (unsigned long long)node_id, addr_cnt);
     for (uint8_t i = 0; i < addr_cnt && p + 2 <= pl + len; i++) {
         uint8_t fm = *p++;
         uint8_t sid = *p++;
@@ -1175,6 +1183,12 @@ static void cs_handle_channel_join(struct chat_sync* cs, uint64_t peer,
             sqlite3_bind_int(stmt, 5, (int)sid);
             sqlite3_step(stmt); sqlite3_finalize(stmt);
         }
+        if (fm == 4)
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] JOIN INSERT node=0x%016llx sock=%d %d.%d.%d.%d:%d",
+                       CS_ID, (unsigned long long)node_id, sid, ip[0], ip[1], ip[2], ip[3], port);
+        else
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] JOIN INSERT v6 node=0x%016llx sock=%d port=%d",
+                       CS_ID, (unsigned long long)node_id, sid, port);
     }
 
     /* build WELCOME with all current peers */
@@ -1279,6 +1293,7 @@ static void cs_handle_welcome(struct chat_sync* cs, uint64_t peer,
         if (rc != 0) DEBUG_ERROR(DEBUG_CATEGORY_DB_SYNC, "%s: member_put(welcome) FAILED ch=%s node=0x%016llx rc=%d", CS_ID, ch_id, (unsigned long long)node_id, rc);
         topo_node_sqlite_node_update_verified(db, node_id, peer_name, x25519, ed_pub, join_ts);
 
+        DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] WELCOME save addrs node=0x%016llx ac=%d", CS_ID, (unsigned long long)node_id, ac);
         for (uint8_t j = 0; j < ac; j++) {
             if (p + 2 > pl + len) break;
             uint8_t fm = *p++;
@@ -1300,6 +1315,12 @@ static void cs_handle_welcome(struct chat_sync* cs, uint64_t peer,
                 sqlite3_bind_int(stmt, 5, (int)sid);
                 sqlite3_step(stmt); sqlite3_finalize(stmt);
             }
+            if (fm == 4)
+                DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] WELCOME INSERT node=0x%016llx sock=%d %d.%d.%d.%d:%d",
+                           CS_ID, (unsigned long long)node_id, sid, ip[0], ip[1], ip[2], ip[3], port);
+            else
+                DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] WELCOME INSERT v6 node=0x%016llx sock=%d port=%d",
+                           CS_ID, (unsigned long long)node_id, sid, port);
         }
         member_sync_cancel(g_cs->inst, peer, ch_id);
         member_sync_set_online(g_cs->inst, peer, 0);
@@ -1375,6 +1396,7 @@ static void cs_handle_peer_upsert(struct chat_sync* cs, uint64_t peer,
             sqlite3_step(ns); sqlite3_finalize(ns); }
     }
 
+    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] PEER_UPSERT save addrs node=0x%016llx ac=%d", CS_ID, (unsigned long long)node_id, ac);
     for (uint8_t i = 0; i < ac; i++) {
         if (p + 2 > pl + len) break;
         uint8_t fm = *p++;
@@ -1396,6 +1418,12 @@ static void cs_handle_peer_upsert(struct chat_sync* cs, uint64_t peer,
             sqlite3_bind_int(stmt, 5, (int)sid);
             sqlite3_step(stmt); sqlite3_finalize(stmt);
         }
+        if (fm == 4)
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] PEER_UPSERT INSERT node=0x%016llx sock=%d %d.%d.%d.%d:%d",
+                       CS_ID, (unsigned long long)node_id, sid, ip[0], ip[1], ip[2], ip[3], port);
+        else
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] PEER_UPSERT INSERT v6 node=0x%016llx sock=%d port=%d",
+                       CS_ID, (unsigned long long)node_id, sid, port);
     }
 
     cs_refresh_channels(cs);

tools/chatgui/transport/member_sync.c

@@ -347,10 +347,16 @@ int member_sync_put(struct UTUN_INSTANCE* inst, const char* ch_id,
     }
 
     if (addrs_data && addr_count > 0) {
+        DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] member_sync_put node=0x%016llx ch=%s addr_count=%d",
+                   MS_ID, (unsigned long long)member_id, ch_id, addr_count);
         sqlite3_exec(db, "BEGIN", NULL, NULL, NULL);
         sqlite3_stmt* ds = NULL;
         sqlite3_prepare_v2(db, "DELETE FROM node_addresses WHERE node_id=? AND addr_type=0", -1, &ds, NULL);
-        if (ds) { sqlite3_bind_int64(ds, 1, (sqlite3_int64)member_id); sqlite3_step(ds); sqlite3_finalize(ds); }
+        if (ds) { sqlite3_bind_int64(ds, 1, (sqlite3_int64)member_id); sqlite3_step(ds);
+            int deleted = sqlite3_changes(db);
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] member_sync_put DELETE addr_type=0 node=0x%016llx: %d rows deleted",
+                       MS_ID, (unsigned long long)member_id, deleted);
+            sqlite3_finalize(ds); }
 
         sqlite3_stmt* as = NULL;
         sqlite3_prepare_v2(db,
@@ -358,6 +364,7 @@ int member_sync_put(struct UTUN_INSTANCE* inst, const char* ch_id,
             " VALUES(?,?,1,?,?,0,?)", -1, &as, NULL);
         if (as) {
             const uint8_t* p = addrs_data;
+            int written = 0;
             for (int i = 0; i < addr_count; i++) {
                 uint8_t fam = *p++;
                 uint8_t sid = *p++;
@@ -370,10 +377,26 @@ int member_sync_put(struct UTUN_INSTANCE* inst, const char* ch_id,
                 sqlite3_bind_int(as, 4, port);
                 sqlite3_bind_int(as, 5, (int)sid);
                 sqlite3_step(as); sqlite3_reset(as);
+                if (fam == 4) {
+                    const uint8_t* ip = p - 6; /* p advanced by ip_sz(4) + port(2) */
+                    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] member_sync_put INSERT node=0x%016llx sock=%d %d.%d.%d.%d:%d",
+                               MS_ID, (unsigned long long)member_id, sid, ip[0], ip[1], ip[2], ip[3], port);
+                } else {
+                    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] member_sync_put INSERT v6 node=0x%016llx sock=%d port=%d",
+                               MS_ID, (unsigned long long)member_id, sid, port);
+                }
+                written++;
             }
             sqlite3_finalize(as);
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] member_sync_put DONE node=0x%016llx: %d addrs written",
+                       MS_ID, (unsigned long long)member_id, written);
         }
         sqlite3_exec(db, "COMMIT", NULL, NULL, NULL);
+    } else {
+        if (!addrs_data)
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] member_sync_put node=0x%016llx ch=%s addrs_data=NULL — NO addresses (skipping)", MS_ID, (unsigned long long)member_id, ch_id);
+        else
+            DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "%s: [ADDR_SYNC] member_sync_put node=0x%016llx ch=%s addr_count=%d — empty, NO DELETE (skipping)", MS_ID, (unsigned long long)member_id, ch_id, addr_count);
     }
 
     merkle_sync_recompute_path(inst, ch_id, member_id);