Intermitent issue when try to provisioning device

[jlpuma24]

When provisioning with android library, the bluetooth connection fails every other attempt. It will successfully connect, then if attempt to provision again, the bluetooth fails to connect. this pattern repeats. the bluetooth permission popup does not occur when the fail happens. My company is in early production with the esp32 device and about to release to market. this problem does not happen with our iOS app.

The problem can be seen using the wifi_prov_mgr example and android ESP provisioning app. After a successful provision, reset device and attempt to provision again. The app will show this error:

Device startup log for version references:

I (0) cpu_start: App cpu up.

I (504) cpu_start: Pro cpu start user code

I (504) cpu_start: cpu freq: 160000000

I (504) cpu_start: Application information:

I (508) cpu_start: Project name:     wifi_prov_mgr

I (514) cpu_start: App version:      1

I (518) cpu_start: Compile time:     Dec 28 2022 13:29:18

I (524) cpu_start: ELF file SHA256:  041cdda80acaa3e2...

I (530) cpu_start: ESP-IDF:          v4.4.1-dirty

I (536) heap_init: Initializing. RAM available for dynamic allocation:

I (543) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM

I (549) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM

I (555) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM

I (561) heap_init: At 3FFC8F18 len 000170E8 (92 KiB): DRAM

I (567) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM

I (574) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM

I (580) heap_init: At 4009CD8C len 00003274 (12 KiB): IRAM

I (588) spi_flash: detected chip: generic

I (591) spi_flash: flash io: dio

I (596) cpu_start: Starting scheduler on PRO CPU.

I (0) cpu_start: Starting scheduler on APP CPU.

I (708) wifi:wifi driver task: 3ffce024, prio:23, stack:6656, core=0

I (708) system_api: Base MAC address is not set

I (708) system_api: read default base MAC address from EFUSE

I (738) wifi:wifi firmware version: 63017e0

I (738) wifi:wifi certification version: v7.0

I (738) wifi:config NVS flash: enabled

I (738) wifi:config nano formating: disabled

I (738) wifi:Init data frame dynamic rx buffer num: 32

I (748) wifi:Init management frame dynamic rx buffer num: 32

I (748) wifi:Init management short buffer num: 32

I (758) wifi:Init dynamic tx buffer num: 32

I (758) wifi:Init static rx buffer size: 1600

I (758) wifi:Init static rx buffer num: 10

I (768) wifi:Init dynamic rx buffer num: 32

I (768) wifi_init: rx ba win: 6

I (778) wifi_init: tcpip mbox: 32

I (778) wifi_init: udp mbox: 6

I (778) wifi_init: tcp mbox: 6

I (788) wifi_init: tcp tx win: 5744

I (788) wifi_init: tcp rx win: 5744

I (798) wifi_init: tcp mss: 1440

I (798) wifi_init: WiFi IRAM OP enabled

I (798) wifi_init: WiFi RX IRAM OP enabled

I (808) wifi_prov_scheme_ble: BT memory released

I (848) app: Starting provisioning

I (858) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07

I (958) wifi:mode : sta (30:c6:f7:b4:57:58)

I (958) wifi:enable tsf

I (958) BTDM_INIT: BT controller compile version [5688ed5]

I (1208) protocomm_nimble: BLE Host Task Started

I (1208) wifi_prov_mgr: Provisioning started with service name : PROV_B45758 

I (1208) app: Provisioning started

This happens all the time when i provision success, then fails, then success, then fail.

Also i have a ANR on the BleScanner, and maybe is relatd.

main (native)
tid=1 systid=31299
com.espressif.provisioning.device_scanner.BleScanner$2.onScanResult (BleScanner.java:183)
android.bluetooth.le.BluetoothLeScanner$BleScanCallbackWrapper$1.run (BluetoothLeScanner.java:558)
android.os.Handler.handleCallback (Handler.java:942)
android.os.Handler.dispatchMessage (Handler.java:99)
android.os.Looper.loopOnce (Looper.java:201)
android.os.Looper.loop (Looper.java:288)
android.app.ActivityThread.main (ActivityThread.java:7872)
java.lang.reflect.Method.invoke (Native method)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:548)
com.android.internal.os.ZygoteInit.main (ZygoteInit.java:936)

Also i'm using the wifi_prov_mgr example and the android provisioning example app and the app will show the error in the image below

[KhushbuShah25]

Hi @jlpuma24 , Can you give some more details like which idf version and Android version you are using ?

