NimBLE-Arduino: Non-blocking NimBLEScan stops calling callback after random number of scans

I’m struggling to put into words what I’m seeing, but here’s my best attempt. I’m writing a simply BLE scanner that uses callbacks, based on the example code. I’ve made it as simple as possible, but it’s not acting the way I’d expect.

The code:

#include "NimBLEDevice.h"

NimBLEScan* pBLEScan;
long lastUpdate;
const int scanTime = 3;

class MyAdvertisedDeviceCallbacks: public NimBLEAdvertisedDeviceCallbacks {
    void onResult(NimBLEAdvertisedDevice* advertisedDevice) {
      Serial.printf("Advertised Device: %s \n", advertisedDevice->toString().c_str());
    }
};

void setup() {
  Serial.begin(115200);
  BLEDevice::init("");
  pBLEScan = BLEDevice::getScan(); //create new scan
  pBLEScan->setAdvertisedDeviceCallbacks(new MyAdvertisedDeviceCallbacks());
  pBLEScan->setActiveScan(true); //active scan uses more power, but get results faster
  pBLEScan->setInterval(97);
  pBLEScan->setWindow(37); // less or equal setInterval value
  pBLEScan->setMaxResults(0);
}

void loop() {
  long now = millis();
  if ( now >= lastUpdate + 1000 ) {
    Serial.printf("Tick: %ld\n", now / 1000 );
    lastUpdate = now;
  }
  BLEScanResults foundDevices = pBLEScan->start(scanTime, false);
  pBLEScan->clearResults(); // delete results fromBLEScan buffer to release memory
}

What I want to see is “Advertised Device: XXX” information printed periodically, as devices are discovered. I’d also like to see the word “Tick” posted every second, indicating that the scan is non-blocking and happening “in the background” while my main loop() continues to work. In this case, it seems that the pBLEScan->start() is blocking, and since my scanTime is 3 seconds, I see “Tick 3” … “Tick 6” … “Tick 9”… and then… nothing. The output looks like this:

