Confirming Node Association Failed (MEGH-4123)

[anjalir14]

Hello

I'm using an ESP32-S3 device. I was trying to connect the device with rainmaker but after scanning the QR code and connecting with wifi the app is unable to confirm the node association and it's due to the MQTT.

As you mentioned earlier, add an event handler if it's crashing and rebooting but I'm not having any issues like this.

I'm sharing my logs so please once go through them.

[shahpiyushv]

@anjalir14 , can you share the logs preceding this, specifically the ones mentioning some claiming related messages and the node id too?

[anjalir14]

Now, something new thing is happening . Earlier I was using IDF 5.0 version then I downgrade the version to 4.4.3 now I'm not able to generate QR code and there is no error. following I have attached all my log.

[anjalir14]

After trying on version 5 . This is the logs I'm getting

[anjalir14]

Hello, It's been a long time that i I din't received any answer from your side. so I request you to pls have a look since I'm trying to solve this issue from last 1 week.

Hope for your reply as soon as possible. thank you

[shahpiyushv]

@anjalir14 , in your context, I think the Assisted claiming itself has succeeded but something failed just after that. I would recommend that you reset wifi (long press boot button for more than 3 seconds) and retry provisioning from the phone app. Please do not erase flash, since that will erase the certificate that you got via assisted claiming.

[anjalir14]

Hello Sir,

I tried exactly what you said to me but it's still not happening. I'm getting same error. Firstly the QR code was not generating so from some solution I found that I have to make a little change in main.cpp i.e. (app_wifi_start(MAC)instead of RANDOM we have to change MAC ) after this I was able to create QR code otherwise it was rebooting itself again and again.

Below are my logs after rebooting. W (93562) wifi:idx W (93562) wifi:idx I (93562) wifi:new:<11,0>, old:<11,2>, ap:<255,255>, sta:<11,2>, prof:1 I (93572) app_wifi: Disconnected. Connecting to the AP again... I (93632) wifi:flush txq I (93632) wifi:stop sw txq I (93632) wifi:lmac stop hw txq I (93712) app_main: Rebooting in 2 seconds. ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x3 (RTC_SW_SYS_RST),boot:0x18 (SPI_FAST_FLASH_BOOT) Saved PC:0x40375b45 0x40375b45: esp_restart_noos_dig at /home/dnk067/ESP/esp-idf/components/esp_system/esp_system.c:46 (discriminator 1)

SPIWP:0xee Octal Flash Mode Enabled For OPI Flash, Use Default Flash Boot Mode mode:SLOW_RD, clock div:1 load:0x3fce3810,len:0x167c load:0x403c9700,len:0xbe8 load:0x403cc700,len:0x2ef4 entry 0x403c9904 I (37) boot: ESP-IDF v5.0 2nd stage bootloader I (37) boot: compile time 12:35:42 I (37) boot: chip revision: v0.1 I (38) boot_comm: chip revision: 1, min. bootloader chip revision: 0 I (46) boot.esp32s3: Boot SPI Speed : 80MHz I (50) boot.esp32s3: SPI Mode : SLOW READ I (56) boot.esp32s3: SPI Flash Size : 4MB I (60) boot: Enabling RNG early entropy source... I (66) boot: Partition Table: I (69) boot: ## Label Usage Type ST Offset Length I (77) boot: 0 sec_cert unknown 3f 06 0000d000 00003000 I (84) boot: 1 nvs WiFi data 01 02 00010000 00006000 I (92) boot: 2 otadata OTA data 01 00 00016000 00002000 I (99) boot: 3 phy_init RF data 01 01 00018000 00001000 I (106) boot: 4 ota_0 OTA app 00 10 00020000 00190000 I (114) boot: 5 ota_1 OTA app 00 11 001b0000 00190000 I (122) boot: 6 fctry WiFi data 01 02 00340000 00006000 I (129) boot: End of partition table I (133) boot_comm: chip revision: 1, min. application chip revision: 0 I (141) esp_image: segment 0: paddr=00020020 vaddr=3c0f0020 size=47580h (292224) map I (218) esp_image: segment 1: paddr=000675a8 vaddr=3fc9ba00 size=04f40h ( 20288) load I (223) esp_image: segment 2: paddr=0006c4f0 vaddr=40374000 size=03b28h ( 15144) load I (228) esp_image: segment 3: paddr=00070020 vaddr=42000020 size=e83a8h (951208) map I (456) esp_image: segment 4: paddr=001583d0 vaddr=40377b28 size=13e98h ( 81560) load I (478) esp_image: segment 5: paddr=0016c270 vaddr=50000000 size=00010h ( 16) load I (489) boot: Loaded app from partition at offset 0x20000 I (489) boot: Disabling RNG early entropy source... I (500) cpu_start: Pro cpu up. I (500) cpu_start: Starting app cpu, entry point is 0x403756a4 0x403756a4: call_start_cpu1 at /home/dnk067/ESP/esp-idf/components/esp_system/port/cpu_start.c:142

