[TW#15172] BLE advertising not working on the samples

[ddewaele]

For some reason, on my Sparkfun ESP32 Thing device, I cannot get any of the bluetooth samples to run. What I want to do for now is have my ESP32 show up as a device (beacon) in the Nrf Connect app. Once I get that up and running, I would like to start reading / writing from / to services.

However, I'm currently stuck at the fact that none of my BLE scanning apps can see my ESP32 device.

Here's what I tried so far :

• See if there is a hardware issue. Don't think this is the case as the Arduino SimpleBleClient (that simply does advertising and allows the device to be picked up by nrf Connect for example) does work, and I can see my device
• Tried esp-idf 2.1 and 3.0
• Tried the toolchain on mac os X and windows
• Tried different BLE scanning apps on both iOS and Android.

I've tried the various samples like ble_adv that produce the output blow. I'm assuming here that running the sample should allow iOs / Android to find ESP-BLE-HELLO :

��[0;32mI (31) boot: ESP-IDF v2.1-2-g7138fb0 2nd stage bootloader�[0m
�[0;32mI (31) boot: compile time 06:08:26�[0m
�[0;32mI (49) boot: Enabling RNG early entropy source...�[0m
�[0;32mI (49) boot: SPI Speed      : 40MHz�[0m
�[0;32mI (60) boot: SPI Mode       : DIO�[0m
�[0;32mI (72) boot: SPI Flash Size : 4MB�[0m
�[0;32mI (84) boot: Partition Table:�[0m
�[0;32mI (95) boot: ## Label            Usage          Type ST Offset   Length�[0m
�[0;32mI (118) boot:  0 nvs              WiFi data        01 02 00009000 00006000�[0m
�[0;32mI (141) boot:  1 phy_init         RF data          01 01 0000f000 00001000�[0m
�[0;32mI (164) boot:  2 factory          factory app      00 00 00010000 00100000�[0m
�[0;32mI (188) boot: End of partition table�[0m
�[0;32mI (201) boot: Disabling RNG early entropy source...�[0m
�[0;32mI (218) boot: Loading app partition at offset 00010000�[0m
�[0;32mI (632) boot: segment 0: paddr=0x00010018 vaddr=0x00000000 size=0x0ffe8 ( 65512) �[0m
�[0;32mI (632) boot: segment 1: paddr=0x00020008 vaddr=0x3f400010 size=0x04a84 ( 19076) map�[0m
�[0;32mI (648) boot: segment 2: paddr=0x00024a94 vaddr=0x3ffc0000 size=0x02238 (  8760) load�[0m
�[0;32mI (678) boot: segment 3: paddr=0x00026cd4 vaddr=0x40080000 size=0x00400 (  1024) load�[0m
�[0;32mI (701) boot: segment 4: paddr=0x000270dc vaddr=0x40080400 size=0x12c5c ( 76892) load�[0m
�[0;32mI (763) boot: segment 5: paddr=0x00039d40 vaddr=0x400c0000 size=0x00000 (     0) load�[0m
�[0;32mI (764) boot: segment 6: paddr=0x00039d48 vaddr=0x00000000 size=0x062c0 ( 25280) �[0m
�[0;32mI (785) boot: segment 7: paddr=0x00040010 vaddr=0x400d0018 size=0x150b4 ( 86196) map�[0m
�[0;32mI (811) cpu_start: Pro cpu up.�[0m
�[0;32mI (822) cpu_start: Starting app cpu, entry point is 0x40080dac�[0m
�[0;32mI (0) cpu_start: App cpu up.�[0m
�[0;32mI (855) heap_alloc_caps: Initializing. RAM available for dynamic allocation:�[0m
�[0;32mI (877) heap_alloc_caps: At 3FFAFF10 len 000000F0 (0 KiB): DRAM�[0m
�[0;32mI (897) heap_alloc_caps: At 3FFC4058 len 0001BFA8 (111 KiB): DRAM�[0m
�[0;32mI (918) heap_alloc_caps: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM�[0m
�[0;32mI (939) heap_alloc_caps: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM�[0m
�[0;32mI (960) heap_alloc_caps: At 4009305C len 0000CFA4 (51 KiB): IRAM�[0m
�[0;32mI (981) cpu_start: Pro cpu start user code�[0m
�[0;32mI (1038) cpu_start: Starting scheduler on PRO CPU.�[0m
�[0;32mI (200) cpu_start: Starting scheduler on APP CPU.�[0m
�[0;32mI (250) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE�[0m
�[0;32mI (530) phy: phy_version: 355.1, 59464c5, Jun 14 2017, 20:25:06, 0, 0�[0m
BLE advt task start
host rcv pkt: 040e0405030c00
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 1
host rcv pkt: 040e0405062000
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 2
host rcv pkt: 040e0405082000
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 3
host rcv pkt: 040e04050a2000
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4

and gatt_server. I'm assuming here that a BLE scanning app should find ESP_GATTS_DEMO.

�⸮�⸮�⸮�KVi⸮�⸮CH�⸮�⸮Y⸮QP⸮kD�⸮F⸮V⸮`⸮�⸮�W⸮��[0;32mI (31) boot: ESP-IDF v3.0-dev-394-ga4fe12c-dirty 2nd stage bootloader�[0m
�[0;32mI (31) boot: compile time 09:18:35�[0m
�[0;32mI (51) boot: Enabling RNG early entropy source...�[0m
�[0;32mI (51) boot: SPI Speed      : 40MHz�[0m
�[0;32mI (63) boot: SPI Mode       : DIO�[0m
�[0;32mI (75) boot: SPI Flash Size : 4MB�[0m
�[0;32mI (87) boot: Partition Table:�[0m
�[0;32mI (99) boot: ## Label            Usage          Type ST Offset   Length�[0m
�[0;32mI (121) boot:  0 nvs              WiFi data        01 02 00009000 00006000�[0m
�[0;32mI (144) boot:  1 phy_init         RF data          01 01 0000f000 00001000�[0m
�[0;32mI (167) boot:  2 factory          factory app      00 00 00010000 00100000�[0m
�[0;32mI (191) boot: End of partition table�[0m
�[0;32mI (204) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2932c (168748) map�[0m
�[0;32mI (411) esp_image: segment 1: paddr=0x00039354 vaddr=0x3ffc0000 size=0x02a3c ( 10812) load�[0m
�[0;32mI (425) esp_image: segment 2: paddr=0x0003bd98 vaddr=0x40080000 size=0x00400 (  1024) load�[0m
�[0;32mI (434) esp_image: segment 3: paddr=0x0003c1a0 vaddr=0x40080400 size=0x03e70 ( 15984) load�[0m
�[0;32mI (480) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x629d0 (403920) map�[0m
�[0;32mI (917) esp_image: segment 5: paddr=0x000a29f0 vaddr=0x40084270 size=0x0f69c ( 63132) load�[0m
�[0;32mI (998) esp_image: segment 6: paddr=0x000b2094 vaddr=0x400c0000 size=0x00000 (     0) load�[0m
�[0;32mI (1034) boot: Loaded app from partition at offset 0x10000�[0m
�[0;32mI (1034) boot: Disabling RNG early entropy source...�[0m
�[0;32mI (1036) cpu_start: Pro cpu up.�[0m
�[0;32mI (1047) cpu_start: Starting app cpu, entry point is 0x40080ea4�[0m
�[0;32mI (0) cpu_start: App cpu up.�[0m
�[0;32mI (1080) heap_init: Initializing. RAM available for dynamic allocation:�[0m
�[0;32mI (1101) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM�[0m
�[0;32mI (1120) heap_init: At 3FFCB1F0 len 00014E10 (83 KiB): DRAM�[0m
�[0;32mI (1139) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM�[0m
�[0;32mI (1159) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM�[0m
�[0;32mI (1179) heap_init: At 4009390C len 0000C6F4 (49 KiB): IRAM�[0m
�[0;32mI (1198) cpu_start: Pro cpu start user code�[0m
�[0;32mI (1257) cpu_start: Starting scheduler on PRO CPU.�[0m
�[0;32mI (196) cpu_start: Starting scheduler on APP CPU.�[0m
�[0;32mI (276) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE�[0m
�[0;32mI (576) phy: phy_version: 357.0, a6bf95b, Jul 25 2017, 12:28:06, 0, 0�[0m
�[0;32mI (616) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 0
�[0m
�[0;32mI (626) GATTS_DEMO: CREATE_SERVICE_EVT___, status 0,  service_handle 40
�[0m
�[0;32mI (626) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 40
�[0m
�[0;32mI (626) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 42, service_handle 40
�[0m
�[0;32mI (636) GATTS_DEMO: the gatts demo char length = 3
�[0m
�[0;32mI (646) GATTS_DEMO: prf_char[0] =11
�[0m
�[0;32mI (646) GATTS_DEMO: prf_char[1] =22
�[0m
�[0;32mI (646) GATTS_DEMO: prf_char[2] =33
�[0m
�[0;32mI (656) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40
�[0m
�[0;32mI (666) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1
�[0m
�[0;32mI (666) GATTS_DEMO: CREATE_SERVICE_EVT, status 0,  service_handle 44
�[0m
�[0;32mI (676) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44
�[0m
�[0;32mI (686) GATTS_DEMO: ADD_CHAR_EVT, status 0,  attr_handle 46, service_handle 44
�[0m
�[0;32mI (696) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44
�[0m

My questions :

• Any ideas what might be causing the fact that none of the bluetooth scanning apps pick up my device ?
• Any way to debug this further ?
• Assuming that the bluetooth examples work (and I assume they do), what other places can we look at ? (menuconfig / toolchain / other device settings that I can manipulate ?

[ddewaele]

Breakthrough (after 2.5 days).

I was using esp-idf via git (using instructions below) where none of the examples work

git clone https://github.com/espressif/esp-idf.git esp-idf-v2.1
cd esp-idf-v2.1/
git checkout v2.1
git submodule update --init --recursive

I just downloaded a 2.1 release zip (from https://github.com/espressif/esp-idf/releases/) and used that one as the IDF_PATH and now the ble_adv sample worked on the first run.

Investigating......

[llewellynnu]

Hi ,
In the Previous IDF version, the crystal frequency was auto detected. In the latest IDF it is default set to 40Mhz . I guess the Sparkfun thing has a 26Mhz crystal. So you gotta select that in menuconfig.

[ddewaele]

Interesting .... good catch .... indeed noticed a difference on both "2.1" releases (github and tarbal).

Any idea why there's a difference between the v2.1 branch on github and the 2.1 tarbal release ? Where are these default menuconfig valus stored ?

[igrr]

release/v2.1 branch on Github currently has one commit on top of v2.1 tag. That is the commit which changes default XTAL frequency from "auto" to 40 MHz. This commit will be part of a bugfix release, 2.1.1 (along with some other fixes which will be added to release/v2.1 branch).

If you check out v2.1 tag, rather than release/v2.1 branch, you should get the same version as the one in the tarball.

Default menuconfig values are stored in Kconfig files under component directories. This setting, in particular, is in components/esp32/Kconfig file.

[s0217391]

Hi,

I'm having the same issue on a Pycom wipy 3.0. I can't seem to figure out why but the device is not showing up in any of the scanning tools we have.

I tried the above solutions but they don't seem to help. Here's my output log for the ble_adv example:

MONITOR
--- idf_monitor on /dev/ttyUSB0 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)
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_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:5680
ho 0 tail 12 room 4
load:0x40078000,len:0
load:0x40078000,len:13804
entry 0x40079030
I (75) boot: Detected ESP32
I (34) boot: ESP-IDF v3.0-dev-1392-g579201b 2nd stage bootloader
I (34) boot: compile time 12:46:36
I (45) boot: Enabling RNG early entropy source...
I (45) boot: SPI Speed      : 40MHz
I (45) boot: SPI Mode       : DIO
I (48) boot: SPI Flash Size : 4MB
I (52) boot: Partition Table:
I (56) boot: ## Label            Usage          Type ST Offset   Length
I (63) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (71) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (78) boot:  2 factory          factory app      00 00 00010000 00100000
I (86) boot: End of partition table
I (90) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x066c8 ( 26312) map
I (108) esp_image: segment 1: paddr=0x000166f0 vaddr=0x3ffc0000 size=0x02864 ( 10340) load
I (112) esp_image: segment 2: paddr=0x00018f5c vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /esp/esp-idf/components/freertos/./xtensa_vectors.S:1685

I (117) esp_image: segment 3: paddr=0x00019364 vaddr=0x40080400 size=0x06cac ( 27820) load
I (137) esp_image: segment 4: paddr=0x00020018 vaddr=0x400d0018 size=0x1caec (117484) map
0x400d0018: _stext at ??:?

I (178) esp_image: segment 5: paddr=0x0003cb0c vaddr=0x400870ac size=0x0b53c ( 46396) load
0x400870ac: xQueueGenericSendFromISR at /esp/esp-idf/components/freertos/./queue.c:2037

I (197) esp_image: segment 6: paddr=0x00048050 vaddr=0x400c0000 size=0x00000 (     0) load
I (208) boot: Loaded app from partition at offset 0x10000
I (208) boot: Disabling RNG early entropy source...
I (209) cpu_start: Pro cpu up.
I (213) cpu_start: Starting app cpu, entry point is 0x40081030
0x40081030: call_start_cpu1 at /esp/esp-idf/components/esp32/./cpu_start.c:222

I (0) cpu_start: App cpu up.
I (223) heap_init: Initializing. RAM available for dynamic allocation:
I (230) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (236) heap_init: At 3FFC46C0 len 0001B940 (110 KiB): DRAM
I (242) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (249) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (255) heap_init: At 400925E8 len 0000DA18 (54 KiB): IRAM
I (261) cpu_start: Pro cpu start user code
I (279) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (341) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (611) phy: phy_version: 366.0, ba9923d, Oct 31 2017, 18:06:17, 0, 0
BLE advt task start
host rcv pkt: 040e0405030c00
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 1
host rcv pkt: 040e0405062000
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 2
host rcv pkt: 040e0405082000
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 3
host rcv pkt: 040e04050a2000
controller rcv pkt ready
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
BLE Advertise, flag_send_avail: 1, cmd_sent: 4
...

Any ideas?