15:26:53.409 -> ets Jun 8 2016 00:22:57 15:26:53.409 -> 15:26:53.409 -> rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) 15:26:53.409 -> configsip: 0, SPIWP:0xee 15:26:53.409 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 15:26:53.409 -> mode:DIO, clock div:1 15:26:53.409 -> load:0x3fff0030,len:1420 15:26:53.409 -> ho 0 tail 12 room 4 15:26:53.409 -> load:0x40078000,len:13540 15:26:53.409 -> load:0x40080400,len:3604 15:26:53.409 -> entry 0x400805f0 15:26:54.044 -> Advertised Device: Name: 846B215F5FC233AEE9, Address: f3:33:c0:55:58:95, appearance: 0, manufacturer data: a705051001000000000000001b00ca, serviceUUID: 0xfe07, txPower: 0 15:26:54.508 -> Advertised Device: Name: , Address: 75:6d:2b:0e:f5:29, manufacturer data: 4c001006191e23cfe2c1, txPower: 8 15:26:55.115 -> Advertised Device: Name: , Address: 76:90:c3:e9:90:02, manufacturer data: e00001b9ca72c54c, serviceUUID: 0xfe9f 15:26:55.115 -> Service Data: 15:26:55.115 -> UUID: 0xfe9f, Data: nTF065F6mZs 15:26:55.115 -> Advertised Device: Name: , Address: 43:16:54:3d:42:ed, manufacturer data: 4c001005491c18dbfe 15:26:55.221 -> Advertised Device: Name: , Address: d7:96:ba:2b:33:e2, manufacturer data: 4c0012020000 15:26:56.187 -> Advertised Device: Name: , Address: 5d:0c:66:6f:61:2e, manufacturer data: 4c00021561b5c6c7bc4249c982cc3fc6832f69ae00640001a6 15:26:56.664 -> Advertised Device: Name: , Address: 5a:35:34:88:dc:8a, serviceUUID: 0xfd6f 15:26:56.664 -> Service Data: 15:26:56.664 -> UUID: 0xfd6f, Data: ⸮<⸮ 15:26:56.912 -> Advertised Device: Name: , Address: 4b:21:d4:48:87:b6, serviceUUID: 0xfe9f 15:26:56.912 -> Service Data: 15:26:56.912 -> UUID: 0xfe9f, Data:
> 15:26:56.912 -> Tick: 3 15:26:56.950 -> Advertised Device: Name: , Address: 43:16:54:3d:42:ed, manufacturer data: 4c001005491c18dbfe 15:26:56.950 -> Advertised Device: Name: , Address: 5a:35:34:88:dc:8a, serviceUUID: 0xfd6f 15:26:56.950 -> Service Data: 15:26:56.950 -> UUID: 0xfd6f, Data: ⸮<⸮ 15:26:58.214 -> Advertised Device: Name: , Address: 76:90:c3:e9:90:02, manufacturer data: e00001b9ca72c54c, serviceUUID: 0xfe9f 15:26:58.214 -> Service Data: 15:26:58.214 -> UUID: 0xfe9f, Data: nTF065F6mZs 15:26:59.290 -> Advertised Device: Name: , Address: 5d:0c:66:6f:61:2e, manufacturer data: 4c00021561b5c6c7bc4249c982cc3fc6832f69ae00640001a6 15:26:59.928 -> Advertised Device: Name: , Address: 75:6d:2b:0e:f5:29, manufacturer data: 4c001006191e23cfe2c1, txPower: 8 15:26:59.928 -> Advertised Device: Name: , Address: f3:33:c0:55:58:95, appearance: 0, manufacturer data: a705051001000000000000001b00ca, serviceUUID: 0xfe07, txPower: 0 > 15:26:59.964 -> Tick: 6 15:27:00.073 -> Advertised Device: Name: , Address: 43:16:54:3d:42:ed, manufacturer data: 4c001005491c18dbfe 15:27:00.682 -> Advertised Device: Name: , Address: 5a:35:34:88:dc:8a, serviceUUID: 0xfd6f 15:27:00.682 -> Service Data: 15:27:00.682 -> UUID: 0xfd6f, Data: ⸮<⸮ 15:27:01.043 -> Advertised Device: Name: , Address: 76:90:c3:e9:90:02, manufacturer data: e00001b9ca72c54c, serviceUUID: 0xfe9f 15:27:01.077 -> Service Data: 15:27:01.077 -> UUID: 0xfe9f, Data: nTF065F6mZs 15:27:01.328 -> Advertised Device: Name: , Address: 5d:0c:66:6f:61:2e, manufacturer data: 4c00021561b5c6c7bc4249c982cc3fc6832f69ae00640001a6 15:27:02.952 -> Advertised Device: Name: , Address: f3:33:c0:55:58:95, appearance: 0, manufacturer data: a705051001000000000000001b00ca, serviceUUID: 0xfe07, txPower: 0 15:27:02.952 -> Advertised Device: Name: , Address: 75:6d:2b:0e:f5:29, manufacturer data: 4c001006191e23cfe2c1, txPower: 8 > 15:27:02.988 -> Tick: 9 15:27:02.988 -> Advertised Device: Name: , Address: 43:16:54:3d:42:ed, manufacturer data: 4c001005491c18dbfe 15:27:03.388 -> Advertised Device: Name: , Address: 5d:0c:66:6f:61:2e, manufacturer data: 4c00021561b5c6c7bc4249c982cc3fc6832f69ae00640001a6 15:27:04.965 -> Advertised Device: Name: , Address: 5a:35:34:88:dc:8a, serviceUUID: 0xfd6f 15:27:04.965 -> Service Data: 15:27:04.965 -> UUID: 0xfd6f, Data: ⸮<⸮ 15:27:05.430 -> Advertised Device: Name: , Address: 76:90:c3:e9:90:02, manufacturer data: e00001b9ca72c54c, serviceUUID: 0xfe9f 15:27:05.430 -> Service Data: 15:27:05.430 -> UUID: 0xfe9f, Data: nTF065F6mZs 15:27:05.430 -> Advertised Device: Name: 846B215F5FC233AEE9, Address: f3:33:c0:55:58:95, appearance: 0, manufacturer data: a705051001000000000000001b00ca, serviceUUID: 0xfe07, txPower: 0 15:27:09.114 -> Advertised Device: Name: , Address: 75:6d:2b:0e:f5:29, manufacturer data: 4c001006191e23cfe2c1, txPower: 8 15:27:17.923 -> Advertised Device: Name: , Address: 7e:d5:fc:b0:9c:b5, manufacturer data: 4c00021561b5c6c7bc4249c982cc3fc6832f69ae00640001a6 15:27:35.274 -> Advertised Device: Name: , Address: d7:96:ba:2b:33:e2, manufacturer data: 4c0012020000 15:27:38.533 -> Advertised Device: Name: PROV_005d13Z, Address: 24:62🆎e2:16:ee, serviceUUID: 0000ffff-0000-1000-8000-00805f9b34fb 15:27:49.808 -> Advertised Device: Name: , Address: 86:2a:fd:a8:50:c6, manufacturer data: 650001c905, serviceUUID: 0xfe78 15:27:49.808 -> Service Data: 15:27:49.808 -> UUID: 0xfdf7, Data: ⸮X⸮⸮⸮⸮V⸮⸮ziEfs5 15:27:54.071 -> Advertised Device: Name: , Address: 43:16:54:3d:42:ed, manufacturer data: 4c001005491c18dbfe 15:27:54.360 -> Advertised Device: Name: , Address: 76:90:c3:e9:90:02, manufacturer data: e00001b9ca72c54c, serviceUUID: 0xfe9f 15:27:54.360 -> Service Data: 15:27:54.360 -> UUID: 0xfe9f, Data: nTF065F6mZs 15:27:55.217 -> Advertised Device: Name: , Address: 7e:d5:fc:b0:9c:b5, manufacturer data: 4c00021561b5c6c7bc4249c982cc3fc6832f69ae00640001a6 15:27:57.163 -> Advertised Device: Name: PROV_005d13Z, Address: 24:62🆎e2:16:ee, serviceUUID: 0000ffff-0000-1000-8000-00805f9b34fb 15:28:00.645 -> Advertised Device: Name: 846B215F5FC233AEE9, Address: f3:33:c0:55:58:95, appearance: 0, manufacturer data: a705051001000000000000001b00ca, serviceUUID: 0xfe07, txPower: 0 15:28:06.468 -> Advertised Device: Name: , Address: 75:6d:2b:0e:f5:29, manufacturer data: 4c001006191e23cfe2c1, txPower: 8 15:28:09.374 -> Advertised Device: Name: , Address: d7:96:ba:2b:33:e2, manufacturer data: 4c0012020000 15:28:09.661 -> Advertised Device: Name: , Address: 4b:21:d4:48:87:b6, manufacturer data: e00001f2ca849dc4, serviceUUID: 0xfe9f 15:28:09.661 -> Service Data: 15:28:09.661 -> UUID: 0xfe9f, Data:

