ESP32C3 Self Claiming doesn't work (MEGH-3690)

[jacek12345]

Works with Assisted Claiming. When switch in menuconfig to Self Claiming, there is:

I (10751) 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":"PROV_8fb9a4","pop":"db837216","transport":"ble"}
I (10771) app_main: Provisioning QR : {"ver":"v1","name":"PROV_8fb9a4","pop":"db837216","transport":"ble"}
I (10781) app_wifi: Provisioning Started. Name : PROV_8fb9a4, POP : db837216
I (10791) app_wifi: Provisioning will auto stop after 30 minute(s).
I (44551) protocomm_nimble: mtu update event; conn_handle=1 cid=4 mtu=256

I (58201) esp_rmaker_user_mapping: Received request for node details
I (58201) esp_rmaker_user_mapping: Got user_id = SignInWithApple_tWgGWURgPU4zwA4JVZVo5J, secret_key = 94F7DD70-21EF-4B93-0A92-02A9CAD9D17A
I (58211) esp_rmaker_user_mapping: User Node mapping reset detected.
I (58221) esp_rmaker_user_mapping: Sending status SUCCESS
I (58481) app_wifi: Received Wi-Fi credentials
        SSID     : Jacek
        Password : xxxxxxxxxx
I (61891) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (61901) wifi:state: init -> auth (b0)
I (62571) wifi:state: auth -> assoc (0)
I (62581) wifi:state: assoc -> run (10)
I (62601) wifi:connected with Jacek, aid = 34, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (62601) wifi:security: WPA3-SAE, phy: bgn, rssi: -57
I (62621) wifi:pm start, type: 1

I (62621) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
W (62671) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
I (62671) wifi:BcnInt:102400, DTIM:3
I (63621) app_wifi: Connected with IP Address:192.168.1.63
I (63621) esp_netif_handlers: sta ip: 192.168.1.63, mask: 255.255.255.0, gw: 192.168.1.1
I (63621) wifi_prov_mgr: STA Got IP
I (63621) app_wifi: Provisioning successful
I (63631) app_main: RainMaker Claim Started.
I (63631) esp_claim: Starting the Self Claim Process. This may take time.
I (64011) esp-x509-crt-bundle: Certificate validated
I (64741) NimBLE: GAP procedure initiated: stop advertising.

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

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

E (64771) protocomm_nimble: Error setting advertisement data; rc = 30
W (64791) Timer: Timer not stopped
W (64801) Timer: Timer not stopped
I (64881) wifi_prov_mgr: Provisioning stopped
W (64881) BTDM_INIT: esp_bt_mem_release not implemented, return OK
I (64881) wifi_prov_scheme_ble: BTDM memory released
I (64881) esp_rmaker_local: Event 6
E (69511) esp_claim: Invalid response for https://esp-claiming.rainmaker.espressif.com/claim/initiate
E (69511) esp_claim: Status = -1, Data = None
E (69511) esp_claim: Claim Init Request Failed.
E (69511) esp_claim: Claim Init Sequence Failed.
I (69521) app_main: RainMaker Claim Failed.
E (69521) esp_rmaker_core: esp_rmaker_self_claim_perform() returned -1. Aborting
I (69531) esp_rmaker_ota_using_topics: Subscribing to: node/A0764E5A640C/otaurl
W (69541) esp_rmaker_mqtt: esp_rmaker_mqtt_unsubscribe not registered
W (69551) esp_rmaker_mqtt: esp_rmaker_mqtt_subscribe not registered
I (69551) esp_rmaker_ota_using_topics: Fetching OTA details, if any.
W (69561) esp_rmaker_mqtt: esp_rmaker_mqtt_publish not registered
W (69571) esp_rmaker_mqtt: esp_rmaker_mqtt_publish not registered
I (69581) esp_rmaker_user_mapping: MQTT Publish: {"node_id":"A0764E5A640C","user_id":"SignInWithApple_tWgGWURgPU4zwA4JVZVo5J","secret_key":"94F7DD70-21EF-4B93-0A92-02A9CAD9D17A","reset":true}
I (70721) wifi:bcn_timout,ap_probe_send_start
I (73221) wifi:ap_probe_send over, resett wifi status to disassoc
I (73221) wifi:state: run -> init (c800)
I (73221) wifi:pm stop, total sleep time: 1313061 us / 10600724 us

