From f4bcc6eae9148bd3d88fc3ce76d466fd1ced232b Mon Sep 17 00:00:00 2001 From: evgeny Date: Fri, 30 Oct 2026 04:17:15 +0100 Subject: [PATCH] Log BLE packet sequences and acknowledgements in debug category --- doc/ble_etcp.txt | 6 ++++-- doc/ble_transport.txt | 7 ++++++- lib/ble/ble_transport.c | 19 ++++++++++--------- 3 files changed, 20 insertions(+), 12 deletions(-) diff --git a/doc/ble_etcp.txt b/doc/ble_etcp.txt index 3f6957a1..2e9ba3bc 100644 --- a/doc/ble_etcp.txt +++ b/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 включает её на время пробы. Ключи/ссылки приглашений не выводятся. diff --git a/doc/ble_transport.txt b/doc/ble_transport.txt index 72c19c74..6d4de44e 100644 --- a/doc/ble_transport.txt +++ b/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 diff --git a/lib/ble/ble_transport.c b/lib/ble/ble_transport.c index 0407607d..8df5f60d 100644 --- a/lib/ble/ble_transport.c +++ b/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; } }