Reading through that, you see I get a “tick” at 15:26:56.912, at 15:26:59.964, 15:27:02.988, and … never again for the next 60+ seconds. The scan appears to continue to run, but my main loop() just… disappears. Questions:

where is executing disappearing to, that my simple little loop() stops looping?
am I unrealistic in thinking there’s a way to scan and continue to process at the same time. Even with the callback, the scan appears to block execution of the main loop

BTW, I don’t think this is a “bug” or “issue”, but I couldn’t find a more appropriate forum to ask this question. If there is one, let me know and I’ll move there. Thanks!

John

About this issue

Original URL
State: closed
Created 3 years ago
Comments: 37 (17 by maintainers)

Most upvoted comments

Looks like the true fix is available upstream here: https://github.com/FreeRTOS/FreeRTOS-Kernel/blob/052e364686b1cf7082b8979fecf211121402bf74/timers.c#L823

You can see the difference in the blocks: https://github.com/espressif/esp-idf/blob/451ce8a7ed486c6c6045189db57106ca7107abdb/components/freertos/FreeRTOS-Kernel/timers.c#L848

I tested and confirmed this in IDF, so I guess the workaround will be needed to compensate for bugged releases. I’m going to try to use esp_timer instead for the master branch fix, 1.3.3 will use the workaround proposed in the PR.