W (73221) wifi:<ba-del>idx
I (73231) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (73231) app_wifi: Disconnected. Connecting to the AP again...
I (75281) app_wifi: Disconnected. Connecting to the AP again...
I (75291) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (75291) wifi:state: init -> auth (b0)
I (75291) wifi:state: auth -> assoc (0)
E (75301) wifi:Association refused temporarily, comeback time 1004 mSec
I (76311) wifi:state: assoc -> assoc (0)
E (76311) wifi:Association refused temporarily, comeback time 1004 mSec
I (77321) wifi:state: assoc -> assoc (0)
I (77321) wifi:state: assoc -> init (6c0)
I (77321) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (77321) app_wifi: Disconnected. Connecting to the AP again...
I (79371) app_wifi: Disconnected. Connecting to the AP again...
I (79381) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (79381) wifi:state: init -> auth (b0)
I (80051) wifi:state: auth -> assoc (0)
I (80061) wifi:state: assoc -> run (10)
I (80081) wifi:connected with Jacek, aid = 28, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (80081) wifi:security: WPA3-SAE, phy: bgn, rssi: -58
I (80091) wifi:pm start, type: 1

I (80091) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
W (80141) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
I (80181) wifi:BcnInt:102400, DTIM:3
I (81121) app_wifi: Connected with IP Address:192.168.1.63
I (81121) esp_netif_handlers: sta ip: 192.168.1.63, mask: 255.255.255.0, gw: 192.168.1.1
I (86501) esp_rmaker_time: SNTP Synchronised.
I (86501) esp_rmaker_time: The current time is: Wed Jul 27 17:17:05 2022 +0800[CST], DST: No.

Done

I erased flash before programming. Using:

• ESP-IDF 4.4.1
• ESP32C3
• switch example

The only way to Self Claiminig success after erase-flash, is:

1. try to add device - claiming will fail and device is not added (Confirming Node association fails)
2. restart module - claiming will success but device not visible in app
3. make provisioning (button for 3s and add device)
4. device added

[shahpiyushv]

@jacek12345 , this and the other issue #148 seem related. Does this occur only with some specific AP? Is your device at a significant distance from the AP?

[jacek12345]

There is near 4 meters between device and AP. There was rssi: -57. Tried little closer (near 3m and RSSI = -49) and the same problem. Than tried with other AP - wifi hotspot from Android phone connected to the internet via LTE. Everything on my desk. Looks little different. Sometimes Self Claiming succeed, sometimes failed. Wifi reconnection take place in different moments. It looks that some problem with wifi occures during provisioning. Claiming success depends on when this problem occure. If it occures after claiming starts AND before the claiming process ends, claiming will fail. If it occures before claiming starts or after claiming ends, it only reconnect to AP and claiming success. So meaby #148 can be the source of this problem. Problem with wifi occures only while provisioning. Meaby it is BLE and WIFI coexistence problem? COEXISTENCE flag is enabled now in menuconfig.

[shahpiyushv]

@jacek12345 , I will check this with the Wi-Fi and BLE teams, but can you also try self claiming with SoftAP provisioning? That will help understand if this is a co-ex issue or not.

[jacek12345]

Sure, tried. It looks like co-ex problem. With SoftAP everything OK. SoftAP:

I (13063) 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":"PROV_40b6d4","pop":"ec5debc6","transport":"softap"}
I (13083) app_main: Provisioning QR : {"ver":"v1","name":"PROV_40b6d4","pop":"ec5debc6","transport":"softap"}
I (13093) app_wifi: Provisioning Started. Name : PROV_40b6d4, POP : ec5debc6
I (13103) app_wifi: Provisioning will auto stop after 30 minute(s).
I (26143) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
I (26153) wifi:station: ce:a4:b1:b5:e2:3e join, AID=1, bgn, 20
I (27383) esp_netif_lwip: DHCP server assigned IP to a station, IP is: 192.168.4.2
W (29293) wifi:<ba-add>idx:2 (ifx:1, ce:a4:b1:b5:e2:3e), tid:0, ssn:0, winSize:64
I (39593) esp_rmaker_user_mapping: Received request for node details
I (39603) esp_rmaker_user_mapping: Got user_id = SignInWithApple_txxxxxxxxxxxxxxxx, secret_key = xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
I (39603) esp_rmaker_user_mapping: User Node mapping reset detected.
I (39613) esp_rmaker_user_mapping: Sending status SUCCESS
I (39683) app_wifi: Received Wi-Fi credentials
        SSID     : Jacek
        Password : xxxxxxxx
