From 0308d4a702ea40d9e9aeb20e9e00d9ab00b9db48 Mon Sep 17 00:00:00 2001 From: evgeny Date: Sun, 1 Nov 2026 20:37:44 +0100 Subject: [PATCH] Add independent diagnostics for stalled BLE WinRT cleanup calls --- lib/ble/CMakeLists.txt | 6 + lib/ble/ble_winrt_diagnostics.h | 122 +++++++++++++++++++ lib/ble/tests/test_ble_winrt_diagnostics.cpp | 70 +++++++++++ 3 files changed, 198 insertions(+) create mode 100644 lib/ble/ble_winrt_diagnostics.h create mode 100644 lib/ble/tests/test_ble_winrt_diagnostics.cpp diff --git a/lib/ble/CMakeLists.txt b/lib/ble/CMakeLists.txt index 6e059bfc3..d481c1ce6 100644 --- a/lib/ble/CMakeLists.txt +++ b/lib/ble/CMakeLists.txt @@ -94,6 +94,12 @@ target_link_libraries(test_ble_identity PRIVATE uasync) target_include_directories(test_ble_identity PRIVATE "${CMAKE_CURRENT_SOURCE_DIR}") set_target_properties(test_ble_identity PROPERTIES AUTOMOC OFF) add_test(NAME test_ble_identity COMMAND test_ble_identity) +add_executable(test_ble_winrt_diagnostics tests/test_ble_winrt_diagnostics.cpp) +target_compile_features(test_ble_winrt_diagnostics PRIVATE cxx_std_17) +target_link_libraries(test_ble_winrt_diagnostics PRIVATE uasync) +set_target_properties(test_ble_winrt_diagnostics PROPERTIES AUTOMOC OFF) +add_test(NAME test_ble_winrt_diagnostics COMMAND test_ble_winrt_diagnostics) +set_tests_properties(test_ble_winrt_diagnostics PROPERTIES TIMEOUT 10) find_package(Python3 COMPONENTS Interpreter QUIET) if(Python3_Interpreter_FOUND) add_test(NAME test_ble_dual_observer COMMAND "${Python3_EXECUTABLE}" "${CMAKE_CURRENT_SOURCE_DIR}/tests/test_ble_dual_observer.py") diff --git a/lib/ble/ble_winrt_diagnostics.h b/lib/ble/ble_winrt_diagnostics.h new file mode 100644 index 000000000..3be0332f6 --- /dev/null +++ b/lib/ble/ble_winrt_diagnostics.h @@ -0,0 +1,122 @@ +/* Диагностика синхронного WinRT teardown: run отмечает вход/выход отдельного вызова. + * start запускает независимый наблюдатель; destructor останавливает и присоединяет только его. + * Наблюдатель читает скалярный снимок, не обращается к WinRT/core/uasync и не удерживает их ресурсы. + * run/start/stop вызывает один поток-владелец; phase — строковый литерал, object/backend только печатаются. */ +#ifndef VIBECHAT_BLE_WINRT_DIAGNOSTICS_H +#define VIBECHAT_BLE_WINRT_DIAGNOSTICS_H +#include "../debug_config.h" +#include +#include +#include +#include +#include +#include + +class BleWinrtDiagnostics { +public: + struct Context { + const void* backend; // Идентификатор backend; наблюдатель его не разыменовывает. + uint64_t link, peer; // 0 для общих ресурсов backend или неизвестного пира. + unsigned long tid; // Windows TID потока, выполняющего WinRT-вызов. + }; + std::atomic queued{0}; // Число ожидающих событий mailbox, без захвата его mutex. + + /* Интервалы в микросекундах: первое предупреждение через 1s, повтор через 30s. */ + explicit BleWinrtDiagnostics(uint64_t warn_us = 1000000, uint64_t repeat_us = 30000000) + : warn_after(warn_us), repeat_after(repeat_us) {} + ~BleWinrtDiagnostics() { stop(); } + + /* Неудача создания наблюдателя логируется; синхронные begin/end остаются работоспособны. */ + void start() { + if (worker.joinable()) return; + try { worker = std::thread([this] { watch(); }); } + catch (const std::exception& e) { DEBUG_ERROR(DEBUG_CATEGORY_DISCOVERY, "BLE WinRT watchdog start failed: %s", e.what()); } + } + /* Пробуждает независимый поток, не ждёт завершения диагностируемого WinRT-вызова. */ + void stop() { + { std::lock_guard guard(mutex); stopping = true; } + changed.notify_one(); + if (worker.joinable()) worker.join(); + } + /* Обрамляет один вызов; исключение сохраняется для существующего обработчика HRESULT. */ + template + void run(Context context, const char* phase, const void* object, Fn fn) { + Snapshot call{context, phase, object, Clock::now(), 0, false}; + { + std::lock_guard guard(mutex); + call.sequence = ++sequence; active = call; + } + changed.notify_one(); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE WinRT step begin backend=%p seq=%llu link=%llu peer=%016llx tid=%lu phase=%s object=%p", + context.backend, (unsigned long long)call.sequence, (unsigned long long)context.link, + (unsigned long long)context.peer, context.tid, phase, object); + try { fn(); } + catch (...) { finish(call, "exception"); throw; } + finish(call, "ok"); + } + +private: + using Clock = std::chrono::steady_clock; + struct Snapshot { + Context context{}; + const char* phase = nullptr; + const void* object = nullptr; + Clock::time_point started{}; + uint64_t sequence = 0; + bool warned = false; + }; + std::chrono::microseconds warn_after, repeat_after; + std::mutex mutex; + std::condition_variable changed; + std::thread worker; + Snapshot active; + uint64_t sequence = 0; + bool stopping = false; + + /* Завершение медленного этапа видно на WARN даже при выключенной категории debug. */ + void finish(const Snapshot& call, const char* outcome) { + bool warned; + { + std::lock_guard guard(mutex); + warned = active.warned; active = {}; + } + changed.notify_one(); + auto elapsed = std::chrono::duration_cast(Clock::now() - call.started); + DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "BLE WinRT step end backend=%p seq=%llu link=%llu tid=%lu phase=%s elapsed_us=%llu result=%s", + call.context.backend, (unsigned long long)call.sequence, (unsigned long long)call.context.link, + call.context.tid, call.phase, (unsigned long long)elapsed.count(), outcome); + if (warned || elapsed >= warn_after) + DEBUG_WARN(DEBUG_CATEGORY_DISCOVERY, + "BLE WinRT slow step returned backend=%p seq=%llu link=%llu peer=%016llx tid=%lu phase=%s elapsed_ms=%llu result=%s", + call.context.backend, (unsigned long long)call.sequence, (unsigned long long)call.context.link, + (unsigned long long)call.context.peer, call.context.tid, call.phase, + (unsigned long long)(elapsed.count() / 1000), outcome); + } + /* Только снимок и часы: продолжает диагностировать даже полностью остановившийся uasync. */ + void watch() { + std::unique_lock lock(mutex); + while (!stopping) { + changed.wait(lock, [this] { return stopping || active.phase; }); + if (stopping) break; + auto current = active.sequence; + auto deadline = active.started + warn_after; + while (!stopping && active.phase && active.sequence == current) { + if (changed.wait_until(lock, deadline, [this, current] { + return stopping || !active.phase || active.sequence != current; + })) break; + active.warned = true; + auto call = active; + auto elapsed = std::chrono::duration_cast(Clock::now() - call.started).count(); + deadline = Clock::now() + repeat_after; + lock.unlock(); + DEBUG_WARN(DEBUG_CATEGORY_DISCOVERY, + "BLE WinRT step stalled backend=%p seq=%llu link=%llu peer=%016llx tid=%lu phase=%s object=%p elapsed_ms=%llu mailbox=%zu", + call.context.backend, (unsigned long long)call.sequence, (unsigned long long)call.context.link, + (unsigned long long)call.context.peer, call.context.tid, call.phase, call.object, + (unsigned long long)elapsed, queued.load()); + lock.lock(); + } + } + } +}; +#endif diff --git a/lib/ble/tests/test_ble_winrt_diagnostics.cpp b/lib/ble/tests/test_ble_winrt_diagnostics.cpp new file mode 100644 index 000000000..828e2f417 --- /dev/null +++ b/lib/ble/tests/test_ble_winrt_diagnostics.cpp @@ -0,0 +1,70 @@ +/* Наблюдатель должен видеть зависший вызов без poll uasync, включая выключенный debug. */ +#include "../ble_winrt_diagnostics.h" +#include +#include +#include +#include + +#define CHECK(value) do { if (!(value)) { DEBUG_ERROR(DEBUG_CATEGORY_DISCOVERY, "CHECK failed line=%d: %s", __LINE__, #value); std::abort(); } } while (0) + +struct Log { + std::string category, message; + std::thread::id thread; +}; +static std::mutex logs_mutex; +static std::condition_variable log_received; +static std::vector logs; + +static void capture(int, const char* category, const char* message) { + { std::lock_guard guard(logs_mutex); logs.push_back({category, message, std::this_thread::get_id()}); } + log_received.notify_one(); +} + +static size_t count(const char* text) { + size_t matches = 0; + for (const auto& log : logs) if (log.message.find(text) != std::string::npos) ++matches; + return matches; +} + +int main() { + debug_config_init(); debug_set_level(DEBUG_LEVEL_WARN); debug_enable_console(0); + debug_set_log_hook(capture); + BleWinrtDiagnostics::Context context{&logs, 278, 0x0c628e1649352dd6, 22164}; + auto owner = std::this_thread::get_id(); + { + BleWinrtDiagnostics diagnostic(20000, 20000); + diagnostic.queued = 19; diagnostic.start(); + debug_set_category_level(DEBUG_CATEGORY_DEBUG, DEBUG_LEVEL_DISABLED); + bool reported = false; + diagnostic.run(context, "BluetoothLEDevice.Close", &context, [&] { + std::unique_lock lock(logs_mutex); + reported = log_received.wait_for(lock, std::chrono::seconds(2), [] { return count("step stalled") >= 2; }); + }); + diagnostic.stop(); + CHECK(reported && !count("step begin") && !count("step end") && count("slow step returned") == 1); + for (const auto& log : logs) if (log.message.find("step stalled") != std::string::npos) { + CHECK(log.thread != owner && log.category == "discovery"); + CHECK(log.message.find("link=278 peer=0c628e1649352dd6 tid=22164 phase=BluetoothLEDevice.Close") != std::string::npos); + CHECK(log.message.find("mailbox=19") != std::string::npos); + } + } + logs.clear(); + debug_set_category_level(DEBUG_CATEGORY_DEBUG, DEBUG_LEVEL_DEBUG); + { + BleWinrtDiagnostics diagnostic; + diagnostic.start(); + diagnostic.run(context, "test.fast", nullptr, [] {}); + bool caught = false; + try { diagnostic.run(context, "test.throw", nullptr, [] { throw std::runtime_error("test cleanup failure"); }); } + catch (const std::runtime_error&) { caught = true; } + diagnostic.run(context, "test.after_exception", nullptr, [] {}); + diagnostic.stop(); + CHECK(caught && count("step begin") == 3 && count("step end") == 3 && count("result=exception") == 1); + CHECK(!count("step stalled") && !count("slow step returned")); + CHECK(count("seq=1") == 2 && count("seq=2") == 2 && count("seq=3") == 2); + for (const auto& log : logs) CHECK(log.category == "debug"); + } + debug_set_log_hook(nullptr); debug_enable_console(1); + DEBUG_WARN(DEBUG_CATEGORY_DISCOVERY, "PASS BLE WinRT diagnostics: independent stall/repeat/recovery, disabled debug, exceptions and shutdown"); + return 0; +}