diff --git a/lib/ble/ble_bluez.c b/lib/ble/ble_bluez.c index 7268f154..9796e464 100644 --- a/lib/ble/ble_bluez.c +++ b/lib/ble/ble_bluez.c @@ -137,6 +137,11 @@ static void notify_read(int fd, void* arg) { struct bluez_link* l = arg; uint8_t data[8]; ssize_t n = recv(fd, data, sizeof(data), MSG_DONTWAIT); if (n < 0 && (errno == EAGAIN || errno == EINTR)) return; + if (n < 0) { + DEBUG_ERROR(CAT, "BLE notification socket read failed link=%llu fd=%d errno=%d: %s", + (unsigned long long)l->id, fd, errno, strerror(errno)); + link_error(l, "notification socket read failed"); return; + } if (!n) { link_error(l, "notification subscription closed"); return; } if (n != 1 || data[0] != 1 || fd != l->fd[BLE_CHANNEL_INVITE] || l->channel != BLE_CHANNEL_INVITE || !l->sending || l->buffered) { @@ -182,7 +187,9 @@ static int options(sd_bus_message* m, const char** device, uint16_t* mtu, uint16 } static int reject(sd_bus_message* m, const char* reason) { DEBUG_WARN(CAT, "BLE BlueZ request rejected: %s", reason); - return sd_bus_reply_method_errorf(m, "org.bluez.Error.Failed", "%s", reason); + int r = sd_bus_reply_method_errorf(m, "org.bluez.Error.Failed", "%s", reason); + if (r < 0) DEBUG_ERROR(CAT, "BLE BlueZ error reply failed: %s", strerror(-r)); + return r; } static int write_value(sd_bus_message* m, void* arg, sd_bus_error* error) { (void)error; struct characteristic* ctx = arg; struct ble_backend* b = ctx->backend; @@ -195,7 +202,9 @@ static int write_value(sd_bus_message* m, void* arg, sd_bus_error* error) { ble_link_id id = l->id; ble_backend_received(b->owner, id, ctx->tx == 2 ? BLE_CHANNEL_INVITE : BLE_CHANNEL_DATA, data, len); if (!find_link(b, id)) return reject(m, "session rejected"); - return sd_bus_reply_method_return(m, ""); + int r = sd_bus_reply_method_return(m, ""); + if (r < 0) DEBUG_ERROR(CAT, "BLE BlueZ WriteValue reply failed link=%llu: %s", (unsigned long long)id, strerror(-r)); + return r; } static int acquire_notify(sd_bus_message* m, void* arg, sd_bus_error* error) { (void)error; struct characteristic* ctx = arg; struct ble_backend* b = ctx->backend; @@ -206,13 +215,18 @@ static int acquire_notify(sd_bus_message* m, void* arg, sd_bus_error* error) { int channel = ctx->tx == 2 ? BLE_CHANNEL_INVITE : BLE_CHANNEL_DATA; if (!l || l->fd[channel] >= 0) return reject(m, "subscription unavailable"); int pair[2]; - if (socketpair(AF_UNIX, SOCK_SEQPACKET | SOCK_NONBLOCK | SOCK_CLOEXEC, 0, pair) < 0) return reject(m, "socketpair failed"); + if (socketpair(AF_UNIX, SOCK_SEQPACKET | SOCK_NONBLOCK | SOCK_CLOEXEC, 0, pair) < 0) { + DEBUG_ERROR(CAT, "BLE notification socketpair failed: %s", strerror(errno)); return reject(m, "socketpair failed"); + } l->fd[channel] = pair[0]; l->mtu = mtu; l->io[channel] = uasync_add_socket(b->ua, l->fd[channel], notify_read, notify_write, notify_read, "ble_notify", l); if (!l->io[channel]) { close(pair[0]); close(pair[1]); l->fd[channel] = -1; return reject(m, "fd registration failed"); } uasync_set_socket_write(b->ua, l->io[channel], 0); int r = sd_bus_reply_method_return(m, "hq", pair[1], mtu); close(pair[1]); - if (r < 0) { link_error(l, "AcquireNotify reply failed"); return r; } + if (r < 0) { + DEBUG_ERROR(CAT, "BLE BlueZ AcquireNotify reply failed link=%llu: %s", (unsigned long long)l->id, strerror(-r)); + link_error(l, "AcquireNotify reply failed"); return r; + } DEBUG_DEBUG(CAT, "BLE BlueZ subscription link=%llu channel=%d mode=%s mtu=%u", (unsigned long long)l->id, channel, channel == BLE_CHANNEL_DATA ? "notification" : "indication", mtu); if (l->fd[0] >= 0 && l->fd[1] >= 0 && !l->opened) { diff --git a/lib/ble/ble_transport.c b/lib/ble/ble_transport.c index 160ec960..2d5befa7 100644 --- a/lib/ble/ble_transport.c +++ b/lib/ble/ble_transport.c @@ -12,14 +12,14 @@ #define STATS_US 5000000ULL struct ble_stats { uint64_t since, tx_bytes, rx_bytes, wait_us, max_wait_us; - unsigned tx_frames, rx_frames, fragments, dropped; + unsigned tx_frames, rx_frames, fragments, dropped, missing; }; struct ble_channel_state { struct ll_queue *tx, *rx; struct ll_entry* current; uint64_t rx_deadline; - uint16_t sequence, offset, rx_sequence, rx_size, rx_offset, dropped_sequence; - int blocked, dropping; + uint16_t sequence, offset, rx_sequence, rx_size, rx_offset, dropped_sequence, rx_next; + int blocked, dropping, rx_seen; uint8_t assembly[BLE_FRAME_MAX]; }; struct ble_connection { @@ -69,10 +69,10 @@ static void log_stats(struct ble_connection* c, uint64_t now) { uint64_t elapsed = now > s->since ? now - s->since : 1; if (s->tx_frames || s->rx_frames || s->fragments || s->dropped || c->pending) { DEBUG_DEBUG(CAT, "BLE traffic link=%llu outgoing=%d elapsed_ms=%llu TX_Bps=%llu RX_Bps=%llu TX_frames=%u RX_frames=%u " - "fragments=%u drops=%u wait_avg_us=%llu wait_max_us=%llu DATA_queue=%d INVITE_queue=%d pending_ms=%llu", + "fragments=%u drops=%u missing=%u wait_avg_us=%llu wait_max_us=%llu DATA_queue=%d INVITE_queue=%d pending_ms=%llu", (unsigned long long)c->id, c->outgoing, (unsigned long long)(elapsed / 1000), (unsigned long long)(s->tx_bytes * 1000000 / elapsed), (unsigned long long)(s->rx_bytes * 1000000 / elapsed), - s->tx_frames, s->rx_frames, s->fragments, s->dropped, + s->tx_frames, s->rx_frames, s->fragments, s->dropped, s->missing, (unsigned long long)(s->fragments ? s->wait_us / s->fragments : 0), (unsigned long long)s->max_wait_us, queue_entry_count(c->channels[BLE_CHANNEL_DATA].tx) + !!c->channels[BLE_CHANNEL_DATA].current, queue_entry_count(c->channels[BLE_CHANNEL_INVITE].tx) + !!c->channels[BLE_CHANNEL_INVITE].current, @@ -330,7 +330,8 @@ void ble_backend_received(struct ble_transport* t, ble_link_id id, enum ble_chan pump(t, c); return; } if (!c->ready || len <= HEADER || len > c->capacity || data[0] != FRAME) { - DEBUG_WARN(CAT, "BLE invalid value link=%llu bytes=%zu ready=%d", (unsigned long long)id, len, c->ready); + DEBUG_WARN(CAT, "BLE invalid value link=%llu channel=%d bytes=%zu capacity=%u ready=%d type=%u", + (unsigned long long)id, channel, len, c->capacity, c->ready, len ? data[0] : 0); c->stats.dropped++; ch->rx_size = ch->rx_offset = 0; return; } @@ -342,7 +343,19 @@ void ble_backend_received(struct ble_transport* t, ble_link_id id, enum ble_chan if (!offset) ch->dropping = 0; if (!total || total > BLE_FRAME_MAX || offset > total || n > (size_t)(total - offset)) goto invalid; if (!offset) { - if (ch->rx_size) { DEBUG_WARN(CAT, "BLE incomplete frame replaced link=%llu", (unsigned long long)id); c->stats.dropped++; } + uint16_t expected = ch->rx_seen ? ch->rx_next : 1; + if (seq != expected) { + uint16_t gap = (uint16_t)(seq - expected); + DEBUG_WARN(CAT, "BLE RX sequence gap link=%llu channel=%d expected=%u received=%u missing=%u", + (unsigned long long)id, channel, expected, seq, gap < 0x8000 ? gap : 0); + if (gap < 0x8000) c->stats.missing += gap; + } + ch->rx_seen = 1; ch->rx_next = (uint16_t)(seq + 1); + if (ch->rx_size) { + DEBUG_WARN(CAT, "BLE incomplete frame replaced link=%llu channel=%d seq=%u received=%u total=%u next=%u", + (unsigned long long)id, channel, ch->rx_sequence, ch->rx_offset, ch->rx_size, seq); + c->stats.dropped++; + } ch->rx_sequence = seq; ch->rx_size = total; ch->rx_offset = 0; ch->rx_deadline = get_time_us() + DEADLINE_US; } if (ch->rx_size != total || ch->rx_sequence != seq || ch->rx_offset != offset) goto invalid; @@ -354,7 +367,7 @@ void ble_backend_received(struct ble_transport* t, ble_link_id id, enum ble_chan c->stats.dropped++; return; } struct ll_entry* entry = ll_alloc_lldgram(total); - if (!entry) { DEBUG_ERROR(CAT, "BLE RX allocation failed bytes=%u", total); return; } + if (!entry) { DEBUG_ERROR(CAT, "BLE RX allocation failed bytes=%u", total); c->stats.dropped++; return; } 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++; @@ -374,7 +387,8 @@ invalid: void ble_backend_sent(struct ble_transport* t, ble_link_id id, int success) { struct ble_connection* c = lookup(t, id); if (!c) return; - if (!success || !c->pending) { DEBUG_WARN(CAT, "BLE send completion failed link=%llu", (unsigned long long)id); + if (!success || !c->pending) { DEBUG_WARN(CAT, "BLE send completion failed link=%llu success=%d pending=%d channel=%d bytes=%u", + (unsigned long long)id, success, c->pending, c->pending_channel, c->pending_bytes); close_link(t, c, "send failed"); return; } enum ble_channel channel = c->pending_channel; uint64_t waited = get_time_us() - c->submitted; diff --git a/tools/cgathui_common/tests/ble_etcp_probe.c b/tools/cgathui_common/tests/ble_etcp_probe.c index 30e860ee..b2f80d35 100644 --- a/tools/cgathui_common/tests/ble_etcp_probe.c +++ b/tools/cgathui_common/tests/ble_etcp_probe.c @@ -76,6 +76,7 @@ int main(int argc, char** argv) { instance = utun_instance_create_from_str(ua, config); if (!instance) { uasync_destroy(ua, 0); return 1; } if (getenv("UTUN_TEST_DEBUG")) { + debug_set_category_level(DEBUG_CATEGORY_DEBUG, DEBUG_LEVEL_TRACE); debug_set_category_level(DEBUG_CATEGORY_ETCP, DEBUG_LEVEL_TRACE); debug_set_category_level(DEBUG_CATEGORY_CONNECTION, DEBUG_LEVEL_DEBUG); }