Add a timer for scan responses

h2zero · h2zero · commit b4dc2d4f10e1 · 2026-03-22T10:07:43.000-06:00
This ensures that the callback will be called within the configured time (in ms) when devices fail to respond to a scan response request within that time.

* Also adds stats when debug logging to help tune the scan response timeout/scan parameters.
diff --git a/src/NimBLEAdvertisedDevice.h b/src/NimBLEAdvertisedDevice.h
@@ -158,11 +158,12 @@ class NimBLEAdvertisedDevice {
     uint8_t findAdvField(uint8_t type, uint8_t index = 0, size_t* data_loc = nullptr) const;
     size_t  findServiceData(uint8_t index, uint8_t* bytes) const;
 
-    NimBLEAddress m_address{};
-    uint8_t       m_advType{};
-    int8_t        m_rssi{};
-    uint8_t       m_callbackSent{};
-    uint16_t      m_advLength{};
+    NimBLEAddress  m_address{};
+    uint8_t        m_advType{};
+    int8_t         m_rssi{};
+    uint8_t        m_callbackSent{};
+    uint16_t       m_advLength{};
+    ble_npl_time_t m_time{};
 
 # if MYNEWT_VAL(BLE_EXT_ADV)
     bool     m_isLegacyAdv{};
diff --git a/src/NimBLEScan.cpp b/src/NimBLEScan.cpp
@@ -20,13 +20,75 @@
 
 # include "NimBLEDevice.h"
 # include "NimBLELog.h"
+# if defined(CONFIG_NIMBLE_CPP_IDF)
+#  include "nimble/nimble_port.h"
+# else
+#  include "nimble/porting/nimble/include/nimble/nimble_port.h"
+# endif
 
 # include <string>
 # include <climits>
 
 static const char*         LOG_TAG = "NimBLEScan";
 static NimBLEScanCallbacks defaultScanCallbacks;
 
+/**
+ * @brief Calls the onResult callback with the given device,
+ * this is used to provide a scan result to the callbacks when a device hasn't responded to
+ * the scan request in time. This is called by the host task from the default event queue.
+ */
+void NimBLEScan::forceResultCallback(ble_npl_event* ev) {
+    auto pScan = NimBLEDevice::getScan();
+    pScan->m_stats.incMissedSrCount();
+    NimBLEAdvertisedDevice* pDev = static_cast<NimBLEAdvertisedDevice*>(ble_npl_event_get_arg(ev));
+    pDev->m_callbackSent         = 2;
+    pScan->m_pScanCallbacks->onResult(pDev);
+}
+
+/**
+ * @brief This will schedule an event to run in the host task that will call forceResultCallback
+ * which will call the onResult callback with the current data.
+ */
+void NimBLEScan::srTimerCb(ble_npl_event* event) {
+    NimBLEScan*             pScan   = static_cast<NimBLEScan*>(ble_npl_event_get_arg(event));
+    NimBLEAdvertisedDevice* curDev  = nullptr;
+    NimBLEAdvertisedDevice* nextDev = nullptr;
+    ble_npl_time_t          now     = ble_npl_time_get();
+
+    for (auto& dev : pScan->m_scanResults.m_deviceVec) {
+        if (dev->m_callbackSent < 2 && dev->isScannable()) {
+            if (!curDev || (now - dev->m_time > now - curDev->m_time)) {
+                nextDev = curDev;
+                curDev  = dev;
+                continue;
+            }
+
+            if (!nextDev || now - dev->m_time > now - nextDev->m_time) {
+                nextDev = dev;
+            }
+        }
+    }
+
+    // Add the event to the host queue
+    if (curDev && now - curDev->m_time >= pScan->m_srTimeoutTicks) {
+        NIMBLE_LOGI(LOG_TAG, "Scan response timeout for: %s", curDev->getAddress().toString().c_str());
+        ble_npl_event_set_arg(&pScan->m_srTimeoutEvent, curDev);
+        ble_npl_eventq_put(nimble_port_get_dflt_eventq(), &pScan->m_srTimeoutEvent);
+    }
+
+    // Restart the timer for the next device that we are expecting a scan response from
+    if (nextDev) {
+        auto nextTime = now - nextDev->m_time;
+        if (nextTime >= pScan->m_srTimeoutTicks) {
+            nextTime = 1;
+        } else {
+            nextTime = pScan->m_srTimeoutTicks - nextTime;
+        }
+
+        ble_npl_callout_reset(&pScan->m_srTimer, nextTime);
+    }
+}
+
 /**
  * @brief Scan constructor.
  */
@@ -35,7 +97,11 @@ NimBLEScan::NimBLEScan()
       // default interval + window, no whitelist scan filter,not limited scan, no scan response, filter_duplicates
       m_scanParams{0, 0, BLE_HCI_SCAN_FILT_NO_WL, 0, 1, 1},
       m_pTaskData{nullptr},
-      m_maxResults{0xFF} {}
+      m_maxResults{0xFF} {
+    ble_npl_callout_init(&m_srTimer, nimble_port_get_dflt_eventq(), NimBLEScan::srTimerCb, this);
+    ble_npl_event_init(&m_srTimeoutEvent, forceResultCallback, NULL);
+    ble_npl_time_ms_to_ticks(BLE_GAP_SCAN_FAST_WINDOW, &m_srTimeoutTicks);
+} // NimBLEScan::NimBLEScan
 
 /**
  * @brief Scan destructor, release any allocated resources.
@@ -44,6 +110,9 @@ NimBLEScan::~NimBLEScan() {
     for (const auto& dev : m_scanResults.m_deviceVec) {
         delete dev;
     }
+
+    ble_npl_callout_deinit(&m_srTimer);
+    ble_npl_event_deinit(&m_srTimeoutEvent);
 }
 
 /**
@@ -101,6 +170,8 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
             // If we haven't seen this device before; create a new instance and insert it in the vector.
             // Otherwise just update the relevant parameters of the already known device.
             if (advertisedDevice == nullptr) {
+                pScan->m_stats.incDevCount();
+
                 // Check if we have reach the scan results limit, ignore this one if so.
                 // We still need to store each device when maxResults is 0 to be able to append the scan results
                 if (pScan->m_maxResults > 0 && pScan->m_maxResults < 0xFF &&
@@ -109,19 +180,36 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
                 }
 
                 if (isLegacyAdv && event_type == BLE_HCI_ADV_RPT_EVTYPE_SCAN_RSP) {
+                    pScan->m_stats.incOrphanedSrCount();
                     NIMBLE_LOGI(LOG_TAG, "Scan response without advertisement: %s", advertisedAddress.toString().c_str());
                 }
 
                 advertisedDevice = new NimBLEAdvertisedDevice(event, event_type);
                 pScan->m_scanResults.m_deviceVec.push_back(advertisedDevice);
+                advertisedDevice->m_time = ble_npl_time_get();
                 NIMBLE_LOGI(LOG_TAG, "New advertiser: %s", advertisedAddress.toString().c_str());
             } else {
                 advertisedDevice->update(event, event_type);
                 if (isLegacyAdv) {
                     if (event_type == BLE_HCI_ADV_RPT_EVTYPE_SCAN_RSP) {
                         NIMBLE_LOGI(LOG_TAG, "Scan response from: %s", advertisedAddress.toString().c_str());
+                        if (!pScan->m_stats.recordSrTime(ble_npl_time_get() - advertisedDevice->m_time,
+                                                         pScan->m_scanParams.window * 625 / 1000)) {
+                            NIMBLE_LOGD(LOG_TAG,
+                                        "Abnormal scan response time, stats ignored for device: %s",
+                                        advertisedAddress.toString().c_str());
+                        }
                     } else {
+                        pScan->m_stats.incDupCount();
                         NIMBLE_LOGI(LOG_TAG, "Duplicate; updated: %s", advertisedAddress.toString().c_str());
+                        // Restart scan-response timeout when we see a new non-scan-response
+                        // legacy advertisement during active scanning for a scannable device.
+                        advertisedDevice->m_time         = ble_npl_time_get();
+                        advertisedDevice->m_callbackSent = 0;
+                        if (pScan->m_srTimeoutTicks && advertisedDevice->isScannable() &&
+                            !ble_npl_callout_is_active(&pScan->m_srTimer)) {
+                            ble_npl_callout_reset(&pScan->m_srTimer, pScan->m_srTimeoutTicks);
+                        }
                     }
                 }
             }
@@ -147,6 +235,10 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
                 advertisedDevice->m_callbackSent++;
                 // got the scan response report the full data.
                 pScan->m_pScanCallbacks->onResult(advertisedDevice);
+            } else if (pScan->m_srTimeoutTicks && isLegacyAdv && advertisedDevice->isScannable() &&
+                       !ble_npl_callout_is_active(&pScan->m_srTimer)) {
+                // Start the timer to wait for the scan response.
+                ble_npl_callout_reset(&pScan->m_srTimer, pScan->m_srTimeoutTicks);
             }
 
             // If not storing results and we have invoked the callback, delete the device.
@@ -158,14 +250,22 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
         }
 
         case BLE_GAP_EVENT_DISC_COMPLETE: {
+            ble_npl_callout_stop(&pScan->m_srTimer);
+            for (const auto& dev : pScan->m_scanResults.m_deviceVec) {
+                if (dev->isScannable() && dev->m_callbackSent < 2) {
+                    pScan->m_stats.incMissedSrCount();
+                    pScan->m_pScanCallbacks->onResult(dev);
+                }
+            }
+
             NIMBLE_LOGD(LOG_TAG, "discovery complete; reason=%d", event->disc_complete.reason);
+            NIMBLE_LOGD(LOG_TAG, "%s", pScan->getStatsString().c_str());
 
+            pScan->m_pScanCallbacks->onScanEnd(pScan->m_scanResults, event->disc_complete.reason);
             if (pScan->m_maxResults == 0) {
                 pScan->clearResults();
             }
 
-            pScan->m_pScanCallbacks->onScanEnd(pScan->m_scanResults, event->disc_complete.reason);
-
             if (pScan->m_pTaskData != nullptr) {
                 NimBLEUtils::taskRelease(*pScan->m_pTaskData, event->disc_complete.reason);
             }
@@ -178,6 +278,25 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
     }
 } // handleGapEvent
 
+/**
+ * @brief Set the scan response timeout.
+ * @param [in] timeoutMs The timeout in milliseconds to wait for a scan response.
+ * @details If a scan response is not received within the timeout period,
+ * a dummy scan response with null data will be sent to the scan event handler
+ * which will trigger the callback with whatever data was in the advertisement.
+ * If set to 0, no dummy scan response will be sent and the callback will only
+ * be triggered when a scan response is received from the advertiser or when the scan completes.
+ */
+void NimBLEScan::setScanResponseTimeout(uint32_t timeoutMs) {
+    if (timeoutMs == 0) {
+        ble_npl_callout_stop(&m_srTimer);
+        m_srTimeoutTicks = 0;
+        return;
+    }
+
+    ble_npl_time_ms_to_ticks(timeoutMs, &m_srTimeoutTicks);
+} // setScanResponseTimeout
+
 /**
  * @brief Should we perform an active or passive scan?
  * The default is a passive scan. An active scan means that we will request a scan response.
@@ -323,11 +442,13 @@ bool NimBLEScan::start(uint32_t duration, bool isContinue, bool restart) {
 
             if (!isContinue) {
                 clearResults();
+                m_stats.reset();
             }
         }
     } else { // Don't clear results while scanning is active
         if (!isContinue) {
             clearResults();
+            m_stats.reset();
         }
     }
 
@@ -394,6 +515,8 @@ bool NimBLEScan::stop() {
         return false;
     }
 
+    ble_npl_callout_stop(&m_srTimer);
+
     if (m_maxResults == 0) {
         clearResults();
     }
diff --git a/src/NimBLEScan.h b/src/NimBLEScan.h
@@ -31,6 +31,8 @@
 # endif
 
 # include <vector>
+# include <cinttypes>
+# include <cstdio>
 
 class NimBLEDevice;
 class NimBLEScan;
@@ -82,6 +84,8 @@ class NimBLEScan {
     void              setMaxResults(uint8_t maxResults);
     void              erase(const NimBLEAddress& address);
     void              erase(const NimBLEAdvertisedDevice* device);
+    void              setScanResponseTimeout(uint32_t timeoutMs);
+    std::string       getStatsString() const { return m_stats.toString(); }
 
 # if MYNEWT_VAL(BLE_EXT_ADV)
     enum Phy { SCAN_1M = 0x01, SCAN_CODED = 0x02, SCAN_ALL = 0x03 };
@@ -92,15 +96,101 @@ class NimBLEScan {
   private:
     friend class NimBLEDevice;
 
+    struct stats {
+# if MYNEWT_VAL(NIMBLE_CPP_LOG_LEVEL) >= 4
+        uint32_t devCount        = 0; // unique devices seen for the first time
+        uint32_t dupCount        = 0; // repeat advertisements from already-known devices
+        uint32_t srMinMs         = UINT32_MAX;
+        uint32_t srMaxMs         = 0;
+        uint64_t srTotalMs       = 0; // uint64 to avoid overflow on long/busy scans
+        uint32_t srCount         = 0; // matched scan responses (advertisement + SR pair)
+        uint32_t orphanedSrCount = 0; // scan responses received with no prior advertisement
+        uint32_t missedSrCount   = 0; // scannable devices for which no SR ever arrived
+
+        void reset() {
+            devCount        = 0;
+            dupCount        = 0;
+            srMinMs         = UINT32_MAX;
+            srMaxMs         = 0;
+            srTotalMs       = 0;
+            srCount         = 0;
+            orphanedSrCount = 0;
+            missedSrCount   = 0;
+        }
+
+        void incDevCount() { devCount++; }
+        void incDupCount() { dupCount++; }
+        void incMissedSrCount() { missedSrCount++; }
+        void incOrphanedSrCount() { orphanedSrCount++; }
+
+        std::string toString() const {
+            std::string out;
+            out.resize(400); // should be more than enough for the stats string
+            snprintf(out.data(),
+                     out.size(),
+                     "Scan stats:\n"
+                     "  Devices seen      : %" PRIu32 "\n"
+                     "  Duplicate advs    : %" PRIu32 "\n"
+                     "  Scan responses    : %" PRIu32 "\n"
+                     "  SR timing (ms)    : min=%" PRIu32 ", max=%" PRIu32 ", avg=%" PRIu64 "\n"
+                     "  Orphaned SR       : %" PRIu32 "\n"
+                     "  Missed SR         : %" PRIu32 "\n",
+                     devCount,
+                     dupCount,
+                     srCount,
+                     srMinMs,
+                     srMaxMs,
+                     srCount ? srTotalMs / srCount : 0,
+                     orphanedSrCount,
+                     missedSrCount);
+            out.resize(strlen(out.c_str()));
+            return out;
+        }
+
+        // Records scan-response round-trip time. Returns false if the timing is abnormal
+        // (>= 5x the scan window) and should be excluded from stats.
+        bool recordSrTime(uint32_t ticks, uint16_t window) {
+            uint32_t ms;
+            ble_npl_time_ticks_to_ms(ticks, &ms);
+            if (ms >= (window ? window : BLE_GAP_SCAN_FAST_WINDOW) * 5) {
+                //return false;
+            }
+
+            if (ms < srMinMs) {
+                srMinMs = ms;
+            }
+            if (ms > srMaxMs) {
+                srMaxMs = ms;
+            }
+            srTotalMs += ms;
+            srCount++;
+            return true;
+        }
+# else
+        void        reset() {}
+        void        incDevCount() {}
+        void        incDupCount() {}
+        void        incMissedSrCount() {}
+        void        incOrphanedSrCount() {}
+        std::string toString() const { return ""; }
+        bool        recordSrTime(uint32_t ticks, uint16_t window) { return true; }
+# endif
+    } m_stats;
+
     NimBLEScan();
     ~NimBLEScan();
-    static int handleGapEvent(ble_gap_event* event, void* arg);
-    void       onHostSync();
+    static int  handleGapEvent(ble_gap_event* event, void* arg);
+    void        onHostSync();
+    static void srTimerCb(ble_npl_event* event);
+    static void forceResultCallback(ble_npl_event* ev);
 
     NimBLEScanCallbacks* m_pScanCallbacks;
     ble_gap_disc_params  m_scanParams;
     NimBLEScanResults    m_scanResults;
     NimBLETaskData*      m_pTaskData;
+    ble_npl_callout      m_srTimer{};
+    ble_npl_time_t       m_srTimeoutTicks{};
+    ble_npl_event        m_srTimeoutEvent{};
     uint8_t              m_maxResults;
 
 # if MYNEWT_VAL(BLE_EXT_ADV)