I (42603) wifi:switch to channel 11
I (42603) wifi:ap channel adjust o:1,1 n:11,2
I (42603) wifi:new:<11,0>, old:<1,0>, ap:<11,2>, sta:<0,0>, prof:1
I (42603) wifi:new:<11,2>, old:<11,0>, ap:<11,2>, sta:<11,0>, prof:1
I (42613) wifi:state: init -> auth (b0)
I (43293) wifi:state: auth -> assoc (0)
I (43303) wifi:state: assoc -> run (10)
I (43333) wifi:connected with Jacek, aid = 37, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (43333) wifi:security: WPA3-SAE, phy: bgn, rssi: -56
I (43343) wifi:pm start, type: 1

I (43343) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
I (43363) wifi:BcnInt:102400, DTIM:3
W (43383) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
I (44093) app_wifi: Connected with IP Address:192.168.1.63
I (44093) esp_netif_handlers: sta ip: 192.168.1.63, mask: 255.255.255.0, gw: 192.168.1.1
I (44093) wifi_prov_mgr: STA Got IP
I (44093) app_wifi: Provisioning successful
I (44103) app_main: RainMaker Claim Started.
I (44103) esp_claim: Starting the Self Claim Process. This may take time.
I (44643) esp-x509-crt-bundle: Certificate validated
I (46073) wifi:station: ce:a4:b1:b5:e2:3e leave, AID = 1, bss_flags is 134259, bss:0x3fcb15a8
I (46073) wifi:new:<11,0>, old:<11,2>, ap:<11,2>, sta:<11,0>, prof:1
W (46073) wifi:<ba-del>idx
I (46073) wifi:mode : sta (a0:76:4e:5a:64:0c)
I (46093) wifi_prov_mgr: Provisioning stopped
I (46093) esp_rmaker_local: Event 6
I (46953) HTTP_CLIENT: Body received in fetch header state, 0x3fcb2bf5, 129
I (47103) esp-x509-crt-bundle: Certificate validated
I (47273) esp_rmaker_time: SNTP Synchronised.
I (47273) esp_rmaker_time: The current time is: Wed Jul 27 22:20:04 2022 +0800[CST], DST: No.
I (50333) HTTP_CLIENT: Body received in fetch header state, 0x3fc9b71a, 502
I (50343) esp_claim: Self Claiming was successful. Certificate received.
I (50343) app_main: RainMaker Claim Successful.
I (50353) esp_mqtt_glue: AWS PPI: ?Platform=APN3|A0|RM|EX00|RMDev|1x0|A0764E5A640C
I (50353) esp_mqtt_glue: Initialising MQTT
I (50363) esp_rmaker_local: Couldn't find POP in NVS. Generating a new one.
I (50373) esp_rmaker_local: Starting ESP Local control with HTTP Transport and security version: 1
I (50393) esp_https_server: Starting server
I (50393) esp_https_server: Server listening on port 8080
I (50393) esp_rmaker_local: esp_local_ctrl service started with name : A0764E5A640C
W (50393) app_main: Unhandled RainMaker Event: 6
I (50403) esp_mqtt_glue: Connecting to a1p72mufdu6064-ats.iot.us-east-1.amazonaws.com
I (50413) esp_mqtt_glue: Waiting for MQTT connection. This may take time.
I (50973) esp-x509-crt-bundle: Certificate validated
I (52483) esp_mqtt_glue: MQTT Connected
I (52483) app_main: MQTT Connected.
I (52483) esp_rmaker_node_config: Reporting Node Configuration of length 1410 bytes.
I (52493) esp_rmaker_core: Waiting for User Node Association.
I (52493) esp_rmaker_ota_using_topics: Subscribing to: node/A0764E5A640C/otaurl
I (52503) esp_rmaker_ota_using_topics: Fetching OTA details, if any.
I (52513) esp_rmaker_user_mapping: MQTT Publish: {"node_id":"A0764E5A640C","user_id":"SignInWithApple_txxxxxxxxxxxxxxxxxxxxxxxxxx","secret_key":"xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx","reset":true}
I (53093) app_main: MQTT Published. Msg id: 54188.
I (53093) app_main: MQTT Published. Msg id: 13667.
I (53103) app_main: MQTT Published. Msg id: 48846.
I (53103) esp_rmaker_user_mapping: User Node association message published successfully.
W (53103) app_main: Unhandled RainMaker Event: 5
I (53113) esp_rmaker_param: Params MQTT Init done.
I (53113) esp_rmaker_param: Reporting params (init): {"Switch":{"Name":"Switch","Power":true},"Time":{"TZ":"","TZ-POSIX":""},"Schedule":{"Schedules":[]},"Scenes":{"Scenes":[]},"Local Control":{"POP":"00447d50","Type":1}}
I (53143) esp_rmaker_cmd_resp: Enabling Command-Response Module.
I (53503) app_main: MQTT Published. Msg id: 26770.
I (58623) esp_rmaker_param: Received params: {"Time":{"TZ":"Europe/Warsaw"}}
I (58623) esp_rmaker_time_service: Received value = Europe/Warsaw for Time - TZ
W (58633) app_main: Unhandled RainMaker Common Event: 6
I (58633) esp_rmaker_time: The current time is: Wed Jul 27 16:20:16 2022 +0200[CEST], DST: Yes.
W (58643) app_main: Unhandled RainMaker Common Event: 7
I (58653) esp_rmaker_param: Reporting params: {"Time":{"TZ-POSIX":"CET-1CEST,M3.5.0,M10.5.0/3"}}
I (58663) esp_rmaker_param: Reporting params: {"Time":{"TZ":"Europe/Warsaw"}}
I (58933) app_main: MQTT Published. Msg id: 22675.
I (59243) app_main: MQTT Published. Msg id: 44850.