h2zero on Nov 22, 2021

Thanks for testing, I hope it does not affect any other parts of the stack.

FWIW I believe I have found the offending code in FreeRTOS here: https://github.com/espressif/esp-idf/blob/451ce8a7ed486c6c6045189db57106ca7107abdb/components/freertos/FreeRTOS-Kernel/timers.c#L952

That calls the timer callback before clearing it as active, I’ll do some tests with IDF and see, might need to make a PR there.

h2zero on Nov 21, 2021

https://github.com/h2zero/NimBLE-Arduino/blob/master/src/NimBLEScan.h#L65

chegewara on Oct 29, 2021

Looks like the true fix is available upstream here: https://github.com/FreeRTOS/FreeRTOS-Kernel/blob/052e364686b1cf7082b8979fecf211121402bf74/timers.c#L823

You can see the difference in the blocks: https://github.com/espressif/esp-idf/blob/451ce8a7ed486c6c6045189db57106ca7107abdb/components/freertos/FreeRTOS-Kernel/timers.c#L848

I tested and confirmed this in IDF, so I guess the workaround will be needed to compensate for bugged releases. I’m going to try to use esp_timer instead for the master branch fix, 1.3.3 will use the workaround proposed in the PR.

Thank you so much for running this down. I apologize I got scarce at the end: my partner had a hip replacement and I’ve been focused on her. I’ll pull these changes into my code and look for improvements.

ab0oo on Nov 22, 2021

@h2zero I’m using arduino esp-32 arduino 2.0.1 using vscode inside visual studio 2019. As per my testing, the RTOS function xTimerIsTimerActive returns active even if the timer has expired. So, to be sure that it is still active, the value coming from xTimerGetExpiryTime must be checked against the current ticks xTaskGetTickCountFromISR

Basically the patch I did is the following `static void ble_hs_timer_sched(int32_t ticks_from_now) { ble_npl_time_t abs_time;

if (ticks_from_now == BLE_HS_FOREVER) {
    return;
}

/* Reset timer if it is not currently scheduled or if the specified time is
 * sooner than the previous expiration time.
 */
uint32_t tt = ble_npl_time_get(); // gets current ticks
// takes into account that the timer can be overflowed compared to the current ticks
bool is_active = (ble_npl_callout_get_ticks(&ble_hs_timer) > tt) && ble_npl_callout_is_active(&ble_hs_timer);

abs_time = ble_npl_time_get() + ticks_from_now;
if (!is_active ||
        ((ble_npl_stime_t)(abs_time -
                           ble_npl_callout_get_ticks(&ble_hs_timer))) < 0) {
    ble_hs_timer_reset(ticks_from_now);
}

} `

cicciocb on Nov 22, 2021

A little more testing with platformio config:

This works fine:

[env:esp32dev]
platform = espressif32
board = esp32dev
framework = arduino
platform_packages = platformio/framework-arduinoespressif32 @ https://github.com/espressif/arduino-esp32.git
monitor_speed = 115200

This fails to trigger the scan stop timer:

[env:esp32dev]
platform = https://github.com/platformio/platform-espressif32.git#feature/arduino-upstream
board = esp32dev
framework = arduino
platform_packages = platformio/framework-arduinoespressif32 @ https://github.com/espressif/arduino-esp32.git#2.0.1
monitor_speed = 115200

Also using 2.0.1 of arduino-esp32 core in Arduino IDE works perfectly with the code @ab0oo shared above. I don’t know platformio well enough to speculate but I suspect there is a toolchain issue somewhere.

h2zero on Nov 21, 2021