Race condition in provisioning procedure (MEGH-4228)

jacek12345 commented 1 year ago

Provisioning with BLE transport (don't know if SoftAP also affected). If we hit with app provisioning in specific moment close to provisioning timeout, WI-FI Reset not work any more. Hard reset is needed. Mobile app hangs on first point of provisioning flow presentation and need to be killed. Paradoxically it is not hard to hit this moment with extensive development work and short timeout set (I have 2 min). So it will definitely happen in real usecase.

I (1206) wifi_prov_mgr: Provisioning started with service name : NX-G-1_3931
I (1216) app_wifi: Provisioning started
I (1216) app_main: Provisioning started
W (1226) app_main: Reset cause: 3
I (1226) led_serv: led 1: pulse fast
I (1236) esp_rmaker_local: Event 1
I (1236) app_wifi: Scan this QR code from the ESP RainMaker phone app for Provisioning.

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

I (1396) app_wifi: If QR code is not visible, copy paste the below URL in a browser.
https://rainmaker.espressif.com/qrcode.html?data={"ver":"v1","name":"NX-G-1_3931","transport":"ble"}
I (1416) app_main: Provisioning QR : {"ver":"v1","name":"NX-G-1_3931","transport":"ble"}
I (1426) app_wifi: Provisioning Started. Name : NX-G-1_3931, POP : <null>
I (1436) app_wifi: Provisioning will auto stop after 2 minute(s).
I (111396) protocomm_nimble: mtu update event; conn_handle=1 cid=4 mtu=256

W (121436) app_wifi: Provisioning timed out. Please reboot device to restart provisioning.
I (121436) app_main: Provisioning Timed Out. Please reboot.
I (122346) esp_rmaker_user_mapping: Received request for node details
I (122346) esp_rmaker_user_mapping: Got user_id = Github_*******************, secret_key = ********-****-******-****-***********
I (122356) esp_rmaker_user_mapping: Sending status SUCCESS
I (122456) NimBLE: GAP procedure initiated: stop advertising.

I (122466) NimBLE: GAP procedure initiated: stop advertising.

I (122476) NimBLE: GAP procedure initiated: terminate connection; conn_handle=1 hci_reason=19

E (122496) protocomm_nimble: Error setting advertisement data; rc = 30
I (122586) wifi_prov_mgr: Provisioning stopped
W (122586) BT_INIT: esp_bt_mem_release not implemented, return OK
I (122586) wifi_prov_scheme_ble: BTDM memory released
I (122586) esp_rmaker_local: Event 6
I (222416) app_reset: Release button now for Wi-Fi reset. Keep pressed for factory reset.
I (222416) led_serv: led 1: pulse fast
I (266396) app_reset: Release button now for Wi-Fi reset. Keep pressed for factory reset.
I (266396) led_serv: led 1: pulse fast

sanketwadekar commented 1 year ago

The timer is deleted on WIFI_PROV_END event. So if the event doesn't get triggered before timeout, the callback for stopping provisioning will get executed. If you want to stop and delete the timer once you pass wifi credentials, you can change the code here

shahpiyushv commented 1 year ago

@jacek12345 Closing this issue since appropriate answer was provided. If it has not helped, please let us know.

espressif / esp-rainmaker

Race condition in provisioning procedure (MEGH-4228) #230