Add independent diagnostics for stalled BLE WinRT cleanup calls

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")

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 <atomic>
+#include <chrono>
+#include <condition_variable>
+#include <exception>
+#include <mutex>
+#include <thread>
+
+class BleWinrtDiagnostics {
+public:
+    struct Context {
+        const void* backend; // Идентификатор backend; наблюдатель его не разыменовывает.
+        uint64_t link, peer; // 0 для общих ресурсов backend или неизвестного пира.
+        unsigned long tid;  // Windows TID потока, выполняющего WinRT-вызов.
+    };
+    std::atomic<size_t> 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<typename Fn>
+    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<std::chrono::microseconds>(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<std::chrono::milliseconds>(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

lib/ble/tests/test_ble_winrt_diagnostics.cpp

@@ -0,0 +1,70 @@
+/* Наблюдатель должен видеть зависший вызов без poll uasync, включая выключенный debug. */
+#include "../ble_winrt_diagnostics.h"
+#include <cstdlib>
+#include <stdexcept>
+#include <string>
+#include <vector>
+
+#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<Log> 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;
+}