I (0) cpu_start: App cpu up. I (515) cpu_start: Pro cpu start user code I (515) cpu_start: cpu freq: 160000000 Hz I (515) cpu_start: Application information: I (518) cpu_start: Project name: switch I (523) cpu_start: App version: 1.0 I (528) cpu_start: Compile time: Jan 6 2023 12:35:30 I (534) cpu_start: ELF file SHA256: 14f46be02f08a750... I (540) cpu_start: ESP-IDF: v5.0 I (545) heap_init: Initializing. RAM available for dynamic allocation: I (552) heap_init: At 3FCA72C8 len 00042448 (265 KiB): D/IRAM I (558) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM I (565) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM I (571) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM I (579) spi_flash: detected chip: mxic W (582) spi_flash: Detected flash size > 16 MB, but access beyond 16 MB is not supported for this flash model yet. I (593) spi_flash: flash io: dio W (597) spi_flash: Detected size(32768k) larger than the size in the binary image header(4096k). Using the size in the binary image header. W (610) rmt(legacy): legacy driver is deprecated, please migrate to driver/rmt_tx.h and/or driver/rmt_rx.h I (621) coexist: coexist rom version e7ae62f I (626) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (10) esp_rmaker_console: Initialising UART on port 0 I (647) esp_rmaker_commands: Registering command: up-time I (647) uart: queue free spaces: 8 I (657) esp_rmaker_commands: Registering command: mem-dump I (667) esp_rmaker_commands: Registering command: task-dump I (667) esp_rmaker_commands: Registering command: cpu-dump I (677) esp_rmaker_commands: Registering command: sock-dump I (687) esp_rmaker_commands: Registering command: heap-trace I (687) esp_rmaker_commands: Registering command: reset-to-factory I (697) esp_rmaker_commands: Registering command: add-user I (707) esp_rmaker_commands: Registering command: get-node-id I (707) esp_rmaker_commands: Registering command: wifi-prov I (717) esp_rmaker_commands: Registering command: local-time I (717) esp_rmaker_commands: Registering command: tz-set I (727) esp_rmaker_commands: Registering command: cmd I (737) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 I (747) gpio: GPIO[19]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 I (767) pp: pp rom version: e7ae62f I (767) net80211: net80211 rom version: e7ae62f I (787) wifi:wifi driver task: 3fca7a54, prio:23, stack:6656, core=0 I (787) system_api: Base MAC address is not set I (787) system_api: read default base MAC address from EFUSE I (797) wifi:wifi firmware version: 0d470ef I (797) wifi:wifi certification version: v7.0 I (797) wifi:config NVS flash: enabled I (797) wifi:config nano formating: disabled I (807) wifi:Init data frame dynamic rx buffer num: 32 I (807) wifi:Init management frame dynamic rx buffer num: 32 I (817) wifi:Init management short buffer num: 32 I (817) wifi:Init dynamic tx buffer num: 32 I (827) wifi:Init static tx FG buffer num: 2 I (827) wifi:Init static rx buffer size: 1600 I (827) wifi:Init static rx buffer num: 10 I (837) wifi:Init dynamic rx buffer num: 32 I (837) wifi_init: rx ba win: 6 I (847) wifi_init: tcpip mbox: 32 I (847) wifi_init: udp mbox: 6 I (847) wifi_init: tcp mbox: 6 I (857) wifi_init: tcp tx win: 5744 I (857) wifi_init: tcp rx win: 5744 I (867) wifi_init: tcp mss: 1440 I (867) wifi_init: WiFi IRAM OP enabled I (867) wifi_init: WiFi RX IRAM OP enabled I (887) esp_rmaker_work_queue: Work Queue created. I (887) esp_claim: Initialising Self Claiming. This may take time. W (897) esp_claim: Generating the private key. This may take time. I (2957) app_main: RainMaker Initialised. I (2957) esp_rmaker_node: Node ID ----- 68B6B33CD3D8 I (2967) esp_rmaker_ota_using_topics: OTA enabled with Topics I (2967) esp_rmaker_ota: OTA state = 2 I (2967) esp_rmaker_time_service: Time service enabled I (2977) esp_rmaker_time: Initializing SNTP. Using the SNTP server: pool.ntp.org I (2987) app_insights: Enable CONFIG_ESP_INSIGHTS_ENABLED to get Insights. I (2987) esp_rmaker_core: Starting RainMaker Work Queue task I (2997) esp_rmaker_work_queue: RainMaker Work Queue task started. W (2997) BT_INIT: esp_bt_mem_release not implemented, return OK I (3007) wifi_prov_scheme_ble: BT memory released I (3017) app_wifi: Starting provisioning I (3027) phy_init: phy_version 503,13653eb,Jun 1 2022,17:47:08 W (3027) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration I (3077) wifi:mode : sta (68:b6:b3:3c:d3:d8) I (3077) wifi:enable tsf I (3077) BT_INIT: BT controller compile version [76c24c9] I (3087) BT_INIT: Bluetooth MAC: 68:b6:b3:3c:d3:da