And one more time for BLE provisioning:

I (4661) 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":"PROV_f24f07","pop":"8e705ac9","transport":"ble"}
I (4681) app_main: Provisioning QR : {"ver":"v1","name":"PROV_f24f07","pop":"8e705ac9","transport":"ble"}
I (4691) app_wifi: Provisioning Started. Name : PROV_f24f07, POP : 8e705ac9
I (4701) app_wifi: Provisioning will auto stop after 30 minute(s).
I (16321) protocomm_nimble: mtu update event; conn_handle=1 cid=4 mtu=256

I (27691) esp_rmaker_user_mapping: Received request for node details
I (27691) esp_rmaker_user_mapping: Got user_id = SignInWithApple_txxxxxxxxxxxxxxxxxxx, secret_key = xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
I (27701) esp_rmaker_user_mapping: User Node mapping reset detected.
I (27711) esp_rmaker_user_mapping: Sending status SUCCESS
I (27971) app_wifi: Received Wi-Fi credentials
        SSID     : Jacek
        Password : xxxxxxxxx
I (31391) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (31391) wifi:state: init -> auth (b0)
I (32071) wifi:state: auth -> assoc (0)
I (32071) wifi:state: assoc -> run (10)
I (32111) wifi:connected with Jacek, aid = 22, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (32111) wifi:security: WPA3-SAE, phy: bgn, rssi: -55
I (32121) wifi:pm start, type: 1

I (32121) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
I (32151) wifi:BcnInt:102400, DTIM:3
W (32251) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
I (33121) app_wifi: Connected with IP Address:192.168.1.63
I (33121) esp_netif_handlers: sta ip: 192.168.1.63, mask: 255.255.255.0, gw: 192.168.1.1
I (33121) wifi_prov_mgr: STA Got IP
I (33121) app_wifi: Provisioning successful
I (33131) app_main: RainMaker Claim Started.
I (33131) esp_claim: Starting the Self Claim Process. This may take time.
I (33591) esp-x509-crt-bundle: Certificate validated
I (34231) NimBLE: GAP procedure initiated: stop advertising.

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

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

