search

h2zero / esp-nimble-cpp

C++ library for the esp32 NimBLE stack based on and mostly compatible with @nkolban cpp_utils BLE library.
https://h2zero.github.io/esp-nimble-cpp/
Apache License 2.0
183 stars 62 forks source link

duplicates repeated after 60s #84

Closed wjcarpenter closed 1 week ago

wjcarpenter commented 2 years ago

I find that if I scan for advertised devices requesting no duplicates my callback sees duplicates repeated at almost exactly 60 second intervals. I wonder if I'm doing something wrong or if there is some config I don't know about for this mystery. Or maybe there is just something I'm misunderstanding about how duplicate suppression is intended to work.

I (2223) NimBLE: GAP procedure initiated: discovery; 
I (2223) NimBLE: own_addr_type=0 filter_policy=0 passive=0 limited=0 filter_duplicates=1 
I (2223) NimBLE: duration=150000ms
I (2233) NimBLE: 

I (2253) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' mfg ''
I (2263) bleXmang: BT peripheral '52:ae:50:1d:6f:2b' is '' mfg '�'
I (2323) bleXmang: BT peripheral '05:01:f1:06:79:4d' is '' mfg ''
I (2393) bleXmang: BT peripheral '7f:02:af:b6:18:57' is '' mfg ''
I (3223) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' mfg ''
I (62253) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' mfg ''
I (62293) bleXmang: BT peripheral '05:01:f1:06:79:4d' is '' mfg ''
I (62513) bleXmang: BT peripheral '6b:3d:8d:59:61:9d' is '' mfg ''
I (62533) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' mfg ''
I (62953) bleXmang: BT peripheral '52:ae:50:1d:6f:2b' is '' mfg '�'
I (87523) bleXmang: BT peripheral '38:16:7a:3c:12:d2' is '' mfg ''
I (122243) bleXmang: BT peripheral '59:c8:7f:ad:73:c4' is '' mfg ''
I (122263) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' mfg ''
I (122293) bleXmang: BT peripheral '38:16:7a:3c:12:d2' is '' mfg ''
I (122443) bleXmang: BT peripheral '52:ae:50:1d:6f:2b' is '' mfg '�'
I (122833) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' mfg ''

My code is pretty simple (it will eventually scan forever and be stopped by a user action or a timeout outside of the BLE code).