I (3087) protocomm_nimble: BLE Host Task Started I (3097) NimBLE: GAP procedure initiated: stop advertising.

I (3097) NimBLE: GAP procedure initiated: advertise; I (3097) NimBLE: disc_mode=2 I (3107) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=256 adv_itvl_max=256 I (3117) NimBLE:

I (3117) wifi_prov_mgr: Provisioning started with service name : PROV_3cd3d8 I (3127) app_wifi: Provisioning started I (3127) esp_rmaker_local: Event 1 I (3137) app_wifi: Scan this QR code from the ESP RainMaker phone app for Provisioning.

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

I (3337) 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_3cd3d8","pop":"b33cd3d8","transport":"ble"} I (3357) app_main: Provisioning QR : {"ver":"v1","name":"PROV_3cd3d8","pop":"b33cd3d8","transport":"ble"} I (3367) app_wifi: Provisioning Started. Name : PROV_3cd3d8, POP : b33cd3d8 I (3377) app_wifi: Provisioning will auto stop after 30 minute(s). I (19847) NimBLE: GAP procedure initiated: advertise; I (19847) NimBLE: disc_mode=2 I (19847) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=256 adv_itvl_max=256 I (19857) NimBLE:

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

I (46947) NimBLE: GAP procedure initiated: advertise; I (46957) NimBLE: disc_mode=2 I (46957) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=256 adv_itvl_max=256 I (46957) NimBLE:

I (72877) esp_rmaker_user_mapping: Received request for node details I (72877) esp_rmaker_user_mapping: Got user_id = Google_BExsnsibETGiNNa8R5qVbz, secret_key = b49561f1-1422-483d-8755-469b353e6 992 I (72887) esp_rmaker_user_mapping: User Node mapping reset detected. I (72887) esp_rmaker_user_mapping: Sending status SUCCESS I (73487) app_wifi: Received Wi-Fi credentials SSID : NetweeN Password : Quickreplyme I (76907) wifi:new:<11,2>, old:<1,0>, ap:<255,255>, sta:<11,2>, prof:1 I (77887) wifi:state: init -> auth (b0) I (77887) wifi:state: auth -> assoc (0) I (77897) wifi:state: assoc -> run (10) I (77967) wifi:connected with NetweeN, aid = 2, channel 11, 40D, bssid = 90:8d:78:76:27:00

77967) wifi:security: WPA2-PSK, phy: bgn, rssi: -30 I (77997) wifi:pm start, type: 1