[jlpuma24]

Thanks for answer @khushbushah2302 i'm using the latest one 2.1.1, and the android version what i'm using are 12 and 13.
Thanks!

[KhushbuShah25]

Hi @jlpuma24 , can you please install esp-idf v5.0 device firmware and check this ?

[adamlehotay]

Hi @khushbushah2302, i am the firmware engineer on the project with @jlpuma24 that has this issue. I have updated to esp-idf v5.0 and i am running the wifi_prov_mgr example without changes to replicate the issue we are seeing. The issue is still there with the latest esp-idf. i have the example configured to reset provisioning after a esp32 reset (CONFIG_EXAMPLE_RESET_PROVISIONED).

when using the ESP BLE Prov app (App version – v2.1.0 – 7f8108a) i see the issue that we believe to be the same as what happens on our custom app. after a successful bluetooth connection and provision, i click "provision another device". i reset the esp32 and then select it from the device list on the app. it then immediately shows "device disconnected". the message disappears after a few seconds. I can also close the app immediately after a successful bluetooth connection without completing the provisioning, reset esp32, then open app again, and the "device disconnected" message will appear after selecting device.

[adamlehotay]

here is the esp32 device log on a BT failure:

I (0) cpu_start: App cpu up.
I (545) cpu_start: Pro cpu start user code
I (545) cpu_start: cpu freq: 160000000 Hz
I (545) cpu_start: Application information:
I (550) cpu_start: Project name: wifi_prov_mgr
I (555) cpu_start: App version: 1
I (560) cpu_start: Compile time: Dec 30 2022 12:58:38
I (566) cpu_start: ELF file SHA256: c2d93d7fe8640f4c...
I (572) cpu_start: ESP-IDF: v5.0-dirty
I (577) heap_init: Initializing. RAM available for dynamic allocation:
I (584) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (590) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (596) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (603) heap_init: At 3FFC98E0 len 00016720 (89 KiB): DRAM
I (609) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (615) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (622) heap_init: At 4009E748 len 000018B8 (6 KiB): IRAM
I (629) spi_flash: detected chip: generic
I (632) spi_flash: flash io: dio
W (636) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (651) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (765) wifi:wifi driver task: 3ffce400, prio:23, stack:6656, core=0
I (765) system_api: Base MAC address is not set
I (765) system_api: read default base MAC address from EFUSE
I (795) wifi:wifi firmware version: 0d470ef
I (795) wifi:wifi certification version: v7.0
I (795) wifi:config NVS flash: enabled
I (795) wifi:config nano formating: disabled
I (795) wifi:Init data frame dynamic rx buffer num: 32
I (805) wifi:Init management frame dynamic rx buffer num: 32
I (805) wifi:Init management short buffer num: 32
I (815) wifi:Init dynamic tx buffer num: 32
I (815) wifi:Init static rx buffer size: 1600
I (815) wifi:Init static rx buffer num: 10
I (825) wifi:Init dynamic rx buffer num: 32
I (825) wifi_init: rx ba win: 6
I (835) wifi_init: tcpip mbox: 32
I (835) wifi_init: udp mbox: 6
I (835) wifi_init: tcp mbox: 6
I (845) wifi_init: tcp tx win: 5744
I (845) wifi_init: tcp rx win: 5744
I (855) wifi_init: tcp mss: 1440
I (855) wifi_init: WiFi IRAM OP enabled
I (855) wifi_init: WiFi RX IRAM OP enabled
I (865) wifi_prov_scheme_ble: BT memory released
I (905) app: Starting provisioning
I (905) app: Development mode: using hard coded salt
I (905) app: Development mode: using hard coded verifier
I (915) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1015) wifi:mode : sta (30:c6:f7:b4:57:58)
I (1015) wifi:enable tsf
I (1025) BTDM_INIT: BT controller compile version [8020d24]
I (1265) protocomm_nimble: BLE Host Task Started
I (1275) wifi_prov_mgr: Provisioning started with service name : PROV_B45758
I (1275) app: Provisioning started
I (1275) app: Scan this QR code from the provisioning application for Provisioning.
I (1285) QRCODE: Encoding below text with ECC LVL 0 & QR Code Version 10
I (1295) QRCODE: {"ver":"v1","name":"PROV_B45758","username":"wifiprov","pop":"abcd1234","transport":"ble"}
I (1295) NimBLE: GAP procedure initiated: advertise;
I (1305) NimBLE: disc_mode=2
I (1315) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=256 adv_itvl_max=256
I (1325) NimBLE:

