OTA job failed if NimBle enabled (MEGH-4122)

[jacek12345]

I use ESP32-C3 and trying OTA update. OTA job ends with success since there is not NimBle initialisation in working code. When i enable NimBle, OTA job fails. I use NimBle for communicate with BLE sensors. I enable Nimble: ESP_ERROR_CHECK(esp_nimble_hci_and_controller_init()); nimble_port_init(); //Initialize the NimBLE host configuration. ble_hs_cfg.reset_cb = bleprph_on_reset; ble_hs_cfg.sync_cb = bleprph_on_sync; nimble_port_freertos_init(bleprph_host_task);

Than while OTA job i have this: `I (30) boot: ESP-IDF v4.4.3 2nd stage bootloader I (30) boot: compile time 07:52:06 I (30) boot: chip revision: 3 I (32) boot.esp32c3: SPI Speed : 80MHz I (37) boot.esp32c3: SPI Mode : DIO I (41) boot.esp32c3: SPI Flash Size : 4MB I (46) boot: Enabling RNG early entropy source... I (52) boot: Partition Table: I (55) boot: ## Label Usage Type ST Offset Length I (62) boot: 0 sec_cert unknown 3f 06 0000d000 00003000 I (70) boot: 1 nvs WiFi data 01 02 00010000 00006000 I (77) boot: 2 otadata OTA data 01 00 00016000 00002000 I (85) boot: 3 phy_init RF data 01 01 00018000 00001000 I (92) boot: 4 ota_0 OTA app 00 10 00020000 00190000 I (100) boot: 5 ota_1 OTA app 00 11 001b0000 00190000 I (107) boot: 6 fctry WiFi data 01 02 00340000 00006000 I (115) boot: 7 devdata WiFi data 01 02 00346000 00003000 I (122) boot: 8 coredump Unknown data 01 03 00349000 00010000 I (130) boot: End of partition table I (134) esp_image: segment 0: paddr=00020020 vaddr=3c110020 size=3e8b8h (256184) map I (183) esp_image: segment 1: paddr=0005e8e0 vaddr=3fc94000 size=01738h ( 5944) load I (184) esp_image: segment 2: paddr=00060020 vaddr=42000020 size=106284h (1073796) map I (356) esp_image: segment 3: paddr=001662ac vaddr=3fc95738 size=016b0h ( 5808) load I (358) esp_image: segment 4: paddr=00167964 vaddr=40380000 size=13fc0h ( 81856) load I (377) esp_image: segment 5: paddr=0017b92c vaddr=50000010 size=00010h ( 16) load I (383) boot: Loaded app from partition at offset 0x20000 I (384) boot: Disabling RNG early entropy source... I (397) cpu_start: Pro cpu up. I (406) cpu_start: Pro cpu start user code I (406) cpu_start: cpu freq: 160000000 I (406) cpu_start: Application information: I (409) cpu_start: Project name: switch I (414) cpu_start: App version: 2.7 I (418) cpu_start: Compile time: Dec 23 2022 15:06:08 I (425) cpu_start: ELF file SHA256: 2d2402b581a85610... I (430) cpu_start: ESP-IDF: v4.4.3 I (435) heap_init: Initializing. RAM available for dynamic allocation: I (443) heap_init: At 3FC9E7F0 len 0003DF20 (247 KiB): DRAM I (449) heap_init: At 3FCDC710 len 00002950 (10 KiB): STACK/DRAM I (456) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM I (462) spi_flash: detected chip: generic I (467) spi_flash: flash io: dio I (471) sleep: Configure to isolate all GPIO pins in sleep state I (477) sleep: Enable automatic switching of GPIO sleep configuration I (484) cpu_start: Starting scheduler. I (489) esp_rmaker_console: Initialising UART on port 0 I (489) uart: queue free spaces: 8 I (499) esp_rmaker_commands: Registering command: up-time I (499) esp_rmaker_commands: Registering command: mem-dump I (509) esp_rmaker_commands: Registering command: task-dump I (509) esp_rmaker_commands: Registering command: cpu-dump I (519) esp_rmaker_commands: Registering command: sock-dump I (529) esp_rmaker_commands: Registering command: heap-trace I (529) esp_rmaker_commands: Registering command: reset-to-factory I (539) esp_rmaker_commands: Registering command: add-user I (549) esp_rmaker_commands: Registering command: get-node-id I (549) esp_rmaker_commands: Registering command: wifi-prov I (559) esp_rmaker_commands: Registering command: local-time I (559) esp_rmaker_commands: Registering command: tz-set I (569) esp_rmaker_commands: Registering command: cmd I (579) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 E (589) gpio: gpio_install_isr_service(449): GPIO isr service already installed I (589) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 W (619) app_main: reading configuration from NVS I (619) pp: pp rom version: 9387209 I (619) net80211: net80211 rom version: 9387209 I (629) wifi:wifi driver task: 3fcaab58, prio:23, stack:6656, core=0 I (629) system_api: Base MAC address is not set I (629) system_api: read default base MAC address from EFUSE I (639) wifi:wifi firmware version: 8cb87ff I (639) wifi:wifi certification version: v7.0 I (639) wifi:config NVS flash: enabled I (649) wifi:config nano formating: disabled I (649) wifi:Init data frame dynamic rx buffer num: 32 I (659) wifi:Init management frame dynamic rx buffer num: 32 I (659) wifi:Init management short buffer num: 32 I (669) wifi:Init dynamic tx buffer num: 32 I (669) wifi:Init static tx FG buffer num: 2 I (669) wifi:Init static rx buffer size: 1600 I (679) wifi:Init static rx buffer num: 10 I (679) wifi:Init dynamic rx buffer num: 32 I (689) wifi_init: rx ba win: 6 I (689) wifi_init: tcpip mbox: 32 I (689) wifi_init: udp mbox: 6 I (699) wifi_init: tcp mbox: 6 I (699) wifi_init: tcp tx win: 5744 I (709) wifi_init: tcp rx win: 5744 I (709) wifi_init: tcp mss: 1440 I (709) wifi_init: WiFi IRAM OP enabled I (719) wifi_init: WiFi RX IRAM OP enabled I (729) esp_rmaker_work_queue: Work Queue created. I (729) esp_mqtt_glue: AWS PPI: ?Platform=APN3|A0|RM|EX00|RMDev|1x0|A0764E5AE100 I (739) esp_mqtt_glue: Initialising MQTT I (739) esp_rmaker_mqtt_budget: MQTT Budgeting initialised. Default: 100, Max: 1024, Revive count: 1, Revive period: 5 I (749) app_main: RainMaker Initialised. I (759) esp_rmaker_node: Node ID ----- A0764E5AE100 E (759) gpio: gpio_install_isr_service(449): GPIO isr service already installed I (769) gpio: GPIO[5]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 I (779) esp_rmaker_ota_using_topics: OTA enabled with Topics I (789) esp_rmaker_ota: OTA state = 2 I (789) esp_rmaker_time_service: Time service enabled I (799) esp_rmaker_time: Initializing SNTP. Using the SNTP server: pool.ntp.org I (809) app_insights: Enable CONFIG_ESP_INSIGHTS_ENABLED to get Insights. I (809) esp_rmaker_core: Starting RainMaker Work Queue task I (819) esp_rmaker_work_queue: RainMaker Work Queue task started. W (829) BTDM_INIT: esp_bt_mem_release not implemented, return OK I (829) wifi_prov_scheme_ble: BT memory released I (839) app_wifi: Already provisioned, starting Wi-Fi STA W (839) BTDM_INIT: esp_bt_mem_release not implemented, return OK I (849) wifi_prov_scheme_ble: BTDM memory released I (859) esp_rmaker_local: Event 6 I (859) phy_init: phy_version 912,d001756,Jun 2 2022,16:28:07 I (889) wifi:mode : sta (a0:76:4e:5a:e1:00) I (899) wifi:enable tsf I (899) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1 I (899) wifi:state: init -> auth (b0) I (1619) wifi:state: auth -> assoc (0) I (1629) wifi:state: assoc -> run (10) I (11629) wifi:state: run -> init (cc00) I (11629) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1 I (11629) app_wifi: Disconnected. Connecting to the AP again... I (14039) app_wifi: Disconnected. Connecting to the AP again... I (14049) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1 I (14049) wifi:state: init -> auth (b0) I (14779) wifi:state: auth -> assoc (0) I (14789) wifi:state: assoc -> run (10) I (14809) wifi:connected with Jacek, aid = 22, channel 11, BW20, bssid = e8:d2:ff:59:9c:a4 I (14819) wifi:security: WPA3-SAE, phy: bgn, rssi: -71 I (14819) wifi:pm start, type: 1

I (14819) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 0, mt_pti: 25000, mt_time: 10000 I (14869) wifi:BcnInt:102400, DTIM:3 W (14869) wifi:idx:0 (ifx:0, e8:d2:ff:59:9c:a4), tid:0, ssn:1, winSize:64 I (15619) app_wifi: Connected with IP Address:192.168.1.62 I (15619) esp_netif_handlers: sta ip: 192.168.1.62, mask: 255.255.255.0, gw: 192.168.1.1 I (15619) esp_rmaker_local: Starting ESP Local control with HTTP Transport and security version: 1 W (15629) app_main: ########## APP_WIFI_PROV_TRANSPORT_BLE ######## I (15649) esp_https_server: Starting server I (15649) esp_https_server: Server listening on port 8080 I (15649) esp_rmaker_local: esp_local_ctrl service started with name : A0764E5AE100 W (15659) app_main: Unhandled RainMaker Event: 6 I (15659) esp_mqtt_glue: Connecting to a1p72mufdu6064-ats.iot.us-east-1.amazonaws.com I (15669) esp_rmaker_core: Waiting for MQTT connection I (16289) esp-x509-crt-bundle: Certificate validated I (17749) esp_mqtt_glue: MQTT Connected I (17749) app_main: MQTT Connected. I (17759) esp_rmaker_node_config: Reporting Node Configuration of length 4592 bytes. I (17929) esp_rmaker_param: Params MQTT Init done. I (17939) esp_rmaker_param: Reporting params (init): {"OUT 1":{"Name":"1","Stan":0,"Czas [ms]":0,"Powiadom przy zalaczeniu":false,"Powiadom przy wylaczeniu":false,"Odwroc logike":false},"OUT 2":{"Name":"Lock 2","Stan":0,"Czas [ms]":1000,"Powiadom przy zalaczeniu":false,"Powiadom przy wylaczeniu":false,"Odwroc logike":false},"IN 1":{"Name":"IN 1","Stan":"ON","Min. czas pobudzenia [s]":0,"Powiadom gdy aktywne":false,"Powiadom gdy nieaktywne":false,"Odwroc logike":false},"MENU_SCAN":{"Wykryj nowe czujniki":false},"MENU_NODE":{"Nazwa urzadzenia":"Odbiornik bramowy","Ukryj komponent OUT 1":false,"Ukryj komponent OUT 2":false,"Ukryj komponent IN 1":false},"Time":{"TZ":"Europe/Warsaw","TZ-POSIX":"CET-1CEST,M3.5.0,M10.5.0/3"},"Schedule":{"Schedules":[]},"Scenes":{"Scenes":[]},"Local Control":{"POP":"acce93c9","Type":1}} I (18009) esp_rmaker_cmd_resp: Enabling Command-Response Module. I (18089) esp_rmaker_ota_using_topics: Subscribing to: node/A0764E5AE100/otaurl I (18359) app_main: MQTT Published. Msg id: 12252. I (18489) app_main: MQTT Published. Msg id: 58315. I (23089) esp_rmaker_ota_using_topics: Fetching OTA details, if any. I (23589) app_main: MQTT Published. Msg id: 1977. I (23719) esp_rmaker_ota_using_topics: Upgrade Handler got:{"url":"https://esp-rainmaker-ota-315787942180-prod.s3.us-east-1.amazonaws.com/users/Github_bo9mZhi2hGExdZfPxXJNFi/firmwareimages/M4fZcmpVg/test28.bin?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIAUTBTNTESIUU4TA5T%2F20221223%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20221223T141944Z&X-Amz-Expires=86400&X-Amz-Security-Token=FwoGZXIvYXdzEJj%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FwEaDJrNB6ucE6SfKbsPCSLRApuBFc8ndjephwKlamDXR8WTcnP72VDoq4k5la%2FL7wKqZOQAS9WbDXH0vHV1%2B4RZE8C%2FWg8rCnkouh93CzhipkRCv1pHaeqOYhjM%2BHe0ld7ZiwXxtgWpacJwtrYMv%2B2Pnbxw80BnoPDmtEVcMDXWV6NNT6p4cTdFdYveadbR7jCgYCYMUjI%2B3rZOHrXujpQF60IsnndhlujTt5hdIvHaIcejm7dIp4sg0qO0cYwD2xbCdnAQ%2FK5aHTS7hUQaE%2FNBIgGBzpXw%2FVG4N20oImnyW7g6im61v73cebkZoePrj3hqgxghyQZrrzqr4z0014JP63CRFcddJd3EN3ulA7uOmFr2LHLKwhLAmy9dmwgfAxbzI8j0GJ1KmJ2PmQhNHDkkBuwoi5reLbWoqOcWoIL1Y7H6KZRXM1Wf0zY%2FOSV4Csa17tZHGDcu%2FbxDhVQugS0P9%2BwogPKWnQYyLQgscOLY3Ejc1lg8iSrA2pxJVSKoNEqbLhSsO8w%2FY%2Fetd%2F4EBx0TgB8tCCaUpg%3D%3D&X-Amz-SignedHeaders=host&X-Amz-Signature=4215244d1df7b4f391d1e84e7814e86811f7cf147fa437cdc7055fb65d47cf70","fw_version":"2.8","ota_job_id":"6DfAeBS7UKJWD4GXRzKoYC","file_size":1431632,"stream_id":"oWvwYMMsRHZyGdCEkBdweq"} on node/A0764E5AE100/otaurl topic

I (23819) esp_rmaker_ota_using_topics: OTA Job ID: 6DfAeBS7UKJWD4GXRzKoYC I (23829) esp_rmaker_ota_using_topics: URL: https://esp-rainmaker-ota-315787942180-prod.s3.us-east-1.amazonaws.com/users/Github_bo9mZhi2hGExdZfPxXJNFi/firmwareimages/M4fZcmpVg/test28.bin?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIAUTBTNTESIUU4TA5T%2F20221223%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20221223T141944Z&X-Amz-Expires=86400&X-Amz-Security-Token=FwoGZXIvYXdzEJj%2F%2F%2F%2F%2F%2F%2F%2F%2F%2FwEaDJrNB6ucE6SfKbsPCSLRApuBFc8ndjephwKlamDXR8WTcnP72VDoq4k5la%2FL7wKqZOQAS9WbDXH0vHV1%2B4RZE8C%2FWg8rCnkouh93CzhipkRCv1pHaeqOYhjM%2BHe0ld7ZiwXxtgWpacJwtrYMv%2B2Pnbxw80BnoPDmtEVcMDXWV6NNT6p4cTdFdYveadbR7jCgYCYMUjI%2B3rZOHrXujpQF60IsnndhlujTt5hdIvHaIcejm7dIp4sg0qO0cYwD2xbCdnAQ%2FK5aHTS7hUQaE%2FNBIgGBzpXw%2FVG4N20oImnyW7g6im61v73cebkZoePrj3hqgxghyQZrrzqr4z0014JP63CRFcddJd3EN3ulA7uOmFr2LHLKwhLAmy9dmwgfAxbzI8j0GJ1KmJ2PmQhNHDkkBuwoi5reLbWoqOcWoIL1Y7H6KZRXM1Wf0zY%2FOSV4Csa17tZHGDcu%2FbxDhVQugS0P9%2BwogPKWnQYyLQgscOLY3Ejc1lg8iSrA2pxJVSKoNEqbLhSsO8w%2FY%2Fetd%2F4EBx0TgB8tCCaUpg%3D%3D&X-Amz-SignedHeaders=host&X-Amz-Signature=4215244d1df7b4f391d1e84e7814e86811f7cf147fa437cdc7055fb65d47cf70 I (23929) esp_rmaker_ota_using_topics: File Size: 1431632 I (23929) esp_rmaker_ota_using_topics: Firmware version: 2.8 I (23939) esp_rmaker_ota: Reporting in-progress: Starting OTA Upgrade I (23949) esp_rmaker_ota_using_topics: {"ota_job_id":"6DfAeBS7UKJWD4GXRzKoYC","status":"in-progress","additional_info":"Starting OTA Upgrade"} W (23959) esp_rmaker_ota: Starting OTA. This may take time. I (24869) app_main: MQTT Published. Msg id: 54046. I (24899) esp-x509-crt-bundle: Certificate validated I (26359) esp_https_ota: Starting OTA... I (26359) esp_https_ota: Writing to partition subtype 17 at offset 0x1b0000 I (26359) wifi:Set ps type: 0

I (26369) esp_rmaker_ota: Reporting in-progress: Downloading Firmware Image I (26369) esp_rmaker_ota_using_topics: {"ota_job_id":"6DfAeBS7UKJWD4GXRzKoYC","status":"in-progress","additional_info":"Downloading Firmware Image"} I (26589) app_main: MQTT Published. Msg id: 14319. I (28279) esp_rmaker_ota: Image bytes read: 50465 I (30169) esp_rmaker_ota: Image bytes read: 101665 I (32089) esp_rmaker_ota: Image bytes read: 152865 I (33979) esp_rmaker_ota: Image bytes read: 204065 I (34929) esp_rmaker_time: SNTP Synchronised. I (34939) esp_rmaker_time: The current time is: Fri Dec 23 15:19:56 2022 +0100[CET], DST: No. W (35639) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK I (35639) BTDM_INIT: BT controller compile version [421c279] I (35639) BTDM_INIT: Bluetooth MAC: a0:76:4e:5a:e1:02

I (35649) app_main: BLE Host Task Started I (35649) NimBLE: GAP procedure initiated: stop advertising.

I (35659) NimBLE: GAP procedure initiated: discovery; I (35659) NimBLE: own_addr_type=2 filter_policy=0 passive=1 limited=0 filter_duplicates=0 I (35669) NimBLE: duration=forever I (35679) NimBLE:

I (36139) esp_rmaker_ota: Image bytes read: 255265 I (39219) esp_rmaker_ota: Image bytes read: 306465 E (39389) Dynamic Impl: alloc(16749 bytes) failed E (39389) esp-tls-mbedtls: read error :-0x7F00: E (39389) TRANSPORT_BASE: esp_tls_conn_read error, errno=Success E (39389) esp-tls-mbedtls: read error :-0x7200: E (39399) TRANSPORT_BASE: esp_tls_conn_read error, errno=Success E (39409) esp_https_ota: data read -1, errno 0 E (39409) esp_rmaker_ota: ESP_HTTPS_OTA upgrade failed ESP_FAIL I (39419) esp_rmaker_ota: Reporting failed: OTA failed: Error ESP_FAIL I (39419) esp_rmaker_ota_using_topics: {"ota_job_id":"6DfAeBS7UKJWD4GXRzKoYC","status":"failed","additional_info":"OTA failed: Error ESP_FAIL"} E (39439) esp_rmaker_ota: Complete data was not received. I (39439) esp_image: segment 0: paddr=001b0020 vaddr=3c110020 size=3ed70h (257392) map I (39489) esp_image: segment 1: paddr=001eed98 vaddr=3fc94200 size=01280h ( 4736) I (39489) esp_image: segment 2: paddr=001f0020 vaddr=42000020 size=107c68h (1080424) map I (39629) esp_image: segment 3: paddr=002f7c90 vaddr=3fc95480 size=01b70h ( 7024) I (39629) esp_image: segment 4: paddr=002f9808 vaddr=40380000 size=1400ch ( 81932) I (39649) esp_image: segment 5: paddr=0030d81c vaddr=50000010 size=00010h ( 16) E (39649) esp_image: Checksum failed. Calculated 0x48 read 0xe5 E (39649) esp_rmaker_ota: Image validation failed, image is corrupted I (39659) esp_rmaker_ota: Reporting failed: Image validation failed I (39659) esp_rmaker_ota_using_topics: {"ota_job_id":"6DfAeBS7UKJWD4GXRzKoYC","status":"failed","additional_info":"Image validation failed"} I (39979) app_main: MQTT Published. Msg id: 38621. I (40129) app_main: MQTT Published. Msg id: 42449.`

[sanketwadekar]

This error E (39389) esp-tls-mbedtls: read error :-0x7F00: means that your device has less memory. Events have been added to OTA which allows you to execute your custom code. You can try turning off BLE on RMAKER_OTA_EVENT_STARTING event.

[jacek12345]

Thank You @sanketwadekar Done like You said. Also will change module to bigger, since now have 4MB Flash only. Can You clarify if it is due to small FLASH, ROM or SRAM?

[sanketwadekar]

The error is caused by low “Heap Memory” at runtime, which means that the RAM is insufficient.

On 31-Dec-2022, at 2:51 PM, jacek12345 @.***> wrote:

Thank You @sanketwadekar https://github.com/sanketwadekar Done like You said. Also will change module to bigger, since now have 4MB Flash only. Can You clarify if it is due to small FLASH, ROM or SRAM?

— Reply to this email directly, view it on GitHub https://github.com/espressif/esp-rainmaker/issues/213#issuecomment-1368190015, or unsubscribe https://github.com/notifications/unsubscribe-auth/AP73YOGF5J2LQJJFT6OW7B3WP73ITANCNFSM6AAAAAATHZLQSU. You are receiving this because you were mentioned.

[jacek12345]

Thank You @sanketwadekar