Add a timer for scan responses

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.

* Adds stats when debug logging to help tune the scan response timeout/scan parameters.

Author: h2zero

src/NimBLEAdvertisedDevice.cpp

@@ -52,6 +52,7 @@ NimBLEAdvertisedDevice::NimBLEAdvertisedDevice(const ble_gap_event* event, uint8
       m_advLength{event->disc.length_data},
       m_payload(event->disc.data, event->disc.data + event->disc.length_data) {
 # endif
+    m_pNextWaiting = this; // initialize sentinel: self-pointer means "not in list"
 } // NimBLEAdvertisedDevice
 
 /**

src/NimBLEAdvertisedDevice.h

@@ -158,11 +158,13 @@ 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{};
+    NimBLEAdvertisedDevice*   m_pNextWaiting{}; // intrusive list node; self-pointer means "not in list", set in ctor
 
 # if MYNEWT_VAL(BLE_EXT_ADV)
     bool     m_isLegacyAdv{};

src/NimBLEScan.cpp

@@ -20,13 +20,43 @@
 
 # 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>
 
+# define DEFAULT_SCAN_RESP_TIMEOUT_MS 10240 // max advertising interval (10.24s)
+
 static const char*         LOG_TAG = "NimBLEScan";
 static NimBLEScanCallbacks defaultScanCallbacks;
 
+/**
+ * @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) {
+    auto pScan = NimBLEDevice::getScan();
+    auto pDev  = pScan->m_pWaitingListHead;
+
+    if (pDev == nullptr) {
+        ble_npl_callout_stop(&pScan->m_srTimer);
+        return;
+    }
+
+    NIMBLE_LOGI(LOG_TAG, "Scan response timeout for: %s", pDev->getAddress().toString().c_str());
+
+    pScan->removeWaitingDevice(pDev);
+    pDev->m_callbackSent = 2;
+    pScan->m_pScanCallbacks->onResult(pDev);
+    if (pScan->m_maxResults == 0) {
+        pScan->erase(pDev);
+    }
+}
+
 /**
  * @brief Scan constructor.
  */
@@ -35,17 +65,122 @@ 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, nullptr);
+    ble_npl_time_ms_to_ticks(DEFAULT_SCAN_RESP_TIMEOUT_MS, &m_srTimeoutTicks);
+} // NimBLEScan::NimBLEScan
 
 /**
  * @brief Scan destructor, release any allocated resources.
  */
 NimBLEScan::~NimBLEScan() {
+    ble_npl_callout_deinit(&m_srTimer);
+
     for (const auto& dev : m_scanResults.m_deviceVec) {
         delete dev;
     }
 }
 
