BLE isnt working properly while using Arduino as esp-idf component

[happynet95]

Hi. I'm working with ESP32 esp-idf. I'm trying to use Arduino as esp-idf component.
It works perfect when I run Blink example with make flash :

/// file name : main.cpp ///

#include <Arduino.h>

int LED_BUILTIN = 5;

void setup() {
pinMode(LED_BUILTIN, OUTPUT);
}

void loop() {
digitalWrite(LED_BUILTIN, HIGH);
delay(1000);
digitalWrite(LED_BUILTIN, LOW);
delay(1000);
}

However, It fails to send data BLE_notify example.

https://github.com/espressif/arduino-esp32/blob/master/libraries/BLE/examples/BLE_notify/BLE_notify.ino

when I run it with esp-idf(I mean, when I type make flash and make monitor)
I got this :

Serial port /dev/cu.usbserial-1460
Connecting....
Chip is ESP32D0WDQ6 (revision 1)
Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None
MAC: 3c:71:bf:10:66:20
Uploading stub...
Running stub...
Stub running...
Configuring flash size...
Auto-detected Flash size: 4MB
Compressed 8192 bytes to 31...
Wrote 8192 bytes (31 compressed) at 0x0000e000 in 0.0 seconds (effective 7281.7 kbit/s)...
Hash of data verified.
Compressed 24464 bytes to 14622...
Wrote 24464 bytes (14622 compressed) at 0x00001000 in 1.4 seconds (effective 137.8 kbit/s)...
Hash of data verified.
Compressed 938192 bytes to 500014...
Wrote 938192 bytes (500014 compressed) at 0x00010000 in 48.5 seconds (effective 154.6 kbit/s)...
Hash of data verified.
Compressed 3072 bytes to 128...
Wrote 3072 bytes (128 compressed) at 0x00008000 in 0.0 seconds (effective 1342.0 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
jeonghaemins-iMac-3:blink junghaemin$ make monitor
Toolchain path: /Users/junghaemin/esp/xtensa-esp32-elf/bin/xtensa-esp32-elf-gcc
Toolchain version: crosstool-ng-1.22.0-80-g6c4433a
Compiler version: 5.2.0
Python requirements from /Users/junghaemin/esp/esp-idf/requirements.txt are satisfied.
MONITOR
--- idf_monitor on /dev/cu.usbserial-1460 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
[Ϋɍ��..ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6356
load:0x40078000,len:11308
load:0x40080400,len:6700
entry 0x40080764
I (29) boot: ESP-IDF v4.0-dev-447-g689032650-dirty 2nd stage bootloader
I (29) boot: compile time 15:32:02
I (30) boot: Enabling RNG early entropy source...
I (35) boot: SPI Speed : 40MHz
I (39) boot: SPI Mode : DIO
I (43) boot: SPI Flash Size : 4MB
I (47) boot: Partition Table:
I (51) boot: ## Label Usage Type ST Offset Length
I (58) boot: 0 nvs WiFi data 01 02 00009000 00005000
I (66) boot: 1 otadata OTA data 01 00 0000e000 00002000
I (73) boot: 2 app0 OTA app 00 10 00010000 00140000
I (81) boot: 3 app1 OTA app 00 11 00150000 00140000
I (88) boot: 4 spiffs Unknown data 01 82 00290000 00170000
I (96) boot: End of partition table
I (100) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x36f90 (225168) map
I (188) esp_image: segment 1: paddr=0x00046fb8 vaddr=0x3ffbdb60 size=0x02ca0 ( 11424) load
I (192) esp_image: segment 2: paddr=0x00049c60 vaddr=0x40080000 size=0x00400 ( 1024) load
0x40080000: _WindowOverflow4 at /Users/junghaemin/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (195) esp_image: segment 3: paddr=0x0004a068 vaddr=0x40080400 size=0x05fa8 ( 24488) load
I (214) esp_image: segment 4: paddr=0x00050018 vaddr=0x400d0018 size=0x99510 (627984) map
0x400d0018: _flash_cache_start at ??:?

I (434) esp_image: segment 5: paddr=0x000e9530 vaddr=0x400863a8 size=0x0bb78 ( 47992) load
0x400863a8: _uart_isr at /Users/junghaemin/esp/esp-idf/examples/get-started/blink/components/arduino/cores/esp32/esp32-hal-uart.c:404

I (464) boot: Loaded app from partition at offset 0x10000
I (464) boot: Disabling RNG early entropy source...
I (465) cpu_start: Pro cpu up.
I (469) cpu_start: Application information:
I (473) cpu_start: Project name: blink
I (478) cpu_start: App version: v4.0-dev-447-g689032650-dirty
I (485) cpu_start: Compile time: Apr 27 2019 15:32:06
I (491) cpu_start: ELF file SHA256: 1eed25426c224611...
I (497) cpu_start: ESP-IDF: v4.0-dev-447-g689032650-dirty
I (504) cpu_start: Starting app cpu, entry point is 0x40081070
0x40081070: call_start_cpu1 at /Users/junghaemin/esp/esp-idf/components/esp32/cpu_start.c:267

I (0) cpu_start: App cpu up.
I (514) heap_init: Initializing. RAM available for dynamic allocation:
I (521) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (527) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (533) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (540) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (546) heap_init: At 3FFCA0F8 len 00015F08 (87 KiB): DRAM
I (552) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (558) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (565) heap_init: At 40091F20 len 0000E0E0 (56 KiB): IRAM
I (571) cpu_start: Pro cpu start user code
I (254) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (10) BTDM_INIT: BT controller compile version [484c057]
I (277) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (377) phy: phy_version: 4100, 2a5dd04, Jan 23 2019, 21:00:07, 0, 0
/Users/junghaemin/esp/esp-idf/components/freertos/queue.c:729 (xQueueGenericSend)- assert failed!
abort() was called at PC 0x4008e753 on core 0
0x4008e753: xQueueGenericSend at /Users/junghaemin/esp/esp-idf/components/freertos/queue.c:2002

ELF file SHA256: 1eed25426c224611975af3b522a8b6168cd36f92debe0890959a109efb92ce56

Backtrace: 0x4008d258:0x3ffcf7e0 0x4008d4a5:0x3ffcf800 0x4008e753:0x3ffcf820 0x4011fc25:0x3ffcf860 0x4011e226:0x3ffcf8a0 0x4011c98d:0x3ffcf8f0 0x4012a80d:0x3ffcf910 0x401265e6:0x3ffcf950 0x4008e1c1:0x3ffcf980
0x4008d258: invoke_abort at /Users/junghaemin/esp/esp-idf/components/esp32/panic.c:716

0x4008d4a5: abort at /Users/junghaemin/esp/esp-idf/components/esp32/panic.c:716

0x4008e753: xQueueGenericSend at /Users/junghaemin/esp/esp-idf/components/freertos/queue.c:2002

0x4011fc25: FreeRTOS::Semaphore::give() at /Users/junghaemin/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/char_traits.h:243

0x4011e226: BLEServer::handleGATTServerEvent(esp_gatts_cb_event_t, unsigned char, esp_ble_gatts_cb_param_t*) at /Users/junghaemin/esp/esp-idf/examples/get-started/blink/components/arduino/cores/esp32/BLEServer.cpp:113

0x4011c98d: BLEDevice::gattServerEventHandler(esp_gatts_cb_event_t, unsigned char, esp_ble_gatts_cb_param_t*) at /Users/junghaemin/esp/esp-idf/examples/get-started/blink/components/arduino/cores/esp32/BLEDevice.cpp:485

0x4012a80d: btc_gatts_cb_to_app at /Users/junghaemin/esp/esp-idf/components/bt/bluedroid/btc/profile/std/gatt/btc_gatts.c:54
(inlined by) btc_gatts_cb_handler at /Users/junghaemin/esp/esp-idf/components/bt/bluedroid/btc/profile/std/gatt/btc_gatts.c:769

0x401265e6: btc_task at /Users/junghaemin/esp/esp-idf/components/bt/bluedroid/btc/core/btc_task.c:111

0x4008e1c1: vPortTaskWrapper at /Users/junghaemin/esp/esp-idf/components/freertos/port.c:403

Rebooting...

DId I do something wrong? I can't even guess what's wrong with it.

[me-no-dev]

I also stumbled upon this recently. Seems there was a change the the queue code that "broke" semaphores. @igrr @projectgus could you comment on this please? Semaphores cause assert exception, even though they are properly given/taken from different threads.

[projectgus]

Hi @me-no-dev,

It looks like the FreeRTOS::Semaphore class always creates a mutex semaphore.

In FreeRTOS, mutex semaphores are a specialised semaphore type for implementing "simple mutual exclusion". As noted in the FreeRTOS docs, the mutex must always be given back otherwise the task which "owns" it can permanently have the wrong priority.

This was the source of a lot of subtle bugs both in IDF and in IDF apps because the mutex semaphore semaphore is taken/given from different tasks, so we added this assert that the task which "takes" a mutex semaphore is the task which "gives" it back.

In this case it looks like the semaphore is "given" in the btc_task callback but is probably taken by another task which is calling into the BLE library. This usage may be more suited to a FreeRTOS binary semaphore?

[happynet95]

@projectgus thanks for ur help.

so you mean.. there's no way to use BLE Arduino library in esp-idf..?

[projectgus]

@happynet95 I mean that the BLE Arduino library probably had some subtle bugs with the incorrect semaphore type before, and now it has an obvious failure in the latest IDF.

The fix may be as simple as changing the call to xSemaphoreCreateMutex() here and replacing the one line with these two lines:

m_semaphore = xSemaphoreCreateBinary();
xSemaphoreGive(m_semaphore);

However I haven't tested this, there might be some places where this class is used that need the mutex semaphore behaviour (ie priority inheritance).

[h2zero]

Awesome, I've been getting this assert occasionally when giving the semaphore in the callback for various BLE functions and have been scratching my head on this for a while. I'll try this change and report back.

[me-no-dev]

@projectgus this is exactly the info I needed :) binary semaphores it is! We will need to change a few libs here and there it seems.

[h2zero]

Tried out the change suggested by @projectgus. Been running fine for a couple hours now.

[h2zero]

I just created a pull request for this as well as taking care of another bug that can cause an assert when giving the semaphore from the callback. #2728

[happynet95]

Still not working...

I (28) boot: ESP-IDF v4.0-dev-447-g689032650-dirty 2nd stage bootloader
I (28) boot: compile time 15:26:45
I (29) boot: Enabling RNG early entropy source...
I (35) boot: SPI Speed : 40MHz
I (39) boot: SPI Mode : DIO
I (43) boot: SPI Flash Size : 4MB
I (47) boot: Partition Table:
I (51) boot: ## Label Usage Type ST Offset Length
I (58) boot: 0 nvs WiFi data 01 02 00009000 00005000
I (65) boot: 1 otadata OTA data 01 00 0000e000 00002000
I (73) boot: 2 app0 OTA app 00 10 00010000 00140000
I (80) boot: 3 app1 OTA app 00 11 00150000 00140000
I (88) boot: 4 spiffs Unknown data 01 82 00290000 00170000
I (95) boot: End of partition table
I (100) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x37460 (226400) map
I (188) esp_image: segment 1: paddr=0x00047488 vaddr=0x3ffbdb60 size=0x02cac ( 11436) load
I (193) esp_image: segment 2: paddr=0x0004a13c vaddr=0x40080000 size=0x00400 ( 1024) load
0x40080000: _WindowOverflow4 at /Users/junghaemin/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (195) esp_image: segment 3: paddr=0x0004a544 vaddr=0x40080400 size=0x05acc ( 23244) load
I (213) esp_image: segment 4: paddr=0x00050018 vaddr=0x400d0018 size=0x99b5c (629596) map
0x400d0018: _flash_cache_start at ??:?

I (434) esp_image: segment 5: paddr=0x000e9b7c vaddr=0x40085ecc size=0x0c440 ( 50240) load
0x40085ecc: spi_flash_mmap_init at /Users/junghaemin/esp/esp-idf/components/spi_flash/flash_mmap.c:321

I (466) boot: Loaded app from partition at offset 0x10000
I (466) boot: Disabling RNG early entropy source...
I (466) cpu_start: Pro cpu up.
I (470) cpu_start: Application information:
I (475) cpu_start: Project name: blink
I (479) cpu_start: App version: v4.0-dev-447-g689032650-dirty
I (486) cpu_start: Compile time: Apr 29 2019 15:26:49
I (492) cpu_start: ELF file SHA256: 07b507db09240e3b...
I (498) cpu_start: ESP-IDF: v4.0-dev-447-g689032650-dirty
I (505) cpu_start: Starting app cpu, entry point is 0x400810e4
0x400810e4: call_start_cpu1 at /Users/junghaemin/esp/esp-idf/components/esp32/cpu_start.c:267

I (0) cpu_start: App cpu up.
I (516) heap_init: Initializing. RAM available for dynamic allocation:
I (522) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (528) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (535) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (541) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (547) heap_init: At 3FFCA110 len 00015EF0 (87 KiB): DRAM
I (553) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (559) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (566) heap_init: At 4009230C len 0000DCF4 (55 KiB): IRAM
I (572) cpu_start: Pro cpu start user code
I (255) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (10) BLEDevice: Entered to BLEDdvice :: init
I (10) BLEDevice: line 344
I (10) BTDM_INIT: BT controller compile version [484c057]
I (283) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (383) phy: phy_version: 4100, 2a5dd04, Jan 23 2019, 21:00:07, 0, 0
I (383) BLEDevice: line 400
I (623) BLEDevice: line 410
I (733) BLEDevice: line 419
I (733) BLEDevice: line 428
I (733) BLEDevice: line 438
I (733) BLEDevice: line 448
I (733) BLEDevice: line 456
/Users/junghaemin/esp/esp-idf/components/freertos/queue.c:729 (xQueueGenericSend)- assert failed!
abort() was called at PC 0x4008eb3f on core 0
0x4008eb3f: xQueueGenericSend at /Users/junghaemin/esp/esp-idf/components/freertos/queue.c:2002

ELF file SHA256: 07b507db09240e3bef32caa529ebdb1a7cf4bbde73eef532dfe56bf783b96e2f

Backtrace: 0x4008d644:0x3ffcfce0 0x4008d891:0x3ffcfd00 0x4008eb3f:0x3ffcfd20 0x40120221:0x3ffcfd60 0x4011e822:0x3ffcfda0 0x4011ccb9:0x3ffcfdf0 0x4012ae09:0x3ffcfe10 0x40126be2:0x3ffcfe50 0x4008e5ad:0x3ffcfe80
0x4008d644: invoke_abort at /Users/junghaemin/esp/esp-idf/components/esp32/panic.c:716

0x4008d891: abort at /Users/junghaemin/esp/esp-idf/components/esp32/panic.c:716

0x4008eb3f: xQueueGenericSend at /Users/junghaemin/esp/esp-idf/components/freertos/queue.c:2002

0x40120221: FreeRTOS::Semaphore::give() at /Users/junghaemin/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/char_traits.h:243

0x4011e822: BLEServer::handleGATTServerEvent(esp_gatts_cb_event_t, unsigned char, esp_ble_gatts_cb_param_t*) at /Users/junghaemin/esp/esp-idf/examples/get-started/blink/components/arduino/cores/esp32/BLEServer.cpp:113

0x4011ccb9: BLEDevice::gattServerEventHandler(esp_gatts_cb_event_t, unsigned char, esp_ble_gatts_cb_param_t*) at /Users/junghaemin/esp/esp-idf/examples/get-started/blink/components/arduino/cores/esp32/BLEDevice.cpp:515

0x4012ae09: btc_gatts_cb_to_app at /Users/junghaemin/esp/esp-idf/components/bt/bluedroid/btc/profile/std/gatt/btc_gatts.c:54
(inlined by) btc_gatts_cb_handler at /Users/junghaemin/esp/esp-idf/components/bt/bluedroid/btc/profile/std/gatt/btc_gatts.c:769

0x40126be2: btc_task at /Users/junghaemin/esp/esp-idf/components/bt/bluedroid/btc/core/btc_task.c:111

0x4008e5ad: vPortTaskWrapper at /Users/junghaemin/esp/esp-idf/components/freertos/port.c:403

Rebooting...

I think I've just have to move on to esp-idf, not using Arduino library.

[happynet95]

@h2zero Does your device work well?

[h2zero]

@happynet95, yes I’ve just ran for 12 hours or so without an issue. Not sure why that didn’t work for you, I’ll do some more testing on another device.

[h2zero]

Just checked again with another device from a fresh IDF and Arduino clone.

Without the above changes I get the same error. As soon as I make the changes in the PR it works fine and has been for over an hour.

Only differences I can think of is my IDF is a couple commits ahead of yours and my sdkconfig is a bit different.

Double check you’ve made the changes in the PR. If it still doesn’t work try the IDF @ ca6cff7, as that is the commit I’m using.

[me-no-dev]

i've been testing the same changes in different code and also have no issues
@h2zero did you take care of that name position?

[h2zero]

@me-no-dev You mean the m_owner position? I haven’t moved it back yet, I can do that right away for the PR if you want. Just be aware that it should be noted as a known bug that will occasionaly cause crashes for some people.

Updated PR to restore m_owner position as requested.