From dc70174af99510c16cc889c54ab37db0da97d32d Mon Sep 17 00:00:00 2001 From: evgeny Date: Thu, 29 Oct 2026 22:38:08 +0100 Subject: [PATCH] Preserve WinRT BLE event context and diagnose API failures --- lib/ble/ble_winrt.cpp | 236 +++++++++++++++++++++++++++++++----------- 1 file changed, 175 insertions(+), 61 deletions(-) diff --git a/lib/ble/ble_winrt.cpp b/lib/ble/ble_winrt.cpp index cafdda9ef..d535690eb 100644 --- a/lib/ble/ble_winrt.cpp +++ b/lib/ble/ble_winrt.cpp @@ -7,6 +7,8 @@ #include "../debug_config.h" #include #include +#include +#include #include #include #include @@ -80,11 +82,19 @@ struct WriteDeferral { ~WriteDeferral() { try { value.Complete(); } catch (...) { DEBUG_WARN(CAT, "%s", exception_reason("write deferral").c_str()); } } }; struct WinState : std::enable_shared_from_this { + /* Имена имеют статическое время жизни; контекст ошибки сохраняется независимо от уровня лога. */ + struct Event { + const char* name; + ble_link_id id; + std::function run; + }; struct UASYNC* ua = nullptr; struct ble_transport* owner = nullptr; uint16_t company = 0; std::mutex mutex; - std::deque> events; + std::deque events; + const char* operation = "idle"; /* Только uasync; Windows callbacks передают контекст через Event. */ + ble_link_id operation_link = 0; struct posted_task* posted = nullptr; bool stopped = false, failed = false, overflow = false, apartment = false, scan_ready = false, service_ready = false; IAsyncInfo startup{nullptr}; @@ -103,27 +113,39 @@ struct WinState : std::enable_shared_from_this { size_t broadcast_size = 0; bool broadcast_enabled = false; uint64_t publish_generation = 0; + /* Отмечает конкретный вызов до обращения к WinRT, включая синхронные исключения. */ + void step(const char* name, ble_link_id id = 0) { + operation = name; operation_link = id; + DEBUG_TRACE(CAT, "BLE WinRT operation=%s link=%llu", name, (unsigned long long)id); + } static void dispatch(void* arg) { auto& s = *static_cast(arg); - std::deque> batch; + std::deque batch; bool overloaded; { std::lock_guard guard(s.mutex); s.posted = nullptr; batch.swap(s.events); overloaded = s.overflow; s.overflow = false; } if (overloaded) { s.fail("WinRT event queue overflow"); return; } DEBUG_TRACE(CAT, "BLE WinRT dispatch events=%zu links=%zu", batch.size(), s.links.size()); for (auto& event : batch) { if (s.stopped || s.failed) break; - try { event(s); } - catch (...) { s.fail(exception_reason("event dispatch").c_str()); } + s.step(event.name, event.id); + try { event.run(s); } + catch (...) { + auto reason = exception_reason(s.operation, s.operation_link); + DEBUG_ERROR(CAT, "BLE WinRT event=%s event_link=%llu: %s", event.name, + (unsigned long long)event.id, reason.c_str()); + if (event.id) s.error(event.id, reason.c_str()); + else s.fail(reason.c_str()); + } } } - void post(std::function event) { + void post(const char* name, ble_link_id id, std::function event) { std::lock_guard guard(mutex); if (stopped) return; if (events.size() >= 256) { if (!overflow) DEBUG_ERROR(CAT, "BLE WinRT event mailbox full queued=%zu limit=256", events.size()); overflow = true; } - else events.push_back(std::move(event)); + else events.push_back({name, id, std::move(event)}); if (posted) return; posted = static_cast(u_calloc(1, sizeof(struct posted_task))); if (!posted) { overflow = true; DEBUG_ERROR(CAT, "BLE WinRT event allocation failed"); return; } @@ -132,6 +154,8 @@ struct WinState : std::enable_shared_from_this { WinLink* link(ble_link_id id) { auto it = links.find(id); return it == links.end() ? nullptr : it->second.get(); } void fail(const char* reason) { if (failed) return; + DEBUG_ERROR(CAT, "BLE WinRT radio failure scan_ready=%d service_ready=%d links=%zu publisher_generation=%llu", + scan_ready, service_ready, links.size(), (unsigned long long)publish_generation); failed = true; DEBUG_ERROR(CAT, "BLE WinRT failed: %s", reason); ble_backend_status(owner, 0, reason); } void error(ble_link_id id, const char* reason) { @@ -145,13 +169,14 @@ struct WinState : std::enable_shared_from_this { } template void await(const char* phase, const IAsyncOperation& operation, ble_link_id id, Callback callback) { + step(phase, id); const bool fragment = !std::strcmp(phase, "write frame") || !std::strcmp(phase, "notify frame"); if (!fragment) DEBUG_DEBUG(CAT, "BLE WinRT async begin phase=%s link=%llu", phase, (unsigned long long)id); if (id) { auto* l = link(id); if (!l) { operation.Cancel(); return; } l->operation = operation; } else startup = operation; auto weak = weak_from_this(); operation.Completed([weak, id, phase, fragment, callback](const IAsyncOperation& op, AsyncStatus status) { - if (auto s = weak.lock()) s->post([id, op, status, phase, fragment, callback](WinState& self) { + if (auto s = weak.lock()) s->post(phase, id, [id, op, status, phase, fragment, callback](WinState& self) { auto* l = id ? self.link(id) : nullptr; if (id && !l) { DEBUG_DEBUG(CAT, "BLE WinRT stale completion phase=%s link=%llu status=%d", phase, (unsigned long long)id, (int)status); @@ -166,7 +191,10 @@ struct WinState : std::enable_shared_from_this { return; } if (!fragment) DEBUG_DEBUG(CAT, "BLE WinRT async complete phase=%s link=%llu", phase, (unsigned long long)id); - callback(self, op.GetResults()); + self.step("IAsyncOperation.GetResults", id); + auto result = op.GetResults(); + self.step(phase, id); + callback(self, result); }); }); } @@ -202,7 +230,7 @@ struct WinState : std::enable_shared_from_this { if (!api) { DEBUG_INFO(CAT, "BLE WinRT speed API unavailable link=%llu; using OS parameters", (unsigned long long)l.id); return; } auto weak = weak_from_this(); auto id = l.id; auto changed = [weak, id](auto const&, auto const&) { - if (auto s = weak.lock()) s->post([id](WinState& s) { s.log_connection(id); }); + if (auto s = weak.lock()) s->post("connection parameters/PHY changed", id, [id](WinState& s) { s.log_connection(id); }); }; l.parameters_changed = api.ConnectionParametersChanged(auto_revoke, changed); l.phy_changed = api.ConnectionPhyChanged(auto_revoke, changed); @@ -215,22 +243,26 @@ struct WinState : std::enable_shared_from_this { } void watch_session(WinLink& l) { auto weak = weak_from_this(); auto id = l.id; + step("GattSession.SessionStatusChanged registration (auto_revoke)", id); l.session_changed = l.session.SessionStatusChanged(auto_revoke, [weak, id](auto const&, GattSessionStatusChangedEventArgs const& a) { - auto status = a.Status(); auto error = a.Error(); - if (auto s = weak.lock()) s->post([id, status, error](WinState& s) { + if (auto s = weak.lock()) s->post("GattSession.SessionStatusChanged", id, [id, a](WinState& s) { + auto status = a.Status(); auto error = a.Error(); DEBUG_DEBUG(CAT, "BLE WinRT session link=%llu status=%d error=%d (%s)", (unsigned long long)id, (int)status, (int)error, bluetooth_error(error)); if (status == GattSessionStatus::Closed && s.link(id)) s.error(id, "GATT session closed"); }); }); + step("GattSession.MaxPduSizeChanged registration (auto_revoke)", id); l.pdu_changed = l.session.MaxPduSizeChanged(auto_revoke, [weak, id](auto const& session, auto const&) { - auto mtu = session.MaxPduSize(); - if (auto s = weak.lock()) s->post([id, mtu](WinState&) { + if (auto s = weak.lock()) s->post("GattSession.MaxPduSizeChanged", id, [id, session](WinState& s) { + if (!s.link(id)) return; + auto mtu = session.MaxPduSize(); DEBUG_DEBUG(CAT, "BLE WinRT negotiated PDU changed link=%llu mtu=%u", (unsigned long long)id, (unsigned)mtu); }); }); } WinLink* incoming(const GattSession& session) { + step("incoming GattSession.DeviceId"); hstring key = session.DeviceId().Id(); for (auto& [id, l] : links) if (l->device_id == key) return l->outgoing ? nullptr : l.get(); std::string endpoint = to_string(key); @@ -245,15 +277,26 @@ struct WinState : std::enable_shared_from_this { } void subscriptions() { std::vector active; + step("GattLocalCharacteristic.SubscribedClients"); auto invitations = local_invite.SubscribedClients(), acknowledgements = local_ack.SubscribedClients(); - for (auto const& client : local_tx.SubscribedClients()) { + auto clients = local_tx.SubscribedClients(); + DEBUG_DEBUG(CAT, "BLE WinRT subscriptions DATA=%u INVITE=%u ACK=%u links=%zu", + clients.Size(), invitations.Size(), acknowledgements.Size(), links.size()); + for (auto const& client : clients) { + step("GattSubscribedClient.Session/DeviceId"); auto same_device = [&client](auto const& other) { return client.Session().DeviceId().Id() == other.Session().DeviceId().Id(); }; auto invitation = std::find_if(invitations.begin(), invitations.end(), same_device); auto acknowledgement = std::find_if(acknowledgements.begin(), acknowledgements.end(), same_device); - if (invitation == invitations.end() || acknowledgement == acknowledgements.end()) continue; + if (invitation == invitations.end() || acknowledgement == acknowledgements.end()) { + DEBUG_DEBUG(CAT, "BLE WinRT subscriptions incomplete device=%s DATA=1 INVITE=%d ACK=%d", + to_string(client.Session().DeviceId().Id()).c_str(), + invitation != invitations.end(), acknowledgement != acknowledgements.end()); + continue; + } auto* l = incoming(client.Session()); if (!l) continue; l->subscriber = client; l->invite_subscriber = *invitation; l->ack_subscriber = *acknowledgement; active.push_back(l->id); if (!l->opened) { + step("GattSubscribedClient.MaxNotificationSize", l->id); auto capacity = std::min({client.MaxNotificationSize(), (*invitation).MaxNotificationSize(), (*acknowledgement).MaxNotificationSize()}); DEBUG_DEBUG(CAT, "BLE WinRT subscribed DATA/INVITE/ACK link=%llu capacity=%u", (unsigned long long)l->id, capacity); l->opened = true; ble_backend_opened(owner, l->id, capacity + 3); @@ -308,17 +351,26 @@ struct WinState : std::enable_shared_from_this { } GattLocalCharacteristic::WriteRequested_revoker watch_write(GattLocalCharacteristic const& characteristic, enum ble_wire_channel channel) { auto weak = weak_from_this(); + step("GattLocalCharacteristic.WriteRequested registration (auto_revoke)"); + DEBUG_DEBUG(CAT, "BLE WinRT register WriteRequested channel=%d", channel); return characteristic.WriteRequested(auto_revoke, [weak, channel](auto const&, GattWriteRequestedEventArgs const& args) { + const char* phase = "WriteRequested.GetDeferral"; try { auto deferral = std::make_shared(args.GetDeferral()); - auto request = args.GetRequestAsync(); auto session = args.Session(); + phase = "WriteRequested.GetRequestAsync"; auto request = args.GetRequestAsync(); + phase = "WriteRequested.Session"; auto session = args.Session(); + phase = "WriteRequested.GetRequestAsync.Completed registration"; request.Completed([weak, deferral, session, channel](auto const& operation, AsyncStatus status) { - if (auto s = weak.lock()) s->post([deferral, session, operation, status, channel](WinState& s) { + if (auto s = weak.lock()) s->post("GattLocalCharacteristic.WriteRequested", 0, + [deferral, session, operation, status, channel](WinState& s) { if (status != AsyncStatus::Completed) { - DEBUG_WARN(CAT, "BLE WinRT GetRequest status=%d HRESULT=0x%08x", (int)status, (unsigned)operation.ErrorCode().value); + DEBUG_WARN(CAT, "BLE WinRT GetRequest channel=%d status=%d HRESULT=0x%08x", + channel, (int)status, (unsigned)operation.ErrorCode().value); return; } + s.step("GattWriteRequestedEventArgs.GetRequestAsync.GetResults"); auto request = operation.GetResults(); if (!request) { DEBUG_WARN(CAT, "BLE WinRT expired write request"); return; } + s.step("GattWriteRequest.Option/Offset/Value"); bool response = request.Option() == GattWriteOption::WriteWithResponse; auto expected = channel == BLE_WIRE_DATA ? GattWriteOption::WriteWithoutResponse : GattWriteOption::WriteWithResponse; if (request.Offset() || request.Option() != expected || !request.Value().Length() || request.Value().Length() > BLE_VALUE_MAX) { @@ -338,15 +390,18 @@ struct WinState : std::enable_shared_from_this { return; } } - auto id = l->id; auto data = bytes(request.Value()); - DEBUG_TRACE(CAT, "BLE WinRT RX write link=%llu bytes=%zu", (unsigned long long)id, data.size()); + auto id = l->id; + s.step("GattWriteRequest.Value/DataReader", id); auto data = bytes(request.Value()); + DEBUG_TRACE(CAT, "BLE WinRT RX write link=%llu channel=%d bytes=%zu response=%d", + (unsigned long long)id, channel, data.size(), response); ble_backend_received(s.owner, id, channel, data.data(), data.size()); + s.step("GattWriteRequest.Respond", id); if (response) { if (s.link(id)) request.Respond(); else request.RespondWithProtocolError(0x08); } }); }); } catch (...) { - auto reason = exception_reason("WriteRequested"); - if (auto s = weak.lock()) s->post([reason](WinState& s) { s.fail(reason.c_str()); }); + auto reason = exception_reason(phase); + if (auto s = weak.lock()) s->post("WriteRequested failure", 0, [reason](WinState& s) { s.fail(reason.c_str()); }); } }); } @@ -355,18 +410,22 @@ struct WinState : std::enable_shared_from_this { write_requested = watch_write(local_rx, BLE_WIRE_DATA); invite_write_requested = watch_write(local_invite, BLE_WIRE_INVITE); ack_write_requested = watch_write(local_ack, BLE_WIRE_ACK); + step("ACK.SubscribedClientsChanged registration (auto_revoke)"); ack_subscriptions_changed = local_ack.SubscribedClientsChanged(auto_revoke, [weak](auto const&, auto const&) { - if (auto s = weak.lock()) s->post([](WinState& s) { s.subscriptions(); }); + if (auto s = weak.lock()) s->post("ACK.SubscribedClientsChanged", 0, [](WinState& s) { s.subscriptions(); }); }); + step("INVITE.SubscribedClientsChanged registration (auto_revoke)"); invite_subscriptions_changed = local_invite.SubscribedClientsChanged(auto_revoke, [weak](auto const&, auto const&) { - if (auto s = weak.lock()) s->post([](WinState& s) { s.subscriptions(); }); + if (auto s = weak.lock()) s->post("INVITE.SubscribedClientsChanged", 0, [](WinState& s) { s.subscriptions(); }); }); + step("DATA.SubscribedClientsChanged registration (auto_revoke)"); subscriptions_changed = local_tx.SubscribedClientsChanged(auto_revoke, [weak](auto const&, auto const&) { - if (auto s = weak.lock()) s->post([](WinState& s) { s.subscriptions(); }); + if (auto s = weak.lock()) s->post("DATA.SubscribedClientsChanged", 0, [](WinState& s) { s.subscriptions(); }); }); + step("GattServiceProvider.AdvertisementStatusChanged registration (auto_revoke)"); service_changed = provider.AdvertisementStatusChanged(auto_revoke, [weak](auto const&, auto const& args) { - auto status = args.Status(); auto error = args.Error(); - if (auto s = weak.lock()) s->post([status, error](WinState& s) { + if (auto s = weak.lock()) s->post("GattServiceProvider.AdvertisementStatusChanged", 0, [args](WinState& s) { + auto status = args.Status(); auto error = args.Error(); DEBUG_DEBUG(CAT, "BLE WinRT service advertising state=%d error=%d (%s)", (int)status, (int)error, bluetooth_error(error)); if (status == GattServiceProviderAdvertisementStatus::Started) { s.service_ready = true; s.ready(); } else if (status == GattServiceProviderAdvertisementStatus::Aborted) s.radio_error("GATT advertising aborted", error); @@ -375,35 +434,56 @@ struct WinState : std::enable_shared_from_this { }); GattServiceProviderAdvertisingParameters parameters; parameters.IsConnectable(true); parameters.IsDiscoverable(true); DEBUG_DEBUG(CAT, "BLE WinRT start server service=%s connectable=1 discoverable=1", BLE_SERVICE_UUID); - provider.StartAdvertising(parameters); + step("GattServiceProvider.StartAdvertising"); provider.StartAdvertising(parameters); + step("BluetoothLEAdvertisementWatcher construction/ScanningMode"); watcher = BluetoothLEAdvertisementWatcher(); watcher.ScanningMode(BluetoothLEScanningMode::Active); + step("Watcher.Received registration (auto_revoke)"); received = watcher.Received(auto_revoke, [weak](auto const&, BluetoothLEAdvertisementReceivedEventArgs const& args) { auto state = weak.lock(); if (!state) return; - bool matching = false; - for (auto const& value : args.Advertisement().ManufacturerData()) if (value.CompanyId() == state->company) matching = true; - if (!matching) return; - state->post([args](WinState& s) { + try { + bool matching = false; + for (auto const& value : args.Advertisement().ManufacturerData()) if (value.CompanyId() == state->company) matching = true; + if (!matching) return; + } catch (...) { + auto reason = exception_reason("Received manufacturer filter"); + state->post("Watcher.Received filter failure", 0, [reason](WinState& s) { s.fail(reason.c_str()); }); + return; + } + state->post("Watcher.Received", 0, [args](WinState& s) { + s.step("Received.Advertisement.ManufacturerData"); for (auto const& value : args.Advertisement().ManufacturerData()) { if (value.CompanyId() != s.company || value.Data().Length() > BLE_BROADCAST_MAX) continue; struct ble_endpoint ep{}; - std::snprintf(ep.id, sizeof(ep.id), "%012llx/%d", (unsigned long long)args.BluetoothAddress(), (int)args.BluetoothAddressType()); + s.step("Received.QueryInterface(IBluetoothLEAdvertisementReceivedEventArgs2)"); + auto address_api = args.try_as(); + if (!address_api) { + s.fail("Received: IBluetoothLEAdvertisementReceivedEventArgs2 unavailable; Windows 10 2004+ required"); return; + } + s.step("Received.BluetoothAddressType"); auto type = address_api.BluetoothAddressType(); + s.step("Received.BluetoothAddress"); auto address = args.BluetoothAddress(); + std::snprintf(ep.id, sizeof(ep.id), "%012llx/%d", (unsigned long long)address, (int)type); + s.step("Received manufacturer buffer/DataReader"); auto data = bytes(value.Data()); + s.step("Received.RawSignalStrengthInDBm"); auto rssi = args.RawSignalStrengthInDBm(); DEBUG_TRACE(CAT, "BLE WinRT broadcast endpoint=%s company=%04x bytes=%zu rssi=%d", ep.id, s.company, - data.size(), args.RawSignalStrengthInDBm()); - ble_backend_broadcast(s.owner, &ep, data.data(), data.size(), args.RawSignalStrengthInDBm()); + data.size(), rssi); + s.step("ble_backend_broadcast"); + ble_backend_broadcast(s.owner, &ep, data.data(), data.size(), rssi); } }); }); + step("Watcher.Stopped registration (auto_revoke)"); scan_stopped = watcher.Stopped(auto_revoke, [weak](auto const&, auto const& args) { - auto error = args.Error(); if (auto s = weak.lock()) s->post([error](WinState& s) { - s.radio_error("scan stopped", error); + if (auto s = weak.lock()) s->post("Watcher.Stopped", 0, [args](WinState& s) { + s.radio_error("scan stopped", args.Error()); }); }); - watcher.Start(); + step("Watcher.Start"); watcher.Start(); DEBUG_DEBUG(CAT, "BLE WinRT scan requested mode=active status=%d company=%04x", (int)watcher.Status(), company); scan_ready = true; ready(); } void publish() { + step("Publisher.Status"); DEBUG_DEBUG(CAT, "BLE WinRT publish requested enabled=%d bytes=%zu generation=%llu", broadcast_enabled, broadcast_size, (unsigned long long)publish_generation); if (publisher) { @@ -415,24 +495,34 @@ struct WinState : std::enable_shared_from_this { publish_changed.revoke(); publisher = nullptr; } if (!broadcast_enabled) return; + step("Publisher construction/manufacturer data"); BluetoothLEAdvertisement advertisement; BluetoothLEManufacturerData data; data.CompanyId(company); data.Data(buffer(broadcast.data(), broadcast_size)); advertisement.ManufacturerData().Append(data); publisher = BluetoothLEAdvertisementPublisher(advertisement); auto weak = weak_from_this(); auto generation = ++publish_generation; + step("Publisher.StatusChanged registration (auto_revoke)"); publish_changed = publisher.StatusChanged(auto_revoke, [weak, generation](auto const&, auto const& args) { - auto status = args.Status(); auto error = args.Error(); - if (auto s = weak.lock()) s->post([status, error, generation](WinState& s) { - if (generation != s.publish_generation) return; + if (auto s = weak.lock()) s->post("Publisher.StatusChanged", 0, [args, generation](WinState& s) { + if (generation != s.publish_generation) { + DEBUG_DEBUG(CAT, "BLE WinRT stale publisher event generation=%llu current=%llu", + (unsigned long long)generation, (unsigned long long)s.publish_generation); + return; + } + auto status = args.Status(); auto error = args.Error(); DEBUG_DEBUG(CAT, "BLE WinRT broadcast state=%d error=%d (%s) generation=%llu", (int)status, (int)error, bluetooth_error(error), (unsigned long long)generation); if (status == BluetoothLEAdvertisementPublisherStatus::Aborted) s.radio_error("broadcast publication aborted", error); else if (status == BluetoothLEAdvertisementPublisherStatus::Stopped) { ble_backend_advertising(s.owner, BLE_CLOSED, "publisher stopped"); s.publish(); } else if (status == BluetoothLEAdvertisementPublisherStatus::Started) ble_backend_advertising(s.owner, BLE_READY, "publisher started"); - else ble_backend_advertising(s.owner, BLE_STARTING, "publisher waiting/stopping"); + else if (status == BluetoothLEAdvertisementPublisherStatus::Waiting) + ble_backend_advertising(s.owner, BLE_STARTING, "publisher waiting for radio resources"); + else if (status == BluetoothLEAdvertisementPublisherStatus::Stopping) + ble_backend_advertising(s.owner, BLE_STARTING, "publisher stopping"); + else ble_backend_advertising(s.owner, BLE_STARTING, "publisher created"); }); }); - publisher.Start(); + step("Publisher.Start"); publisher.Start(); } void connect(ble_link_id id, uint64_t address, BluetoothAddressType type) { DEBUG_DEBUG(CAT, "BLE WinRT connect link=%llu address=%012llx type=%d", (unsigned long long)id, (unsigned long long)address, (int)type); @@ -497,10 +587,14 @@ struct WinState : std::enable_shared_from_this { } GattCharacteristic::ValueChanged_revoker watch_value(ble_link_id id, GattCharacteristic const& characteristic, enum ble_wire_channel channel) { auto weak = weak_from_this(); + step("GattCharacteristic.ValueChanged registration (auto_revoke)", id); + DEBUG_DEBUG(CAT, "BLE WinRT register ValueChanged link=%llu channel=%d", (unsigned long long)id, channel); return characteristic.ValueChanged(auto_revoke, [weak, id, channel](auto const&, GattValueChangedEventArgs const& args) { - if (auto s = weak.lock()) s->post([id, channel, args](WinState& s) { + if (auto s = weak.lock()) s->post("GattCharacteristic.ValueChanged", id, [id, channel, args](WinState& s) { if (!s.link(id)) return; + s.step("ValueChanged.CharacteristicValue/DataReader", id); auto data = bytes(args.CharacteristicValue()); + DEBUG_TRACE(CAT, "BLE WinRT RX value link=%llu channel=%d bytes=%zu", (unsigned long long)id, channel, data.size()); ble_backend_received(s.owner, id, channel, data.data(), data.size()); }); }); @@ -510,12 +604,15 @@ struct WinState : std::enable_shared_from_this { auto characteristic = channel == BLE_WIRE_ACK ? l->ack : channel == BLE_WIRE_DATA ? l->tx : l->invite; auto mode = channel == BLE_WIRE_DATA ? GattClientCharacteristicConfigurationDescriptorValue::Notify : GattClientCharacteristicConfigurationDescriptorValue::Indicate; - await("subscribe channel", characteristic.WriteClientCharacteristicConfigurationDescriptorAsync(mode), id, - [id, channel](WinState& s, GattCommunicationStatus status) { + step("GattCharacteristic.WriteCCCDWithResultAsync", id); + DEBUG_DEBUG(CAT, "BLE WinRT subscribe request link=%llu channel=%d mode=%d", (unsigned long long)id, channel, (int)mode); + await("subscribe channel", characteristic.WriteClientCharacteristicConfigurationDescriptorWithResultAsync(mode), id, + [id, channel](WinState& s, GattWriteResult const& result) { + auto status = result.Status(); auto protocol = result.ProtocolError(); DEBUG_DEBUG(CAT, "BLE WinRT subscribe link=%llu channel=%d status=%d", (unsigned long long)id, channel, (int)status); if (status != GattCommunicationStatus::Success) { - DEBUG_WARN(CAT, "BLE WinRT subscription failed link=%llu channel=%d status=%d", - (unsigned long long)id, channel, (int)status); + DEBUG_WARN(CAT, "BLE WinRT subscription failed link=%llu channel=%d status=%d ATT_error=%d", + (unsigned long long)id, channel, (int)status, protocol ? int(protocol.Value()) : -1); s.error(id, "GATT subscription failed"); return; } if (channel == BLE_WIRE_DATA) { s.subscribe_channel(id, BLE_WIRE_INVITE); return; } @@ -543,7 +640,7 @@ struct WinState : std::enable_shared_from_this { } void shutdown() { struct posted_task* task; - std::deque> discarded; + std::deque discarded; { std::lock_guard guard(mutex); stopped = true; task = posted; posted = nullptr; discarded.swap(events); } DEBUG_DEBUG(CAT, "BLE WinRT shutdown links=%zu discarded_events=%zu pending_dispatch=%d", links.size(), discarded.size(), task != nullptr); discarded.clear(); @@ -568,6 +665,16 @@ extern "C" struct ble_backend* ble_backend_create(struct ble_transport* owner, s try { DEBUG_DEBUG(CAT, "BLE WinRT initialize company=%04x node=%016llx apartment=MTA", cfg->company_id, (unsigned long long)cfg->node_id); init_apartment(apartment_type::multi_threaded); state->apartment = true; + state->step("ApiInformation.IsPropertyPresent(BluetoothAddressType)"); + bool address_type = Windows::Foundation::Metadata::ApiInformation::IsPropertyPresent( + L"Windows.Devices.Bluetooth.Advertisement.BluetoothLEAdvertisementReceivedEventArgs", L"BluetoothAddressType"); + DEBUG_INFO(CAT, "BLE WinRT API BluetoothAddressType=%d required=Windows10-2004 wire=3 channels=DATA/INVITE/ACK", address_type); + if (!address_type) throw hresult_error(E_NOINTERFACE, L"BLE requires BluetoothAddressType (Windows 10 2004 / build 19041 or newer)"); + try { + auto version = Windows::System::Profile::AnalyticsInfo::VersionInfo(); + DEBUG_INFO(CAT, "BLE WinRT OS family=%s version=%s", to_string(version.DeviceFamily()).c_str(), + to_string(version.DeviceFamilyVersion()).c_str()); + } catch (...) { DEBUG_WARN(CAT, "%s", exception_reason("OS version diagnostics").c_str()); } state->await("get default adapter", BluetoothAdapter::GetDefaultAsync(), 0, [](WinState& s, BluetoothAdapter const& adapter) { if (!adapter) { s.fail("no default Bluetooth adapter"); return; } DEBUG_DEBUG(CAT, "BLE WinRT adapter id=%s address=%012llx BLE=%d central=%d peripheral=%d", to_string(adapter.DeviceId()).c_str(), @@ -589,7 +696,7 @@ extern "C" struct ble_backend* ble_backend_create(struct ble_transport* owner, s void* memory = u_malloc(sizeof(ble_backend)); if (!memory) { DEBUG_ERROR(CAT, "BLE WinRT allocation failed"); state->shutdown(); return nullptr; } return new(memory) ble_backend{state}; - } catch (...) { DEBUG_ERROR(CAT, "%s", exception_reason("initialize").c_str()); state->shutdown(); return nullptr; } + } catch (...) { DEBUG_ERROR(CAT, "%s", exception_reason(state->operation).c_str()); state->shutdown(); return nullptr; } } extern "C" void ble_backend_destroy(struct ble_backend* b) { if (!b) return; @@ -600,7 +707,7 @@ extern "C" int ble_backend_advertise(struct ble_backend* b, const uint8_t* data, auto& s = *b->state; s.broadcast_enabled = data != nullptr; s.broadcast_size = len; if (len) std::memcpy(s.broadcast.data(), data, len); s.publish(); return BLE_OK; - } catch (...) { DEBUG_ERROR(CAT, "%s", exception_reason("advertise").c_str()); return BLE_ERROR; } + } catch (...) { DEBUG_ERROR(CAT, "%s", exception_reason(b->state->operation).c_str()); return BLE_ERROR; } } extern "C" int ble_backend_connect(struct ble_backend* b, ble_link_id id, const struct ble_endpoint* ep) { unsigned long long address; int type, consumed = 0; @@ -621,31 +728,38 @@ extern "C" int ble_backend_send(struct ble_backend* b, ble_link_id id, enum ble_ return BLE_ERROR; } try { - DEBUG_TRACE(CAT, "BLE WinRT TX fragment link=%llu outgoing=%d bytes=%zu", (unsigned long long)id, l->outgoing, len); + DEBUG_TRACE(CAT, "BLE WinRT TX fragment link=%llu outgoing=%d channel=%d bytes=%zu", + (unsigned long long)id, l->outgoing, channel, len); + s.step("TX DataWriter buffer", id); l->sending = true; auto buffer = WinState::buffer(data, len); auto option = channel == BLE_WIRE_DATA ? GattWriteOption::WriteWithoutResponse : GattWriteOption::WriteWithResponse; + uint64_t started = get_time_us(); + s.step(l->outgoing ? "GattCharacteristic.WriteValueWithResultAsync" : "GattLocalCharacteristic.NotifyValueAsync", id); if (l->outgoing) s.await("write frame", (channel == BLE_WIRE_ACK ? l->ack : channel == BLE_WIRE_INVITE ? l->invite : l->rx) .WriteValueWithResultAsync(buffer, option), id, - [id, len](WinState& s, GattWriteResult const& result) { + [id, len, channel, started](WinState& s, GattWriteResult const& result) { auto* l = s.link(id); l->sending = false; auto protocol = result.ProtocolError(); if (result.Status() != GattCommunicationStatus::Success) - DEBUG_WARN(CAT, "BLE WinRT write failed link=%llu bytes=%zu status=%d ATT_error=%d", (unsigned long long)id, - len, (int)result.Status(), protocol ? int(protocol.Value()) : -1); - else DEBUG_TRACE(CAT, "BLE WinRT write complete link=%llu bytes=%zu", (unsigned long long)id, len); + DEBUG_WARN(CAT, "BLE WinRT write failed link=%llu channel=%d bytes=%zu status=%d ATT_error=%d", (unsigned long long)id, + channel, len, (int)result.Status(), protocol ? int(protocol.Value()) : -1); + else DEBUG_TRACE(CAT, "BLE WinRT write complete link=%llu channel=%d bytes=%zu elapsed_us=%llu", + (unsigned long long)id, channel, len, (unsigned long long)(get_time_us() - started)); ble_backend_sent(s.owner, id, result.Status() == GattCommunicationStatus::Success); }); else s.await("notify frame", (channel == BLE_WIRE_ACK ? s.local_ack : channel == BLE_WIRE_INVITE ? s.local_invite : s.local_tx) .NotifyValueAsync(buffer, channel == BLE_WIRE_ACK ? l->ack_subscriber : channel == BLE_WIRE_INVITE ? l->invite_subscriber : l->subscriber), id, - [id, len](WinState& s, GattClientNotificationResult const& result) { + [id, len, channel, started](WinState& s, GattClientNotificationResult const& result) { auto* l = s.link(id); l->sending = false; + s.step("GattClientNotificationResult.Status/BytesSent", id); if (result.Status() != GattCommunicationStatus::Success || result.BytesSent() != len) - DEBUG_WARN(CAT, "BLE WinRT notification failed link=%llu expected=%zu sent=%u status=%d", (unsigned long long)id, - len, result.BytesSent(), (int)result.Status()); - else DEBUG_TRACE(CAT, "BLE WinRT notification complete link=%llu bytes=%zu", (unsigned long long)id, len); + DEBUG_WARN(CAT, "BLE WinRT notification failed link=%llu channel=%d expected=%zu sent=%u status=%d", (unsigned long long)id, + channel, len, result.BytesSent(), (int)result.Status()); + else DEBUG_TRACE(CAT, "BLE WinRT notification complete link=%llu channel=%d bytes=%zu elapsed_us=%llu", + (unsigned long long)id, channel, len, (unsigned long long)(get_time_us() - started)); ble_backend_sent(s.owner, id, result.Status() == GattCommunicationStatus::Success && result.BytesSent() == len); }); return BLE_OK; - } catch (...) { l->sending = false; DEBUG_ERROR(CAT, "%s", exception_reason("send", id).c_str()); return BLE_ERROR; } + } catch (...) { l->sending = false; DEBUG_ERROR(CAT, "%s", exception_reason(s.operation, id).c_str()); return BLE_ERROR; } }