Log BLE packet sequences and acknowledgements in debug category

doc/ble_etcp.txt

@@ -270,8 +270,10 @@ tx_limit=1 ограничивает только нашу ll_queue; очеред
   INIT/keepalive; busy — DEBUG, отказ — WARN/ERROR. Успешный лог называется
   submitted, поскольку он не подтверждает доставку получателю.
 
-Для сопоставления кадров: discovery=debug, debug=trace; для RTO/ACK — etcp=trace,
-connection=debug, keepalive=debug. Обычный профиль не включает пофрагментный TRACE.
+Для сопоставления кадров и BLE ACK: debug=debug; для сводок очередей — discovery=debug.
+Категория debug содержит DATA TX/RX с seq каждого GATT-пакета, ACK TX/RX с ID и кредитом,
+а также wire TX/RX с отдельным seq, длиной и отпечатком целого кадра.
+Для RTO/ACK ETCP — etcp=trace, connection=debug, keepalive=debug.
 На desktop UTUN_TEST_DEBUG=1 включает trace диагностической категории;
 Android BlePeerProbe включает её на время пробы. Ключи/ссылки приглашений не выводятся.
 

doc/ble_transport.txt

@@ -242,7 +242,12 @@ TX/RX_Bps полезных байтов BLE-кадров (оба канала в
 размеры DATA/INVITE очередей и возраст pending. Локальный TX не равен доставке.
 Отдельная сводка flow показывает flight bytes/packets, peak_bytes, ID/ACK и число
 ACK TX/RX. INFO печатает фиксированную скорость/окно/интервал/разрядность ID.
-Wire TRACE категории debug содержит каждый flow TX, ACK TX/RX и освобождённый кредит.
+Категория debug (debug=debug) содержит каждый DATA TX/RX с seq, type и длиной,
+ACK TX/RX с ID, освобождённым кредитом и остатком flight. Повторные ACK видны как ignored=stale.
+DATA seq — 16-битный ID GATT-пакета, соответствующий ID в ACK; type: 1=HELLO, 2=ACCEPT, 3=FRAME.
+BLE wire TX/RX содержит отдельный seq целого кадра, длину и отпечаток tag для сверки двух узлов.
+DATA/ACK TX означает принятие backend, wire TX — завершение локальной отправки целого кадра;
+удалённый ACK подтверждает приём GATT-пакетов. Содержимое пакетов в эти логи не выводится.
 Повторные радиообъявления не засоряют DEBUG.
 
 Desktop GUI

lib/ble/ble_transport.c

@@ -219,14 +219,14 @@ static void pump(struct ble_transport* t, struct ble_connection* c) {
         if (wire == BLE_WIRE_ACK) {
             if (c->ack_timer) { uasync_cancel_timeout(t->ua, c->ack_timer); c->ack_timer = NULL; }
             c->ack_dirty = 0; c->stats.ack_tx++;
-            DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "BLE ACK TX link=%llu id=%u", (unsigned long long)c->id, c->rx_last);
+            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE ACK TX link=%llu id=%u", (unsigned long long)c->id, c->rx_last);
         } else if (wire == BLE_WIRE_DATA) {
             if (!c->flight_count) c->flight_deadline = c->submitted + DEADLINE_US;
             c->flight_sizes[(c->flight_head + c->flight_count++) % FLOW_SLOTS] = len;
             c->flight_bytes += len;
             if (c->flight_bytes > c->stats.max_flight) c->stats.max_flight = c->flight_bytes;
-            DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "BLE flow TX link=%llu id=%u bytes=%zu flight=%u/%u", (unsigned long long)c->id,
-                        c->tx_next, len, c->flight_count, c->flight_bytes);
+            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE DATA TX link=%llu seq=%u type=%u bytes=%zu flight=%u/%u",
+                        (unsigned long long)c->id, c->tx_next, value[FLOW_HEADER], len, c->flight_count, c->flight_bytes);
             c->tx_next++;
             if (!ble_tx_ready(t, c->id)) c->channels[BLE_CHANNEL_DATA].blocked = 1;
         }