I (77997) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000 I (77997) wifi:BcnInt:102400, DTIM:1 W (78017) wifi:idx:0 (ifx:0, 90:8d:78:76:27:00), tid:0, ssn:2, winSize:64 I (79267) app_wifi: Connected with IP Address:192.168.0.13 I (79267) esp_netif_handlers: sta ip: 192.168.0.13, mask: 255.255.255.0, gw: 192.168.0.1 I (79267) wifi_prov_mgr: STA Got IP I (79267) app_wifi: Provisioning successful I (79277) esp_claim: Starting the Self Claim Process. This may take time. I (79277) app_main: RainMaker Claim Started. I (81067) esp-x509-crt-bundle: Certificate validated I (81937) NimBLE: GAP procedure initiated: stop advertising.

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

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

E (82007) protocomm_nimble: Error setting advertisement data; rc = 30 I (82067) wifi_prov_mgr: Provisioning stopped W (82067) BT_INIT: esp_bt_mem_release not implemented, return OK I (82067) wifi_prov_scheme_ble: BTDM memory released I (82067) esp_rmaker_local: Event 6 W (82407) wifi:idx:1 (ifx:0, 90:8d:78:76:27:00), tid:1, ssn:0, winSize:64 I (82407) esp_rmaker_time: SNTP Synchronised. I (82407) esp_rmaker_time: The current time is: Fri Jan 6 15:10:22 2023 +0800[CST], DST: No. I (82427) HTTP_CLIENT: Body received in fetch header state, 0x3fcf365d, 129 I (82617) esp-x509-crt-bundle: Certificate validated I (85087) HTTP_CLIENT: Body received in fetch header state, 0x3fcf3406, 502 I (85097) esp_claim: Self Claiming was successful. Certificate received. I (85097) app_main: RainMaker Claim Successful. E (85097) esp_rmaker_core: Failed to initialise MQTT Config after claiming. Aborting I (85107) esp_rmaker_ota_using_topics: Subscribing to: node/68B6B33CD3D8/otaurl W (85117) esp_rmaker_mqtt: esp_rmaker_mqtt_unsubscribe not registered W (85127) esp_rmaker_mqtt: esp_rmaker_mqtt_subscribe not registered W (85127) esp_rmaker_mqtt_budget: MQTT budgeting not started yet. Allowing publish. W (85137) esp_rmaker_mqtt: esp_rmaker_mqtt_publish not registered I (85147) esp_rmaker_user_mapping: MQTT Publish: {"node_id":"68B6B33CD3D8","user_id":"Google_BExsnsibETGiNNa8R5qVbz","secret_k ey":"b49561f1-1422-483d-8755-469b353e6992","reset":true} I (90127) esp_rmaker_ota_using_topics: Fetching OTA details, if any. W (90127) esp_rmaker_mqtt_budget: MQTT budgeting not started yet. Allowing publish. W (90127) esp_rmaker_mqtt: esp_rmaker_mqtt_publish not registered

Waiting for your reply as soon as possible.

[shahpiyushv]

@anjalir14, your earlier log had Assisted Claiming and the new one has Self Claiming. So I guess you have changed the config and probably also erase the flash, else the claiming wouldn't have started again. As mentioned earlier, can you just reset wifi and retry? Meanwhile, we will check why the device is getting this error E (85097) esp_rmaker_core: Failed to initialise MQTT Config after claiming. Aborting. That is causing the failures you see.

[anjalir14]

Hello @shahpiyushv I tried everything that has been mentioned but still MQTT is not intializating. Actually I'm running on my deadline of the project, so I would like you to pls check this . Can you pls let me know when this issue is going to solve as my deadline of project is very close. Hoping to get your answer as soon as possible

[sanketwadekar]

Hi, Can you specify your branch and commit hash of IDF and Rainmaker repos ?

[shahpiyushv]

@anjalir14 , it would have really helped if logs for the boot cycle after this (with only wifi credentials reset) were shared. Since both the logs are with device booting up in unclaimed state, it is hard to tell why things may not have worked even during the subsequent boot cycles when the node was already claimed. The issue with claiming indeed looks to be some issue, but atleast pre-claimed nodes should work fine.

Meanwhike, as asked above, please share the branch and commit hash of IDF and Rainmaker repos.

[shahpiyushv]

@anjalir14 , can you check if the suggestion provided here solves the issue for you? https://github.com/espressif/esp-rainmaker/issues/221#issuecomment-1381420160

[shahpiyushv]

Closing this issue since no response was received.