extern "C" {
class MyCallbacks: public NimBLEAdvertisedDeviceCallbacks
{
    void onResult(NimBLEAdvertisedDevice *device)
    {
        ESP_LOGI(TAG, "BT peripheral '%s' is '%s' mfg '%s'", device->getAddress().toString().c_str(), device->getName().c_str(), device->getManufacturerData().c_str());
    }
};

static NimBLEScan *pScan;

bool start_ble_scanning()
{
    pScan = NimBLEDevice::getScan();
    pScan->setAdvertisedDeviceCallbacks(new MyCallbacks(), false);
    pScan->setActiveScan(true);
    bool ret = pScan->start(150, nullptr, true);
    return ret;
}

void stop_ble_scanning()
{
    pScan->stop();
}
h2zero commented 2 years ago

There is a buffer in the controller that once filled will clear itself and duplicate devices will be reported again.

You can adjust the size of the buffer by calling NimbleDevice:: setScanDuplicateCacheSize before calling init, it takes a value range of 20-1000.

wjcarpenter commented 2 years ago

I think something is not working here, but it might be something down inside ESP-IDF.

First of all, the default value for the duplicates cache is 200, which is way more than I am seeing. Second, even changing it to 1000, both in the config and in the esp-nimble-cpp API, does not eliminate the duplicates. I initialize this way:

NimBLEDevice::setScanDuplicateCacheSize(1000);
NimBLEDevice::setScanFilterMode(CONFIG_BTDM_SCAN_DUPL_TYPE_DEVICE);
NimBLEDevice::init("example");

I wonder if maybe this is a bug in ESP-IDF that worked with Bluedroid but doesn't work with NimBLE. The code for this in esp-nimble-cpp looks correct to my eyeballs (for passing the right thing down into ESP calls).

Incidentally, when I use passive scanning instead of active scanning, I see tons and tons of duplicates in my callback.

h2zero commented 2 years ago

What IDF/NimBLE version are you using? Do you have a lot of BLE advertisers around you?

wjcarpenter commented 2 years ago

I am using ESP-IDF 4.4.1. I have 10-20 BLE advertisers typically visible if I scan for a while.

I think I have figured out what's going on, but I'm not sure if it's a bug or just something I didn't understand correctly. I modified my code to print the current result count in the callback, and I also print the results list when I stop the scan. These things happen:

  1. Some things show up in the result list that are never seen by the callback.
  2. Correspondingly, there are gaps in the numbering of the current result count.
  3. The callback does see duplicate addresses.
  4. The result list does not have any duplicates.

Here's the current code:

extern "C" {
static NimBLEScan *pScan;

class MyCallbacks: public NimBLEAdvertisedDeviceCallbacks
{
    void onResult(NimBLEAdvertisedDevice *device)
    {
        ESP_LOGI(TAG, "BT peripheral '%s' is '%s' count %d", device->getAddress().toString().c_str(), device->getName().c_str(), pScan->getResults().getCount());
    }
};

bool start_ble_scanning()
{
    ESP_LOGI(TAG, "START Scanning... heap free: %d", xPortGetFreeHeapSize());
    pScan = NimBLEDevice::getScan();
    pScan->setAdvertisedDeviceCallbacks(new MyCallbacks(), false);
    pScan->setActiveScan(true);
    bool ret = pScan->start(0, nullptr, true);
//    bool ret = true;
//    NimBLEScanResults res = pScan->start(150, false);
//    res.dump();

    return ret;
}

void stop_ble_scanning()
{
    if (pScan->isScanning()) {
    NimBLEScanResults results = pScan->getResults();
    for (int ii=0; ii<results.getCount(); ++ii) {
        NimBLEAdvertisedDevice device = results.getDevice(ii);
        ESP_LOGI(TAG, "%d:  BT device '%s' at '%s'", ii, device.getName().c_str(), device.getAddress().toString().c_str());
    }

        pScan->stop();
        ESP_LOGI(TAG, "STOP  Scanning!");
    }
}

void init_blues()
{
    NimBLEDevice::setScanDuplicateCacheSize(1000);
    NimBLEDevice::setScanFilterMode(CONFIG_BTDM_SCAN_DUPL_TYPE_DEVICE);
    NimBLEDevice::init("bleXmang");
}

}

And here is the output from a run of that code:

I (20254) bleXmang: Managing device type P slot 0, name NO NAME
I (20254) bleXmang: START Scanning... heap free: 192068
I (20254) NimBLE: GAP procedure initiated: discovery; 
I (20254) NimBLE: own_addr_type=0 filter_policy=0 passive=0 limited=0 filter_duplicates=1 
I (20264) NimBLE: duration=forever
I (20264) NimBLE: 

I (20284) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' count 1
I (20364) bleXmang: BT peripheral '7e:d0:30:d8:cc:bb' is '' count 3
I (20554) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' count 5
I (20594) bleXmang: BT peripheral '5a:29:d4:62:7b:2e' is '' count 6
I (20914) bleXmang: BT peripheral '8c:de:52:cb:22:21' is 'BEDJET' count 7
I (20964) bleXmang: BT peripheral 'f7:76:b4:c2:d3:cb' is 'Amazfit Bip Watch' count 8
I (22184) bleXmang: BT peripheral '42:6a:3e:e1:3a:b6' is '' count 9
I (80284) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' count 12
I (80294) bleXmang: BT peripheral '7e:d0:30:d8:cc:bb' is '' count 12
I (80634) bleXmang: BT peripheral '5a:29:d4:62:7b:2e' is '' count 12
I (80854) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' count 12
I (81024) bleXmang: BT peripheral 'c5:7a:e6:4f:9d:22' is 'Amazfit Bip Watch' count 12
I (81814) bleXmang: BT peripheral '42:6a:3e:e1:3a:b6' is '' count 12
I (87964) bleXmang: BT peripheral '8c:de:52:cb:22:21' is 'BEDJET' count 12
I (140284) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' count 13
I (140334) bleXmang: BT peripheral '5a:29:d4:62:7b:2e' is '' count 13
I (140464) bleXmang: BT peripheral '42:6a:3e:e1:3a:b6' is '' count 13
I (140704) bleXmang: BT peripheral '7e:d0:30:d8:cc:bb' is '' count 13
I (141014) bleXmang: BT peripheral 'f7:76:b4:c2:d3:cb' is 'Amazfit Bip Watch' count 13
I (142144) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' count 13
I (143334) bleXmang: BT peripheral '8c:de:52:cb:22:21' is 'BEDJET' count 13
I (148194) bleXmang: BT peripheral 'db:e0:de:76:07:cc' is '' count 14
I (200294) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' count 14
I (200404) bleXmang: BT peripheral '5a:29:d4:62:7b:2e' is '' count 14
I (200424) bleXmang: BT peripheral '79:79:c0:78:ba:fb' is '' count 15
I (200434) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' count 15
I (200564) bleXmang: BT peripheral '42:6a:3e:e1:3a:b6' is '' count 15
I (201934) bleXmang: BT peripheral 'c5:7a:e6:4f:9d:22' is 'Amazfit Bip Watch' count 15
I (203434) bleXmang: BT peripheral '8c:de:52:cb:22:21' is 'BEDJET' count 15
I (204244) bleXmang: BT peripheral 'db:e0:de:76:07:cc' is '' count 15
I (260274) bleXmang: BT peripheral 'b0:38:29:9e:d2:f6' is 'HB-00020668' count 15
I (260344) bleXmang: BT peripheral '5a:29:d4:62:7b:2e' is '' count 15
I (260424) bleXmang: BT peripheral '7e:d0:30:d8:cc:bb' is '' count 15
I (260474) bleXmang: BT peripheral '42:6a:3e:e1:3a:b6' is '' count 15
I (260724) bleXmang: BT peripheral '3f:59:c8:61:1c:e8' is 'LYWSD02' count 15
I (261034) bleXmang: BT peripheral 'c5:7a:e6:4f:9d:22' is 'Amazfit Bip Watch' count 15
I (264464) bleXmang: BT peripheral '8c:de:52:cb:22:21' is 'BEDJET' count 15

I (301154) bleXmang: 0:  BT device 'HB-00020668' at 'b0:38:29:9e:d2:f6'
I (301154) bleXmang: 1:  BT device 'YamahaAV' at 'c8:84:47:5a:21:70'
I (301154) bleXmang: 2:  BT device '' at '7e:d0:30:d8:cc:bb'
I (301164) bleXmang: 3:  BT device '' at '42:6a:3e:e1:3a:b6'
I (301164) bleXmang: 4:  BT device '' at '3f:59:c8:61:1c:e8'
I (301174) bleXmang: 5:  BT device '' at '5a:29:d4:62:7b:2e'
I (301174) bleXmang: 6:  BT device 'BEDJET' at '8c:de:52:cb:22:21'
I (301184) bleXmang: 7:  BT device '' at 'f7:76:b4:c2:d3:cb'
I (301184) bleXmang: 8:  BT device 'Amazfit Bip Watch' at 'c5:7a:e6:4f:9d:22'
I (301194) bleXmang: 9:  BT device '' at '22:22:31:0d:7e:4d'
I (301204) bleXmang: 10:  BT device 'LE_WH-1000XM3' at 'cc:98:8b:63:f6:ae'
I (301204) bleXmang: 11:  BT device '' at 'c3:f0:cd:27:43:b2'
I (301214) bleXmang: 12:  BT device '' at '4e:07:91:e4:e3:1c'
I (301214) bleXmang: 13:  BT device '' at 'db:e0:de:76:07:cc'
I (301224) bleXmang: 14:  BT device '' at '79:79:c0:78:ba:fb'
I (301234) bleXmang: STOP  Scanning!

4e:07:91:e4:e3:1c is an example of something that shows up in the results list but not in the callback output.

wjcarpenter commented 2 years ago

BTW, I am using v1.3.3 of esp-nimble-cpp

h2zero commented 2 years ago

Thank you for the info. I can reproduce and explain this. Here is my log:

I (1942) NimBLEScan: New advertiser: 2f:61:6c:63:f7:29
I (1942) MAIN: BT peripheral '2f:61:6c:63:f7:29' is '' count 1
I (2242) NimBLEScan: New advertiser: e8:42:2d:ab:ed:9e
I (2242) MAIN: BT peripheral 'e8:42:2d:ab:ed:9e' is '' count 2
I (3042) NimBLEScan: New advertiser: 61:02:63:c5:82:f3
I (3042) NimBLEScan: Updated advertiser: 61:02:63:c5:82:f3
I (3042) MAIN: BT peripheral '61:02:63:c5:82:f3' is '' count 3
I (5152) NimBLEScan: New advertiser: ee:63:2e:40:dc:09
I (5152) MAIN: BT peripheral 'ee:63:2e:40:dc:09' is '' count 4
I (9142) NimBLEScan: New advertiser: 2c:41:a1:71:5c:c3
I (9142) NimBLEScan: New advertiser: b0:ce:18:49:9f:75
I (9142) MAIN: BT peripheral 'b0:ce:18:49:9f:75' is '' count 6
I (14422) NimBLEScan: New advertiser: d0:4f:7e:2b:d7:6e
I (15352) NimBLEScan: New advertiser: cc:b8:6c:d6:a8:82
I (15392) NimBLEScan: Updated advertiser: cc:b8:6c:d6:a8:82
I (15392) MAIN: BT peripheral 'cc:b8:6c:d6:a8:82' is 'Temp/Hmid/Pres' count 8
I (21192) NimBLEScan: Updated advertiser: d0:4f:7e:2b:d7:6e
I (21202) MAIN: BT peripheral 'd0:4f:7e:2b:d7:6e' is '' count 8
I (60952) NimBLEScan: Updated advertiser: 61:02:63:c5:82:f3
I (61042) NimBLEScan: Updated advertiser: ee:63:2e:40:dc:09
I (61042) MAIN: BT peripheral 'ee:63:2e:40:dc:09' is '' count 8
I (61752) NimBLEScan: Updated advertiser: 61:02:63:c5:82:f3
I (61752) MAIN: BT peripheral '61:02:63:c5:82:f3' is '' count 8
I (62032) NimBLEScan: Updated advertiser: 2f:61:6c:63:f7:29
I (62032) MAIN: BT peripheral '2f:61:6c:63:f7:29' is '' count 8
I (62292) NimBLEScan: Updated advertiser: e8:42:2d:ab:ed:9e
I (62292) MAIN: BT peripheral 'e8:42:2d:ab:ed:9e' is '' count 8
I (66382) NimBLEScan: Updated advertiser: 2c:41:a1:71:5c:c3
I (67912) NimBLEScan: Updated advertiser: d0:4f:7e:2b:d7:6e
I (67912) NimBLEScan: Updated advertiser: d0:4f:7e:2b:d7:6e
I (67912) MAIN: BT peripheral 'd0:4f:7e:2b:d7:6e' is '' count 8
I (69802) NimBLEScan: Updated advertiser: b0:ce:18:49:9f:75
I (69802) MAIN: BT peripheral 'b0:ce:18:49:9f:75' is '' count 8
I (78352) NimBLEScan: Updated advertiser: cc:b8:6c:d6:a8:82
I (78402) NimBLEScan: Updated advertiser: cc:b8:6c:d6:a8:82
I (78402) MAIN: BT peripheral 'cc:b8:6c:d6:a8:82' is 'Temp/Hmid/Pres' count 8
I (96842) NimBLEScan: New advertiser: 57:5b:a7:da:ad:ab
I (121402) NimBLEScan: Updated advertiser: 57:5b:a7:da:ad:ab
I (121702) NimBLEScan: Updated advertiser: ee:63:2e:40:dc:09
I (121702) MAIN: BT peripheral 'ee:63:2e:40:dc:09' is '' count 9
I (122122) NimBLEScan: Updated advertiser: 2f:61:6c:63:f7:29
I (122122) MAIN: BT peripheral '2f:61:6c:63:f7:29' is '' count 9
I (122362) NimBLEScan: Updated advertiser: e8:42:2d:ab:ed:9e
I (122362) MAIN: BT peripheral 'e8:42:2d:ab:ed:9e' is '' count 9
I (122762) NimBLEScan: Updated advertiser: 57:5b:a7:da:ad:ab
I (122762) MAIN: BT peripheral '57:5b:a7:da:ad:ab' is '' count 9
I (130352) NimBLEScan: Updated advertiser: b0:ce:18:49:9f:75
I (130352) MAIN: BT peripheral 'b0:ce:18:49:9f:75' is '' count 9
I (138362) NimBLEScan: Updated advertiser: cc:b8:6c:d6:a8:82
I (138362) NimBLEScan: Updated advertiser: cc:b8:6c:d6:a8:82
I (138362) MAIN: BT peripheral 'cc:b8:6c:d6:a8:82' is 'Temp/Hmid/Pres' count 9
I (139372) NimBLEScan: Updated advertiser: d0:4f:7e:2b:d7:6e
I (151702) NimBLEScan: Updated advertiser: 2c:41:a1:71:5c:c3

In here you can see the gaps are due to awaiting scan response data. The device when first detected is added to the vector and either calls the callback or waits for the scan response data before calling it, which can be seen here. The duplicates you are seeing and as I see them in the log are due to the scan response data being updated. So it would seem there may be room for improvement on the filtering side, what you could try for the time being is changing the scan filter mode to CONFIG_BTDM_SCAN_DUPL_TYPE_DATA_DEVICE.

I will look to improve this shortly.

h2zero commented 2 years ago

I made a quick patch for v1.3.3 for you to try: scan_patch.txt

wjcarpenter commented 2 years ago

Thanks for the quick turnaround. With the patch, the duplicates in the callback are gone. With active scanning, there are still some devices that don't show up in the callback, but with passive scanning they all show up. That resolves things for my use case, so I'll leave it to you whether you want to pursue the active scan case.

(FWIW, in my scenario I'll be updating a UI with scanned devices as they are found. That's in a different FreeRTOS task, so I'm probably going to just check for a change in the results count every few seconds and act on that.)

Thanks again (and thanks for your work in porting this library in the first place).

h2zero commented 2 years ago

Re; active scan, The devices don't show due to not receiving the scan response. This is an issue that I've been struggling with for a while as to how it should be resolved. If the scan is short and restarted often this is a non-issue mostly, however, it's not ideal.

wjcarpenter commented 2 years ago

Yeah, I don't even know what most of the devices are that I'm picking up in my scans. I checked the MACs and they are either unregistered or have confidential vendors in the IEEE database. Some of them could be quite old or could be sketchy manufacturers who don't follow the protocols reliably.

I guess there is no way to tell from the initial advertising packet if the device would respond to the request for additional scan data. If there were, and the indication was "no", you could skip them for the active scan follow-up.

h2zero commented 2 years ago

I guess there is no way to tell from the initial advertising packet if the device would respond to the request for additional scan data. If there were, and the indication was "no", you could skip them for the active scan follow-up.

Actually, this is already being done, it's just a matter of the device responding to the request. After advertising it will go into receive mode to listen for scan requests but if the timing is off or it goes out of range etc. then the response won't come until the next time we request from it (assuming it works that time).

What I have in place now is, when the scan ends the callback for any device that it hasn't been called for yet will be called at that time. It's not ideal but you'll at least get it eventually.

wjcarpenter commented 2 years ago

Even with the patch, I'm not getting those "eventual" callbacks. Should that be working with a "scan forever" call that is stopped by a stop() call instead of the timeout?

h2zero commented 2 years ago

Should that be working with a "scan forever" call that is stopped by a stop() call instead of the timeout?

Unfortunately no, manually stopping does not call the callbacks as it would cause problems for the client connect function.

h2zero commented 2 years ago

I'm all ears for potential solutions to this problem. So far the options considered have been to use a timeout on waiting for the scan response, this is not ideal though because the response could come at any moment so coming up with an appropriate time would be a challenge. The second option is to provide a callback for the initial advertisement and again when the scan response is received, this may result in breaking the API.

wjcarpenter commented 2 years ago

I'm not any kind of BT expert, so I don't have any great ideas. I was only using active scanning in the hope of getting something human-consumable for the devices that don't provide names in the initial packet. But so far I haven't seen them provide names in those cases. (Funny story, though. The remote for a TiVo Stream 4k gives its name as "TiVo Remot" in the initial packet but completes it to "TiVo Remote" in the additional scan data. So, I guess that's something. :-).)

h2zero commented 2 years ago

Lol, yeah there isn't much advertising data space so most devices don't advertise a name or if they do it's a short version.