Set default timeout to default window time and add debug stats

h2zero · h2zero · commit ca46c60beebf · 2026-03-22T08:49:50.000-06:00
diff --git a/src/NimBLEAdvertisedDevice.cpp b/src/NimBLEAdvertisedDevice.cpp
@@ -58,19 +58,19 @@ NimBLEAdvertisedDevice::NimBLEAdvertisedDevice(const ble_gap_event* event, uint8
  * @brief Update the advertisement data.
  * @param [in] event The advertisement event data.
  */
-void NimBLEAdvertisedDevice::update(const ble_gap_event* event, uint8_t eventType) {
+bool NimBLEAdvertisedDevice::update(const ble_gap_event* event, uint8_t eventType) {
 # if MYNEWT_VAL(BLE_EXT_ADV)
     const auto& disc = event->ext_disc;
     if (!disc.length_data) { // dummy sr, just return, don't update anything
-        return;
+        return false;
     }
 
     if (m_dataStatus == BLE_GAP_EXT_ADV_DATA_STATUS_INCOMPLETE) {
         m_payload.reserve(m_advLength + disc.length_data);
         m_payload.insert(m_payload.end(), disc.data, disc.data + disc.length_data);
         m_dataStatus = disc.data_status;
         m_advLength  = m_payload.size();
-        return;
+        return true;
     }
 
     m_dataStatus  = disc.data_status;
@@ -80,17 +80,18 @@ void NimBLEAdvertisedDevice::update(const ble_gap_event* event, uint8_t eventTyp
 # endif
 
     if (!disc.length_data) { // dummy sr, just return, don't update anything
-        return;
+        return false;
     }
 
     m_rssi = disc.rssi;
     if (eventType == BLE_HCI_ADV_RPT_EVTYPE_SCAN_RSP && isLegacyAdvertisement()) {
         m_payload.insert(m_payload.end(), disc.data, disc.data + disc.length_data);
-        return;
+        return true;
     }
     m_advLength = disc.length_data;
     m_payload.assign(disc.data, disc.data + disc.length_data);
     m_callbackSent = 0; // new data, reset callback sent flag
+    return true;
 } // update
 
 /**
diff --git a/src/NimBLEAdvertisedDevice.h b/src/NimBLEAdvertisedDevice.h
@@ -154,7 +154,7 @@ class NimBLEAdvertisedDevice {
     friend class NimBLEScan;
 
     NimBLEAdvertisedDevice(const ble_gap_event* event, uint8_t eventType);
-    void    update(const ble_gap_event* event, uint8_t eventType);
+    bool    update(const ble_gap_event* event, uint8_t eventType);
     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;
 
diff --git a/src/NimBLEScan.cpp b/src/NimBLEScan.cpp
@@ -60,8 +60,9 @@ extern "C" void ble_gap_rx_adv_report(ble_gap_disc_desc* desc);
  * provide the 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.
  */
-static void sendDummyScanResponse(ble_npl_event* ev) {
+void NimBLEScan::sendDummyScanResponse(ble_npl_event* ev) {
     (void)ev;
+    NimBLEDevice::getScan()->m_stats.incMissedSrCount();
 # if MYNEWT_VAL(BLE_EXT_ADV)
     ble_gap_rx_ext_adv_report(&dummyDesc);
 # else
@@ -128,7 +129,7 @@ NimBLEScan::NimBLEScan()
       m_maxResults{0xFF} {
     ble_npl_callout_init(&m_srTimer, nimble_port_get_dflt_eventq(), NimBLEScan::srTimerCb, this);
     ble_npl_event_init(&dummySrTimerEvent, sendDummyScanResponse, NULL);
-    ble_npl_time_ms_to_ticks(MYNEWT_VAL(NIMBLE_CPP_SCAN_RSP_TIMEOUT), &m_srTimeoutTicks);
+    ble_npl_time_ms_to_ticks(BLE_GAP_SCAN_FAST_WINDOW, &m_srTimeoutTicks);
 } // NimBLEScan::NimBLEScan
 
 /**
@@ -198,6 +199,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 &&
@@ -206,6 +209,7 @@ 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());
                 }
 
@@ -218,7 +222,14 @@ int NimBLEScan::handleGapEvent(ble_gap_event* event, void* arg) {
                 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.
@@ -269,6 +280,13 @@ 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);
 
             pScan->m_pScanCallbacks->onScanEnd(pScan->m_scanResults, event->disc_complete.reason);
@@ -437,6 +455,8 @@ void NimBLEScan::setPeriod(uint32_t periodMs) {
  * @return True if scan started or false if there was an error.
  */
 bool NimBLEScan::start(uint32_t duration, bool isContinue, bool restart) {
+    m_stats.reset();
+
     NIMBLE_LOGD(LOG_TAG, ">> start: duration=%" PRIu32, duration);
     if (isScanning()) {
         if (restart) {
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;
@@ -83,6 +85,7 @@ class NimBLEScan {
     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 };
@@ -93,11 +96,93 @@ 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);
+
+            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 void srTimerCb(ble_npl_event* event);
+    static void sendDummyScanResponse(ble_npl_event* ev);
 
     NimBLEScanCallbacks* m_pScanCallbacks;
     ble_gap_disc_params  m_scanParams;
diff --git a/src/nimconfig.h b/src/nimconfig.h
@@ -69,14 +69,6 @@
 /** @brief Un-comment to change the stack size for the NimBLE host task */
 // #define MYNEWT_VAL_NIMBLE_HOST_TASK_STACK_SIZE 4096
 
-/**
- * @brief Un-comment to change the default scan response timeout, in milliseconds.
- * @details This is the time to wait for a scan response before calling the onResult scan callback,
- * lower values increase callback rates but will lose data more often, higher values give full data more
- * often. Setting this to 0 will disable the scan response timeout.
- */
- // #define MYNEWT_VAL_NIMBLE_CPP_SCAN_RSP_TIMEOUT (200)
-
 /**
  * @brief Un-comment to change the bit used to block tasks during BLE operations
  * that call NimBLEUtils::taskWait. This should be different than any other
diff --git a/src/syscfg/syscfg.h b/src/syscfg/syscfg.h
@@ -2023,8 +2023,4 @@
 #define MYNEWT_VAL_NIMBLE_CPP_ENABLE_ADVERTISEMENT_TYPE_TEXT (0)
 #endif
 
-#ifndef MYNEWT_VAL_NIMBLE_CPP_SCAN_RSP_TIMEOUT
-#define MYNEWT_VAL_NIMBLE_CPP_SCAN_RSP_TIMEOUT (30)
-#endif
-
 #endif /* H_SYSCFG_ */