@@ -409,7 +409,8 @@ void ble_backend_received(struct ble_transport* t, ble_link_id id, enum ble_wire
         }
         uint16_t ack = read16(data), advance = (uint16_t)(ack - c->tx_acked);
         if (!advance || advance >= 0x8000) {
-            DEBUG_TRACE(CAT, "BLE stale ACK link=%llu id=%u acked=%u", (unsigned long long)id, ack, c->tx_acked); return;
+            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE ACK RX link=%llu id=%u acked=%u flight=%u/%u ignored=stale",
+                        (unsigned long long)id, ack, c->tx_acked, c->flight_count, c->flight_bytes); return;
         }
         if (advance > c->flight_count) {
             DEBUG_WARN(CAT, "BLE ACK outside flight link=%llu id=%u acked=%u next=%u count=%u",
@@ -422,7 +423,7 @@ void ble_backend_received(struct ble_transport* t, ble_link_id id, enum ble_wire
         }
         c->flight_count -= advance; c->flight_bytes -= bytes; c->tx_acked = ack; c->stats.ack_rx++;
         c->flight_deadline = c->flight_count ? get_time_us() + DEADLINE_US : 0;
-        DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "BLE ACK RX link=%llu id=%u released=%u/%u flight=%u/%u", (unsigned long long)id,
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE ACK RX link=%llu id=%u released=%u/%u flight=%u/%u", (unsigned long long)id,
                     ack, advance, bytes, c->flight_count, c->flight_bytes);
         wake_writer(t, c, BLE_CHANNEL_DATA); pump(t, c); return;
     }
@@ -433,6 +434,8 @@ void ble_backend_received(struct ble_transport* t, ble_link_id id, enum ble_wire
             close_link(t, c, "invalid DATA flow header"); return;
         }
         uint16_t seq = read16(data), advance = (uint16_t)(seq - c->rx_last);
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE DATA RX link=%llu seq=%u type=%u bytes=%zu previous=%u advance=%u",
+                    (unsigned long long)id, seq, data[FLOW_HEADER], len, c->rx_last, advance);
         if (!advance || advance >= 0x8000) {
             DEBUG_WARN(CAT, "BLE duplicate/stale DATA link=%llu id=%u last=%u", (unsigned long long)id, seq, c->rx_last);
             if (c->rx_flow_seen) schedule_ack(t, c); return;
@@ -502,9 +505,8 @@ void ble_backend_received(struct ble_transport* t, ble_link_id id, enum ble_wire
     memcpy(entry->dgram, ch->assembly, total); entry->len = total;
     if (queue_data_put(ch->rx, entry) != 0) { DEBUG_ERROR(CAT, "BLE RX queue invariant failed"); return; }
     c->stats.rx_bytes += total; c->stats.rx_frames++;
-    DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "BLE wire RX link=%llu channel=%d seq=%u bytes=%u tag=%08x",
+    DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE wire RX link=%llu channel=%d seq=%u bytes=%u tag=%08x",
                 (unsigned long long)id, channel, seq, total, frame_tag(entry->dgram, entry->len));
-    DEBUG_TRACE(CAT, "BLE RX frame link=%llu channel=%d seq=%u bytes=%u queued=%d", (unsigned long long)id, channel, seq, total, queue_entry_count(ch->rx));
     void (*received)(void*, ble_link_id) = channel == BLE_CHANNEL_DATA ? t->config.callbacks.received : t->config.callbacks.invite_received;
     if (received) received(t->config.arg, id);
     return;
@@ -542,10 +544,9 @@ void ble_backend_sent(struct ble_transport* t, ble_link_id id, int success) {
         ch->offset += c->pending_bytes;
         if (ch->offset == ch->current->len) {
             c->stats.tx_bytes += ch->current->len; c->stats.tx_frames++;
-            DEBUG_TRACE(DEBUG_CATEGORY_DEBUG, "BLE wire TX link=%llu channel=%d seq=%u bytes=%u tag=%08x",
+            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE wire TX link=%llu channel=%d seq=%u bytes=%u tag=%08x",
                         (unsigned long long)id, channel, ch->sequence, ch->current->len,
                         frame_tag(ch->current->dgram, ch->current->len));
-            DEBUG_TRACE(CAT, "BLE TX frame link=%llu channel=%d seq=%u bytes=%u", (unsigned long long)id, channel, ch->sequence, ch->current->len);
             release_entry(ch->current); ch->current = NULL;
         }
     }