E (34261) protocomm_nimble: Error setting advertisement data; rc = 30
W (34281) Timer: Timer not stopped
W (34291) Timer: Timer not stopped
I (34311) wifi_prov_mgr: Provisioning stopped
W (34311) BTDM_INIT: esp_bt_mem_release not implemented, return OK
I (34311) wifi_prov_scheme_ble: BTDM memory released
I (34311) esp_rmaker_local: Event 6
E (39101) esp_claim: Invalid response for https://esp-claiming.rainmaker.espressif.com/claim/initiate
E (39101) esp_claim: Status = -1, Data = None
E (39101) esp_claim: Claim Init Request Failed.
E (39101) esp_claim: Claim Init Sequence Failed.
I (39111) app_main: RainMaker Claim Failed.
E (39111) esp_rmaker_core: esp_rmaker_self_claim_perform() returned -1. Aborting
I (39121) esp_rmaker_ota_using_topics: Subscribing to: node/A0764E5A640C/otaurl
W (39131) esp_rmaker_mqtt: esp_rmaker_mqtt_unsubscribe not registered
W (39141) esp_rmaker_mqtt: esp_rmaker_mqtt_subscribe not registered
I (39141) esp_rmaker_ota_using_topics: Fetching OTA details, if any.
W (39151) esp_rmaker_mqtt: esp_rmaker_mqtt_publish not registered
W (39161) esp_rmaker_mqtt: esp_rmaker_mqtt_publish not registered
I (39171) esp_rmaker_user_mapping: MQTT Publish: {"node_id":"A0764E5A640C","user_id":"SignInWithApple_txxxxxxxxxxxxxxxx","secret_key":"xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx","reset":true}
I (40201) wifi:bcn_timout,ap_probe_send_start
I (42701) wifi:ap_probe_send over, resett wifi status to disassoc
I (42701) wifi:state: run -> init (c800)
I (42701) wifi:pm stop, total sleep time: 1396692 us / 10581417 us

W (42701) wifi:<ba-del>idx
I (42711) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (42711) app_wifi: Disconnected. Connecting to the AP again...
I (44771) app_wifi: Disconnected. Connecting to the AP again...
I (44771) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (44771) wifi:state: init -> auth (b0)
I (44781) wifi:state: auth -> assoc (0)
E (44781) wifi:Association refused temporarily, comeback time 1004 mSec
I (45791) wifi:state: assoc -> assoc (0)
E (45791) wifi:Association refused temporarily, comeback time 1004 mSec
I (46801) wifi:state: assoc -> assoc (0)
I (46801) wifi:state: assoc -> init (6c0)
I (46801) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (46801) app_wifi: Disconnected. Connecting to the AP again...
I (48851) app_wifi: Disconnected. Connecting to the AP again...
I (48871) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (48871) wifi:state: init -> auth (b0)
I (49541) wifi:state: auth -> assoc (0)
I (49541) wifi:state: assoc -> run (10)
I (49571) wifi:connected with Jacek, aid = 35, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4
I (49571) wifi:security: WPA3-SAE, phy: bgn, rssi: -55
I (49571) wifi:pm start, type: 1

I (49571) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
W (49631) wifi:<ba-add>idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64
I (49661) wifi:BcnInt:102400, DTIM:3
I (50621) app_wifi: Connected with IP Address:192.168.1.63
I (50621) esp_netif_handlers: sta ip: 192.168.1.63, mask: 255.255.255.0, gw: 192.168.1.1
I (71651) esp_rmaker_time: SNTP Synchronised.
I (71651) esp_rmaker_time: The current time is: Wed Jul 27 22:28:27 2022 +0800[CST], DST: No.

[shahpiyushv]

@jacek12345 , what is the esp-idf version being used? I saw similar failure with the tagged release v4.4.1, but the same works fine with latest release/v4.4 branch. Can you check if it is the same for you?

[jacek12345]

I use v4.4.1. Versioning of ESP-IDF drives me creazy. I don't understand which version is newest and which i should use. I use v4.4.1 with other project also so I am afraid of changing. Additionally, I am not very proficient with github's functions...

[shahpiyushv]

@jacek12345 , v4.4.1 is indeed the latest stable esp-idf release. You can read more about esp-idf versioning here. All v4.4.x releases would be tagged on release/v4.4 branch. The branch has moved ahead from v4.4.1 with new bugfixes and this BLE issue seems one of those. The command to clone this branch is:

git clone -b release/v4.4 --recursive https://github.com/espressif/esp-idf.git

[jcassette]

I had the same issue with ESP-IDF v4.4.1 and now it works with v4.4.2

[jacek12345]

Thank You @shahpiyushv and @jcassette . Now it works with.