+/**
+ * @brief Add a device to the waiting list for scan responses.
+ * @param [in] pDev The device to add to the list.
+ */
+void NimBLEScan::addWaitingDevice(NimBLEAdvertisedDevice* pDev) {
+    if (pDev == nullptr || pDev->m_pNextWaiting != pDev) {
+        return; // Invalid or already in list (self-pointer is the "not in list" sentinel)
+    }
+
+    pDev->m_pNextWaiting = nullptr;
+    if (m_pWaitingListTail == nullptr) {
+        ble_npl_hw_enter_critical();
+        m_pWaitingListHead = pDev;
+        m_pWaitingListTail = pDev;
+        ble_npl_hw_exit_critical(0);
+        return;
+    }
+
+    ble_npl_hw_enter_critical();
+    m_pWaitingListTail->m_pNextWaiting = pDev;
+    m_pWaitingListTail                 = pDev;
+    ble_npl_hw_exit_critical(0);
+}
+
+/**
+ * @brief Remove a device from the waiting list.
+ * @param [in] pDev The device to remove from the list.
+ */
+void NimBLEScan::removeWaitingDevice(NimBLEAdvertisedDevice* pDev) {
+    if (pDev == nullptr) {
+        return;
+    }
+
+    if (pDev->m_pNextWaiting == pDev) {
+        return; // Not in the list
+    }
+
+    bool resetTimer = false;
+    ble_npl_hw_enter_critical();
+    if (m_pWaitingListHead == pDev) {
+        m_pWaitingListHead = pDev->m_pNextWaiting;
+        if (m_pWaitingListHead == nullptr) {
+            m_pWaitingListTail = nullptr;
+        } else {
+            resetTimer = true;
+        }
+    } else {
+        NimBLEAdvertisedDevice* current = m_pWaitingListHead;
+        while (current != nullptr) {
+            if (current->m_pNextWaiting == pDev) {
+                current->m_pNextWaiting = pDev->m_pNextWaiting;
+                if (m_pWaitingListTail == pDev) {
+                    m_pWaitingListTail = current;
+                }
+                break;
+            }
+            current = current->m_pNextWaiting;
+        }
+    }
+    ble_npl_hw_exit_critical(0);
+    pDev->m_pNextWaiting = pDev; // Restore sentinel: self-pointer means "not in list"
+    if (resetTimer) {
+        resetWaitingTimer();
+    }
+}
+
+/**
+ * @brief Clear all devices from the waiting list.
+ */
+void NimBLEScan::clearWaitingList() {
+    // Stop the timer and remove any pending timeout events since we're clearing
+    // the list and won't be processing any more timeouts for these devices
+    ble_npl_callout_stop(&m_srTimer);
+    ble_npl_hw_enter_critical();
+    NimBLEAdvertisedDevice* current = m_pWaitingListHead;
+    while (current != nullptr) {
+        NimBLEAdvertisedDevice* next = current->m_pNextWaiting;
+        current->m_pNextWaiting      = current; // Restore sentinel
+        current                      = next;
+    }
+    m_pWaitingListHead = nullptr;
+    m_pWaitingListTail = nullptr;
+    ble_npl_hw_exit_critical(0);
+}
+
+/**
+ * @brief Reset the timer for the next waiting device at the head of the FIFO list.
+ */
+void NimBLEScan::resetWaitingTimer() {
+    if (m_srTimeoutTicks == 0 || m_pWaitingListHead == nullptr) {
+        ble_npl_callout_stop(&m_srTimer);
+        return;
+    }
+
+    ble_npl_time_t now      = ble_npl_time_get();
+    ble_npl_time_t elapsed  = now - m_pWaitingListHead->m_time;
+    ble_npl_time_t nextTime = elapsed >= m_srTimeoutTicks ? 1 : m_srTimeoutTicks - elapsed;
+    ble_npl_callout_reset(&m_srTimer, nextTime);
+}
+
 /**
  * @brief Handle GAP events related to scans.
  * @param [in] event The event type for this event.
@@ -101,6 +236,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 +246,39 @@ 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) {
+                        pScan->m_stats.recordSrTime(ble_npl_time_get() - advertisedDevice->m_time);
                         NIMBLE_LOGI(LOG_TAG, "Scan response from: %s", advertisedAddress.toString().c_str());
+                        // Remove device from waiting list since we got the response
+                        pScan->removeWaitingDevice(advertisedDevice);
                     } 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();
+                        // Re-add to the tail so FIFO timeout order matches advertisement order.
+                        if (pScan->m_srTimeoutTicks && advertisedDevice->isScannable()) {
+                            pScan->removeWaitingDevice(advertisedDevice);
+                            pScan->addWaitingDevice(advertisedDevice);
+                        }
+
+                        // If we're not filtering duplicates, we need to reset the callbackSent count
+                        // so that callbacks will be triggered again for this device
+                        if (!pScan->m_scanParams.filter_duplicates) {
+                            advertisedDevice->m_callbackSent = 0;
+                        }
                     }
                 }
             }
@@ -147,6 +304,12 @@ 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()) {
+                // Add to waiting list for scan response and start the timer
+                pScan->addWaitingDevice(advertisedDevice);
+                if (pScan->m_pWaitingListHead == advertisedDevice) {
+                    pScan->resetWaitingTimer();
+                }
             }
 
             // If not storing results and we have invoked the callback, delete the device.
@@ -158,7 +321,28 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
         }
 
         case BLE_GAP_EVENT_DISC_COMPLETE: {
+            pScan->clearWaitingList();
+            // If we have any scannable devices that haven't received a scan response,
+            // we should trigger the callback with whatever data we have since the scan is complete
+            // and we won't be getting any more updates for these devices.
+
+            // Make a copy in case the callback modifies the vector (e.g. by calling clearResults)
+            std::vector<NimBLEAdvertisedDevice*> pending{};
+            pending.reserve(pScan->m_scanResults.m_deviceVec.size());
+            for (const auto& dev : pScan->m_scanResults.m_deviceVec) {
+                if (dev->isScannable() && dev->m_callbackSent < 2) {
+                    pScan->m_stats.incMissedSrCount();
+                    dev->m_callbackSent = 2;
+                    pending.push_back(dev);
+                }
+            }
+
+            for (const auto& dev : pending) {
+                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());
 
             if (pScan->m_maxResults == 0) {
                 pScan->clearResults();
@@ -178,6 +362,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, default: max advertising interval (10.24s)
+ * @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 +526,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 +599,8 @@ bool NimBLEScan::stop() {
         return false;
     }
 
+    clearWaitingList();
+
     if (m_maxResults == 0) {
         clearResults();
     }
@@ -414,6 +621,7 @@ void NimBLEScan::erase(const NimBLEAddress& address) {
     NIMBLE_LOGD(LOG_TAG, "erase device: %s", address.toString().c_str());
     for (auto it = m_scanResults.m_deviceVec.begin(); it != m_scanResults.m_deviceVec.end(); ++it) {
         if ((*it)->getAddress() == address) {
+            removeWaitingDevice(*it);
             delete *it;
             m_scanResults.m_deviceVec.erase(it);
             break;
@@ -429,6 +637,7 @@ void NimBLEScan::erase(const NimBLEAdvertisedDevice* device) {
     NIMBLE_LOGD(LOG_TAG, "erase device: %s", device->getAddress().toString().c_str());
     for (auto it = m_scanResults.m_deviceVec.begin(); it != m_scanResults.m_deviceVec.end(); ++it) {
         if ((*it) == device) {
+            removeWaitingDevice(*it);
             delete *it;
             m_scanResults.m_deviceVec.erase(it);
             break;
@@ -483,6 +692,12 @@ NimBLEScanResults NimBLEScan::getResults() {
  * @brief Clear the stored results of the scan.
  */
 void NimBLEScan::clearResults() {
+    if (isScanning()) {
+        NIMBLE_LOGW(LOG_TAG, "Cannot clear results while scan is active");
+        return;
+    }
+
+    clearWaitingList();
     if (m_scanResults.m_deviceVec.size()) {
         std::vector<NimBLEAdvertisedDevice*> vSwap{};
         ble_npl_hw_enter_critical();