█▀▀▀▀▀█ ███ ▀▄▀▀▀▄▄▄█▄▀▀▄▄▀▀ █▀▀▀▀▀█
█ ███ █ █▄▀█ ▄▄▄█▀▀▀▄▀▀█▄▄ ▄█ █ ███ █
█ ▀▀▀ █ ▄ ▄▄█▀▀▀ ▄▀█▄▀ ▀█▀ █ ▀▀▀ █
▀▀▀▀▀▀▀ ▀▄▀ █ █ █▄▀ ▀▄▀▄▀ ▀▄█ ▀▀▀▀▀▀▀
▀█▄▄▀▀▀▄▄▄▄▀▄▄█▄ ▀█▀▄▀██▀▄ █▀▄ █▄▀▀▀▀
█ ▄▀▀▄▀▀ ▀█▀▀ ▀█▄ ▄▄▄▀▄ ██ ██ ▀█▄█▄
▀▀▄▀▀█▀▀▄▄ ▀ █▀██▀▀▀ ▄▀▄ ▄▀ ▀█▄▀█▄▀
█▀▀▀█▀▀▄▄▄ ▄ █▀██▀▄▀▄██▀▀▄▀ █▄█ █▄
▄ ▄▀ ▀▀▄█▄▄▀▄▀█▄ ▀█▀▀█ █▀▄▄▄▀██▀▄ ▀▀▀
█▀▀███▀▄▄ █▀█▀█▀▄ ▄ █▄▀█ ██ █ █▄▀▄▄▄
▀▀▄ ▀▄█ ▄ ▀█▄▄█▀ ▀▀▀ ▄ ▄ ▄▀██▀▄█▀█▀
█▀█▄█▀ █▀▀ ▄ ▄▀██▀ ▀▄█▀ ▀ █▀█▄▀ █▄▄▄
██▀▄▀█▀▄█▀█▀▄▀▀▄█▀ ▀▀▀█▄█ ▄▄▀▀█▀▄▀▀ ▀
▄▀█ ▀ ▄▀██▀█▀▀ ▄ ▄ ██▀ ▀▀▀█ █▄█▄█▀▄
▀▀▀ ▀▀▀▀██ ▀█▄█▄▀▄▀██▀█▄▄▄ █▀▀▀█ ▀▄
█▀▀▀▀▀█ ▄ ▄ ▄ ▄███▄▄ ▄ ▀ ▄▀█ ▀ ██▄▄▄
█ ███ █ ▀█▄▀▄▀▀▄██▄ ▄▀█▄█ ▄▄████▀▄█▄▄
█ ▀▀▀ █ ▄███▀█▀▀▄▄▀▄ ████ █ ▄ ▀▄██▄
▀▀▀▀▀▀▀ ▀▀ ▀▀ ▀▀ ▀▀▀ ▀ ▀ ▀▀ ▀▀▀

I (1595) app: If QR code is not visible, copy paste the below URL in a browser.
https://espressif.github.io/esp-jumpstart/qrcode.html?data={"ver":"v1","name":"PROV_B45758","username":"wifiprov","pop":"abcd1234","transport":"ble"}
I (7335) NimBLE: GAP procedure initiated: advertise;
I (7335) NimBLE: disc_mode=2
I (7335) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=256 adv_itvl_max=256
I (7345) NimBLE:

[KhushbuShah25]

Hi @jlpuma24 ,
We have fixed the issue in app and firmware (esp-idf v5.0). But app is still in beta stage. Can you install ESP BLE Prov beta app (version - v2.1.2 - 661f84d) and check this ?

[jlpuma24]

Hi @khushbushah2302 i didn't see that commit, or branch, or tag in the tree. Can you clarify how can i got the access to this version? Thanks!

[KhushbuShah25]

Hi @jlpuma24 ,
The app side commit is not available on GitHub yet. It will be available soon.
For installing beta version of app, you need to join the beta program from PlayStore as shown in screenshot. You can install beta app by updating current app after sometime of joining beta.

[KhushbuShah25]

Hi @jlpuma24 , app is released now. Please check with new app.

[adamlehotay]

Hi @khushbushah2302, I have tested the new app and it still shows the "device disconnected" message every other provisioning attempt. For the custom android app that @jlpuma24 is developing, which also has this problem, we have found that the issue is only happening on samsung devices.

[cliut]

@adamlehotay I have same issue with samsung devices. did you resolve this issue?