espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.85k stars 7.32k forks source link

Wifi : "wifi:m f null" losing connection. (IDFGH-11313) #12464

Closed MarkMendelsohn closed 11 months ago

MarkMendelsohn commented 1 year ago

Answers checklist.

IDF version.

v5.1-2-g8ec4d423f0

Espressif SoC revision.

Chip is ESP32-S3 (QFN56) (revision v0.1)

Operating System used.

macOS

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32-S3-DevKitC-1

Power Supply used.

USB

What is the expected behavior?

During communications with AWS over Wifi

145104 W (3381716) wifi:m f null

Previously reported here with no resolution

Wifi : "wifi:m f null" losing connection. (IDFGH-9263) #10646

What is the actual behavior?

connection to AP is lost and the program can't detect

Steps to reproduce.

Running a modified esp-aws-iot ota sample.

Debug Logs.

No response

More Information.

No response

AxelLin commented 1 year ago

FYI, https://github.com/espressif/esp-idf/issues/11615#issuecomment-1778431394

Espressif-liuuuu commented 1 year ago

Hi @MarkMendelsohn , sorry but I didnt find v5.1-2-g8ec4d423f0, could you pls have a check?

MarkMendelsohn commented 1 year ago

This was generated by the command to pull this info that was present in the instructions. This is essentially the tag v.5.1 which seems to be one commit past release/v5.1

Espressif-liuuuu commented 1 year ago

This was generated by the command to pull this info that was present in the instructions. This is essentially the tag v.5.1 which seems to be one commit past release/v5.1

then exactly which commit on v5.1?

MarkMendelsohn commented 1 year ago

commit cbce221e88d52665523093b2b6dd0ebe3f1243f1 (tag: v5.1) Merge: c570f67461 e44a6888ea Author: Jiang Jiang Jian jack@espressif.com Date: Wed Jun 28 17:33:53 2023 +0800

Espressif-liuuuu commented 1 year ago

commit cbce221 (tag: v5.1) Merge: c570f67 e44a688 Author: Jiang Jiang Jian jack@espressif.com Date: Wed Jun 28 17:33:53 2023 +0800

thanks. And yes pls update to https://github.com/espressif/esp-idf/commit/78ae4c3b8e37f69c4aab0ab9d66d4779caca5abe or the lastest release/v5.1 to have a try, m f null may stiil happen while station would be in response.

MarkMendelsohn commented 1 year ago

Ok. Trying now

MarkMendelsohn commented 1 year ago

Tested the new release/v5.1 from Oct 20, but the issue has reappeared.

258977 W (4681685) wifi:m f null^M

Espressif-liuuuu commented 1 year ago

Tested the new release/v5.1 from Oct 20, but the issue has reappeared.

258977 W (4681685) wifi:m f null^M

Did the m f null show up for many times or just one time? Then did you still get connection lost? And whats the type of your connection lost? Was it station disconnected (there was INFO log shown like run -> init or pm stop) or just unreachable (like no TCP ACK package from station)?

MarkMendelsohn commented 1 year ago

W (4681685) wifi:m f null I (4708055) wifi:state: run -> init (4c0) I (4708065) wifi:pm stop, total sleep time: 4078743950 us / 4698969776 us I (4708075) wifi:idx:1, tid:0 I (4708075) wifi:idx:0, tid:7 I (4708075) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1

MarkMendelsohn commented 1 year ago

here is another more complete example

2 I (7820) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
4 I (8880) wifi:state: init -> auth (b0)

12 I (8890) wifi:state: auth -> assoc (0) 16 I (8890) wifi:state: assoc -> run (10) 27 I (8920) wifi:connected with bonneau, aid = 16, channel 1, BW20, bssid = f0:7b:65:42:c6:43 28 I (8920) wifi:security: WPA2-PSK, phy: bgn, rssi: -61 29 I (9070) wifi:pm start, type: 1 31 I (9070) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000 32 I (9070) wifi:AP's beacon interval = 102400 us, DTIM period = 2 33 I (9120) wifi:idx:0 (ifx:0, f0:7b:65:42:c6:43), tid:7, ssn:1, winSize:64 128 I (14240) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 26975 I (875900) wifi:bcn_timeout,ap_probe_send_start 27015 W (876900) wifi:m f null 27070 I (878400) wifi:ap_probe_send over, resett wifi status to disassoc 27071 I (878400) wifi:state: run -> init (c800) 27072 I (878400) wifi:pm stop, total sleep time: 733594869 us / 869329427 us 27074 I (878400) wifi:idx:1, tid:0 27075 I (878410) wifi:idx:0, tid:7 27076 I (878410) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 27232 I (881800) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 27233 I (881800) wifi:state: init -> auth (b0) 27234 I (881810) wifi:state: auth -> assoc (0) 27235 I (881810) wifi:state: assoc -> run (10) 27236 I (881830) wifi:connected with bonneau, aid = 14, channel 1, BW20, bssid = f0:7b:65:42:c6:43 27237 I (881830) wifi:security: WPA2-PSK, phy: bgn, rssi: -57 27238 I (881840) wifi:pm start, type: 1 27240 I (881840) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000 27241 I (881850) wifi:idx:0 (ifx:0, f0:7b:65:42:c6:43), tid:7, ssn:1, winSize:64 27242 I (881880) wifi:AP's beacon interval = 102400 us, DTIM period = 2 27315 I (884850) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 27315 I (884850) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 27317 27318 E (884990) esp-tls-mbedtls: mbedtls_ssl_setup returned -0x7F00 27319 E (884990) esp-tls: create_ssl_handle failed 27320 E (884990) esp-tls: Failed to open new connection 27321 Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. 27322 27323 Core 0 register dump: 27324 PC : 0x4210c7bc PS : 0x00060930 A0 : 0x8201271c A1 : 0x3fcccc30 27325 A2 : 0x00000000 A3 : 0x3fcb25d4 A4 : 0x00001080 A5 : 0x00000001 27326 A6 : 0xb33fffff A7 : 0xb33fffff A8 : 0x00000700 A9 : 0x3fcccbf0 27327 A10 : 0x00000000 A11 : 0x00060b20 A12 : 0x00000000 A13 : 0x00060b23 27328 A14 : 0xb33fffff A15 : 0xb33fffff SAR : 0x00000004 EXCCAUSE: 0x0000001c 27329 EXCVADDR: 0x0000072c LBEG : 0x400556d5 LEND : 0x400556e5 LCOUNT : 0xfffffffc 27330 27331 27332 Backtrace: 0x4210c7b9:0x3fcccc30 0x42012719:0x3fcccc50 0x42012346:0x3fcccc70 0x4201250a:0x3fcccca0 0x4200dc6f:0x3fccccc0 0x4200e8df:0x 3fcccd20 0x4200ce7f:0x3fcccd40 0x4200f182:0x3fcccd80 0x420043f0:0x3fcccda0 0x40384791:0x3fcccdc0

Espressif-liuuuu commented 1 year ago

here is another more complete example

2 I (7820) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
4 I (8880) wifi:state: init -> auth (b0)

12 I (8890) wifi:state: auth -> assoc (0) 16 I (8890) wifi:state: assoc -> run (10) 27 I (8920) wifi:connected with bonneau, aid = 16, channel 1, BW20, bssid = f0:7b:65:42:c6:43 28 I (8920) wifi:security: WPA2-PSK, phy: bgn, rssi: -61 29 I (9070) wifi:pm start, type: 1 31 I (9070) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000 32 I (9070) wifi:AP's beacon interval = 102400 us, DTIM period = 2 33 I (9120) wifi:idx:0 (ifx:0, f0:7b:65:42:c6:43), tid:7, ssn:1, winSize:64 128 I (14240) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 26975 I (875900) wifi:bcn_timeout,ap_probe_send_start 27015 W (876900) wifi:m f null 27070 I (878400) wifi:ap_probe_send over, resett wifi status to disassoc 27071 I (878400) wifi:state: run -> init (c800) 27072 I (878400) wifi:pm stop, total sleep time: 733594869 us / 869329427 us 27074 I (878400) wifi:idx:1, tid:0 27075 I (878410) wifi:idx:0, tid:7 27076 I (878410) wifi🆕<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 27232 I (881800) wifi🆕<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 27233 I (881800) wifi:state: init -> auth (b0) 27234 I (881810) wifi:state: auth -> assoc (0) 27235 I (881810) wifi:state: assoc -> run (10) 27236 I (881830) wifi:connected with bonneau, aid = 14, channel 1, BW20, bssid = f0:7b:65:42:c6:43 27237 I (881830) wifi:security: WPA2-PSK, phy: bgn, rssi: -57 27238 I (881840) wifi:pm start, type: 1 27240 I (881840) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000 27241 I (881850) wifi:idx:0 (ifx:0, f0:7b:65:42:c6:43), tid:7, ssn:1, winSize:64 27242 I (881880) wifi:AP's beacon interval = 102400 us, DTIM period = 2 27315 I (884850) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 27315 I (884850) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 27317 27318 E (884990) esp-tls-mbedtls: mbedtls_ssl_setup returned -0x7F00 27319 E (884990) esp-tls: create_ssl_handle failed 27320 E (884990) esp-tls: Failed to open new connection 27321 Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. 27322 27323 Core 0 register dump: 27324 PC : 0x4210c7bc PS : 0x00060930 A0 : 0x8201271c A1 : 0x3fcccc30 27325 A2 : 0x00000000 A3 : 0x3fcb25d4 A4 : 0x00001080 A5 : 0x00000001 27326 A6 : 0xb33fffff A7 : 0xb33fffff A8 : 0x00000700 A9 : 0x3fcccbf0 27327 A10 : 0x00000000 A11 : 0x00060b20 A12 : 0x00000000 A13 : 0x00060b23 27328 A14 : 0xb33fffff A15 : 0xb33fffff SAR : 0x00000004 EXCCAUSE: 0x0000001c 27329 EXCVADDR: 0x0000072c LBEG : 0x400556d5 LEND : 0x400556e5 LCOUNT : 0xfffffffc 27330 27331 27332 Backtrace: 0x4210c7b9:0x3fcccc30 0x42012719:0x3fcccc50 0x42012346:0x3fcccc70 0x4201250a:0x3fcccca0 0x4200dc6f:0x3fccccc0 0x4200e8df:0x 3fcccd20 0x4200ce7f:0x3fcccd40 0x4200f182:0x3fcccd80 0x420043f0:0x3fcccda0 0x40384791:0x3fcccdc0

Thanks for the info. It looks like a issue about short of memory. Lets check 3 things
1) pls provide us with your sdkconfig, some configuratio may be inappropriate 2) pls call esp_get_free_heap_size esp_get_free_internal_heap_size esp_get_minimum_free_heap_size and dump the return value at the moment you lose connection, to make sure this is a memory issue 3) pls call esp_wifi_statis_dump(0xffff) at the moment you lose connection, so that we could get more information.

MarkMendelsohn commented 1 year ago

sdkconfig.zip

MarkMendelsohn commented 1 year ago

10178 E (363835) esp-tls-mbedtls: read error :-0x004C: 10179 E (363835) AWS_OTA: Publish failed, all attempts exhausted. 10180 E (363835) AWS_OTA: Failed to send PUBLISH packet to broker with error = 4. 10181 esp_get_free_heap_size 7156 10182 esp_get_free_internal_heap_size 3268 10183 esp_get_minimum_free_heap_size 2848

Even though esp_wifi_statis_dump() shows in the online API, it is not present in the release/v5.1 from Oct 20.

MarkMendelsohn commented 1 year ago

Any progress over the last 3 days finding the root cause of this issue?

Espressif-liuuuu commented 1 year ago

Any progress over the last 3 days finding the root cause of this issue?

I think its did a memory issue, its safe to reserve about 10k internal memory at runtime.
Its seems that SPIRAM is not selected in your sdkconfig, Is it possible to try your application on a chip with SPIRAM? Or simpily select CONFIG_SPIRAM in menuconfig and configure SPIRAM_MALLOC_RESERVE_INTERNAL to reserve more memory.

Espressif-liuuuu commented 1 year ago

here is another more complete example

2 I (7820) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
4 I (8880) wifi:state: init -> auth (b0)

12 I (8890) wifi:state: auth -> assoc (0) 16 I (8890) wifi:state: assoc -> run (10) 27 I (8920) wifi:connected with bonneau, aid = 16, channel 1, BW20, bssid = f0:7b:65:42:c6:43 28 I (8920) wifi:security: WPA2-PSK, phy: bgn, rssi: -61 29 I (9070) wifi:pm start, type: 1 31 I (9070) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000 32 I (9070) wifi:AP's beacon interval = 102400 us, DTIM period = 2 33 I (9120) wifi:idx:0 (ifx:0, f0:7b:65:42:c6:43), tid:7, ssn:1, winSize:64 128 I (14240) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 26975 I (875900) wifi:bcn_timeout,ap_probe_send_start 27015 W (876900) wifi:m f null 27070 I (878400) wifi:ap_probe_send over, resett wifi status to disassoc 27071 I (878400) wifi:state: run -> init (c800) 27072 I (878400) wifi:pm stop, total sleep time: 733594869 us / 869329427 us 27074 I (878400) wifi:idx:1, tid:0 27075 I (878410) wifi:idx:0, tid:7 27076 I (878410) wifi🆕<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 27232 I (881800) wifi🆕<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1 27233 I (881800) wifi:state: init -> auth (b0) 27234 I (881810) wifi:state: auth -> assoc (0) 27235 I (881810) wifi:state: assoc -> run (10) 27236 I (881830) wifi:connected with bonneau, aid = 14, channel 1, BW20, bssid = f0:7b:65:42:c6:43 27237 I (881830) wifi:security: WPA2-PSK, phy: bgn, rssi: -57 27238 I (881840) wifi:pm start, type: 1 27240 I (881840) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000 27241 I (881850) wifi:idx:0 (ifx:0, f0:7b:65:42:c6:43), tid:7, ssn:1, winSize:64 27242 I (881880) wifi:AP's beacon interval = 102400 us, DTIM period = 2 27315 I (884850) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 27315 I (884850) wifi:idx:1 (ifx:0, f0:7b:65:42:c6:43), tid:0, ssn:1, winSize:64 27317 27318 E (884990) esp-tls-mbedtls: mbedtls_ssl_setup returned -0x7F00 27319 E (884990) esp-tls: create_ssl_handle failed 27320 E (884990) esp-tls: Failed to open new connection 27321 Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. 27322 27323 Core 0 register dump: 27324 PC : 0x4210c7bc PS : 0x00060930 A0 : 0x8201271c A1 : 0x3fcccc30 27325 A2 : 0x00000000 A3 : 0x3fcb25d4 A4 : 0x00001080 A5 : 0x00000001 27326 A6 : 0xb33fffff A7 : 0xb33fffff A8 : 0x00000700 A9 : 0x3fcccbf0 27327 A10 : 0x00000000 A11 : 0x00060b20 A12 : 0x00000000 A13 : 0x00060b23 27328 A14 : 0xb33fffff A15 : 0xb33fffff SAR : 0x00000004 EXCCAUSE: 0x0000001c 27329 EXCVADDR: 0x0000072c LBEG : 0x400556d5 LEND : 0x400556e5 LCOUNT : 0xfffffffc 27330 27331 27332 Backtrace: 0x4210c7b9:0x3fcccc30 0x42012719:0x3fcccc50 0x42012346:0x3fcccc70 0x4201250a:0x3fcccca0 0x4200dc6f:0x3fccccc0 0x4200e8df:0x 3fcccd20 0x4200ce7f:0x3fcccd40 0x4200f182:0x3fcccd80 0x420043f0:0x3fcccda0 0x40384791:0x3fcccdc0

BTW, did you keep the elf of this crash? Pls provide us with the elf if its available so that we could see the reason of crash.

MarkMendelsohn commented 1 year ago

ota_mqtt.elf.zip Attached is the elf from the crash

MarkMendelsohn commented 1 year ago

Tried enabling CONFIG_SPIRAM but when it runs an error shows that SPIRAM is not available on the chip we are using.

Espressif-liuuuu commented 1 year ago

Tried enabling CONFIG_SPIRAM but when it runs an error shows that SPIRAM is not available on the chip we are using.

you could try chips with PSRAM, pls refer to https://products.espressif.com/#/product-selector?names=&filter={%22Series%22:[%22ESP32-S3%22]}

MarkMendelsohn commented 1 year ago

When loading the FW from the ESP32-S3-DevKit-1:

Chip is ESP32-S3 (QFN56) (revision v0.1) Features: WiFi, BLE, Embedded PSRAM 8MB (AP_3v3)

Then running the code:

E (456) quad_psram: PSRAM ID read error: 0x00ffffff, PSRAM chip not found or not supported, or wrong PSRAM line mode E (459) cpu_start: Failed to init external RAM!

When loading our new board:

Chip is ESP32-S3 (QFN56) (revision v0.1) Features: WiFi, BLE, Embedded PSRAM 2MB (AP_3v3)

Then running: PSRAM size: 2097152 bytes

On the new board, BLE does not work when PSRAM is enabled:

I (1293) BLE_INIT: BT controller compile version [85b425c] I (1293) BLE_INIT: Bluetooth MAC: 68:b6:b3:4f:c9:da be configured so E (1333) BLE_INIT: Malloc failed E (1333) BT_HCI: CC evt: op=0x2009, status=0x7

It seems the dev kit has more PSRAM than our new board but is not accessible. What can be changed to make the Dev Kit work?

PSRAM size: 8388608 bytes Dev kit PSAM access works when mode is QUAD instead of OCTO

Still malloc error and BLE not working

How should the PSRAM memory be configured so BLE can do malloc and task_create still works?

wmy-espressif commented 1 year ago

Hi @MarkMendelsohn , according to the LOG you provided:

E (1333) BLE_INIT: Malloc failed

Bluetooth initialization failed due to failure of acquiring memory. Bluetooth Controller requires internal RAM with DMA capability. My suggestion is to make better use of SPIRAM and offload the burden of internal memory.

From your sdkconfig, I observe that you are using Bluedroid, here is my suggestion that can reduce the memory requrirement or offload to SPIRAM for Bluetooth component:

  1. Enable menuconfig option: CONFIG_BT_BLE_DYNAMIC_ENV_MEMORY=y
  2. Enable SPIRAM menu, set CONFIG_SPIRAM_USE_MALLOC=y, and set CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=512
  3. Optionally, if you do not demand BLE mutliple links, you can set CONFIG_BT_CTRL_BLE_MAX_ACT=3 , to reduce the memory requirement of Bluetooth controller.

Suggestion 1 and 2 can offload the memory use of Bluedroid from internal RAM to SPIRAM.

You can check the free heap size after applying the above suggestions, using

esp_get_free_heap_size
esp_get_free_internal_heap_size
esp_get_minimum_free_heap_size

If they still cannot work, I suggest to find ways to reduce internal memory cost from application and from other idf components.

You can find some instructions on using SPIRAM related options via: SPIRAM options

MarkMendelsohn commented 11 months ago

heap_caps_malloc was called but failed to allocate 1700 bytes with 0x1800 capabilities. heap_caps_malloc was called but failed to allocate 1700 bytes with 0x1800 capabilities. heap_caps_calloc was called but failed to allocate 412 bytes with 0x804 capabilities. heap_caps_malloc was called but failed to allocate 1532 bytes with 0x1800 capabilities. heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (79387) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80007) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80107) wifi:m f null

heap_caps_malloc was called but failed to allocate 1532 bytes with 0x1800 capabilities. heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80207) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80317) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80417) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80517) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80617) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80727) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80827) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (80927) wifi:m f null

heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (81027) wifi:m f null

MarkMendelsohn commented 11 months ago

I (11766) AWS_OTA: Establishing a TLS session to a1lls2ekfptys8-ats.iot.us-east-2.amazonaws.com:8883. heap_caps_malloc was called but failed to allocate 1700 bytes with 0x1800 capabilities. heap_caps_malloc was called but failed to allocate 1700 bytes with 0x1800 capabilities. heap_caps_malloc was called but failed to allocate 84 bytes with 0x804 capabilities. heap_caps_calloc was called but failed to allocate 4 bytes with 0x804 capabilities. E (12176) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x3B00 I (12176) esp-tls-mbedtls: Certificate verified. E (12186) esp-tls: Failed to open new connection W (12186) AWS_OTA: Connection to the broker failed. Retrying connection after 317 ms backoff. I (12506) AWS_OTA: Establishing a TLS session to a1lls2ekfptys8-ats.iot.us-east-2.amazonaws.com:8883. heap_caps_malloc was called but failed to allocate 1700 bytes with 0x1800 capabilities. heap_caps_malloc was called but failed to allocate 84 bytes with 0x804 capabilities. heap_caps_calloc was called but failed to allocate 4 bytes with 0x804 capabilities. E (12766) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x3B00 I (12766) esp-tls-mbedtls: Certificate verified. E (12776) esp-tls: Failed to open new connection W (12786) AWS_OTA: Connection to the broker failed. Retrying connection after 450 ms backoff. I (13236) AWS_OTA: Establishing a TLS session to a1lls2ekfptys8-ats.iot.us-east-2.amazonaws.com:8883. heap_caps_malloc was called but failed to allocate 124 bytes with 0x80C capabilities. W (13386) wifi:m f null

MarkMendelsohn commented 11 months ago

My project is a combination of the wifi_prov_mgr and the ota_mqtt project. When trying to run each of these separately with SPIRAM enabled, wifi_prov_mgr can't link properly and gets the error:

[ 98%] Built target bootloader [ 98%] Built target __ldgen_output_sections.ld [100%] Linking CXX executable wifi_prov_mgr.elf /Users/mpm/.espressif/tools/xtensa-esp32-elf/esp-12.2.0_20230208/xtensa-esp32-elf/bin/../lib/gcc/xtensa-esp32-elf/12.2.0/../../../../xtensa-esp32-elf/bin/ld: wifi_prov_mgr.elf section .iram0.text' will not fit in regioniram0_0_seg' /Users/mpm/.espressif/tools/xtensa-esp32-elf/esp-12.2.0_20230208/xtensa-esp32-elf/bin/../lib/gcc/xtensa-esp32-elf/12.2.0/../../../../xtensa-esp32-elf/bin/ld: IRAM0 segment data does not fit. /Users/mpm/.espressif/tools/xtensa-esp32-elf/esp-12.2.0_20230208/xtensa-esp32-elf/bin/../lib/gcc/xtensa-esp32-elf/12.2.0/../../../../xtensa-esp32-elf/bin/ld: region `iram0_0_seg' overflowed by 14124 bytes collect2: error: ld returned 1 exit status make[2]: [wifi_prov_mgr.elf] Error 1 make[1]: [CMakeFiles/wifi_prov_mgr.elf.dir/all] Error 2 make: *** [all] Error 2 HINT: The applications static IRAM usage is larger than the available IRAM size. For more information on how to reduze IRAM usage run 'idf.py docs -sp api-guides/performance/ram-usage.html#optimizing-iram-usage' make failed with exit code 2, output of the command is in the /Users/mpm/esp-idf/examples/provisioning/wifi_prov_mgr/build/log/idf_py_stderr_output_37689 and /Users/mpm/esp-idf/examples/provisioning/wifi_prov_mgr/build/log/idf_py_stdout_output_37689 MacMiniM1:wifi_prov_mgr mpm$

The ota_mqtt project will build with PSRAM access set to OCTO instead of QUAD.

The only example of a PSRAM project in the IDF is the xip_from_psram which does not seem to run correctly based on the output. Therefore there is no working sample of PSRAM to use as a template.

I (27) boot: ESP-IDF v5.1.2-89-g5c61c89308-dirty 2nd stage bootloader I (27) boot: compile time Dec 8 2023 11:59:00 I (28) boot: Multicore bootloader I (32) boot: chip revision: v0.1 I (35) boot.esp32s3: Boot SPI Speed : 80MHz I (40) boot.esp32s3: SPI Mode : DIO I (45) boot.esp32s3: SPI Flash Size : 2MB I (50) boot: Enabling RNG early entropy source... I (55) boot: Partition Table: I (59) boot: ## Label Usage Type ST Offset Length I (66) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (73) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (81) boot: 2 factory factory app 00 00 00010000 00100000 I (88) boot: 3 storage1 Unknown data 01 81 00110000 00010000 I (96) boot: End of partition table I (100) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=0a570h ( 42352) map I (116) esp_image: segment 1: paddr=0001a598 vaddr=3fc92600 size=02d1ch ( 11548) load I (119) esp_image: segment 2: paddr=0001d2bc vaddr=40374000 size=02d5ch ( 11612) load I (128) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1835ch ( 99164) map I (152) esp_image: segment 4: paddr=00038384 vaddr=40376d5c size=0b7c4h ( 47044) load I (168) boot: Loaded app from partition at offset 0x10000 I (169) boot: Disabling RNG early entropy source... I (180) cpu_start: Multicore app I (180) octal_psram: vendor id : 0x0d (AP) I (181) octal_psram: dev id : 0x02 (generation 3) I (184) octal_psram: density : 0x03 (64 Mbit) I (189) octal_psram: good-die : 0x01 (Pass) I (194) octal_psram: Latency : 0x01 (Fixed) I (200) octal_psram: VCC : 0x01 (3V) I (205) octal_psram: SRF : 0x01 (Fast Refresh) I (211) octal_psram: BurstType : 0x01 (Hybrid Wrap) I (216) octal_psram: BurstLen : 0x01 (32 Byte) I (222) octal_psram: Readlatency : 0x02 (10 cycles@Fixed) I (228) octal_psram: DriveStrength: 0x00 (1/1) I (233) esp_psram: Found 8MB PSRAM device I (238) esp_psram: Speed: 40MHz I (258) mmu_psram: Instructions copied and mapped to SPIRAM ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x10 (RTCWDT_RTC_RST),boot:0x8 (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3818,len:0x1764 load:0x403c9700,len:0x4 load:0x403c9704,len:0xc00 load:0x403cc700,len:0x2e04 entry 0x403c9908 I (27) boot: ESP-IDF v5.1.2-89-g5c61c89308-dirty 2nd stage bootloader I (27) boot: compile time Dec 8 2023 11:59:00 I (28) boot: Multicore bootloader I (32) boot: chip revision: v0.1 I (36) boot.esp32s3: Boot SPI Speed : 80MHz I (41) boot.esp32s3: SPI Mode : DIO I (46) boot.esp32s3: SPI Flash Size : 2MB I (50) boot: Enabling RNG early entropy source... I (56) boot: Partition Table: I (59) boot: ## Label Usage Type ST Offset Length I (67) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (74) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (82) boot: 2 factory factory app 00 00 00010000 00100000 I (89) boot: 3 storage1 Unknown data 01 81 00110000 00010000 I (97) boot: End of partition table I (101) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=0a570h ( 42352) map I (117) esp_image: segment 1: paddr=0001a598 vaddr=3fc92600 size=02d1ch ( 11548) load I (120) esp_image: segment 2: paddr=0001d2bc vaddr=40374000 size=02d5ch ( 11612) load I (129) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1835ch ( 99164) map I (152) esp_image: segment 4: paddr=00038384 vaddr=40376d5c size=0b7c4h ( 47044) load I (169) boot: Loaded app from partition at offset 0x10000 I (169) boot: Disabling RNG early entropy source... I (181) cpu_start: Multicore app I (181) octal_psram: vendor id : 0x0d (AP) I (181) octal_psram: dev id : 0x02 (generation 3) I (184) octal_psram: density : 0x03 (64 Mbit) I (190) octal_psram: good-die : 0x01 (Pass) I (195) octal_psram: Latency : 0x01 (Fixed) I (200) octal_psram: VCC : 0x01 (3V) I (205) octal_psram: SRF : 0x01 (Fast Refresh) I (211) octal_psram: BurstType : 0x01 (Hybrid Wrap) I (217) octal_psram: BurstLen : 0x01 (32 Byte) I (223) octal_psram: Readlatency : 0x02 (10 cycles@Fixed) I (229) octal_psram: DriveStrength: 0x00 (1/1) I (234) esp_psram: Found 8MB PSRAM device I (239) esp_psram: Speed: 40MHz I (259) mmu_psram: Instructions copied and mapped to SPIRAM E (259) ry test OK : No enough psram memory for rodata! ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x10 (RTCWDT_RTC_RST),boot:0x8 (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3818,len:0x1764 load:0x403c9700,len:0x4 load:0x403c9704,len:0xc00 load:0x403cc700,len:0x2e04 entry 0x403c9908 I (27) boot: ESP-IDF v5.1.2-89-g5c61c89308-dirty 2nd stage bootloader I (27) boot: compile time Dec 8 2023 11:59:00 I (28) boot: Multicore bootloader I (32) boot: chip revision: v0.1 I (36) boot.esp32s3: Boot SPI Speed : 80MHz I (41) boot.esp32s3: SPI Mode : DIO I (46) boot.esp32s3: SPI Flash Size : 2MB I (50) boot: Enabling RNG early entropy source... I (56) boot: Partition Table: I (59) boot: ## Label Usage Type ST Offset Length I (67) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (74) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (82) boot: 2 factory factory app 00 00 00010000 00100000 I (89) boot: 3 storage1 Unknown data 01 81 00110000 00010000 I (97) boot: End of partition table I (101) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=0a570h ( 42352) map I (117) esp_image: segment 1: paddr=0001a598 vaddr=3fc92600 size=02d1ch ( 11548) load I (120) esp_image: segment 2: paddr=0001d2bc vaddr=40374000 size=02d5ch ( 11612) load I (129) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1835ch ( 99164) map I (152) esp_image: segment 4: paddr=00038384 vaddr=40376d5c size=0b7c4h ( 47044) load I (169) boot: Loaded app from partition at offset 0x10000 I (169) boot: Disabling RNG early entropy source... I (181) cpu_start: Multicore app I (181) octal_psram: vendor id : 0x0d (AP) I (181) octal_psram: dev id : 0x02 (generation 3) I (184) octal_psram: density : 0x03 (64 Mbit) I (190) octal_psram: good-die : 0x01 (Pass) I (195) octal_psram: Latency : 0x01 (Fixed) I (200) octal_psram: VCC : 0x01 (3V) I (205) octal_psram: SRF : 0x01 (Fast Refresh) I (211) octal_psram: BurstType : 0x01 (Hybrid Wrap) I (217) octal_psram: BurstLen : 0x01 (32 Byte) I (223) octal_psram: Readlatency : 0x02 (10 cycles@Fixed) I (229) octal_psram: DriveStrength: 0x00 (1/1) I (234) esp_psram: Found 8MB PSRAM device I (239) esp_psram: Speed: 40MHz I (259) mmu_psram: Instructions copied and mapped to SPIRAM ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x10 (RTCWDT_RTC_RST),boot:0x8 (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3818,len:0x1764 load:0x403c9700,len:0x4 load:0x403c9704,len:0xc00 load:0x403cc700,len:0x2e04 entry 0x403c9908 I (27) boot: ESP-IDF v5.1.2-89-g5c61c89308-dirty 2nd stage bootloader I (27) boot: compile time Dec 8 2023 11:59:00 I (28) boot: Multicore bootloader I (32) boot: chip revision: v0.1 I (36) boot.esp32s3: Boot SPI Speed : 80MHz I (41) boot.esp32s3: SPI Mode : DIO I (46) boot.esp32s3: SPI Flash Size : 2MB I (50) boot: Enabling RNG early entropy source... I (56) boot: Partition Table: I (59) boot: ## Label Usage Type ST Offset Length I (67) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (74) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (82) boot: 2 factory factory app 00 00 00010000 00100000 I (89) boot: 3 storage1 Unknown data 01 81 00110000 00010000 I (97) boot: End of partition table I (101) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=0a570h ( 42352) map I (117) esp_image: segment 1: paddr=0001a598 vaddr=3fc92600 size=02d1ch ( 11548) load I (120) esp_image: segment 2: paddr=0001d2bc vaddr=40374000 size=02d5ch ( 11612) load I (129) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1835ch ( 99164) map I (152) esp_image: segment 4: paddr=00038384 vaddr=40376d5c size=0b7c4h ( 47044) load I (169) boot: Loaded app from partition at offset 0x10000 I (169) boot: Disabling RNG early entropy source... I (181) cpu_start: Multicore app I (181) octal_psram: vendor id : 0x0d (AP) I (181) octal_psram: dev id : 0x02 (generation 3) I (184) octal_psram: density : 0x03 (64 Mbit) I (190) octal_psram: good-die : 0x01 (Pass) I (195) octal_psram: Latency : 0x01 (Fixed) I (200) octal_psram: VCC : 0x01 (3V) I (205) octal_psram: SRF : 0x01 (Fast Refresh) I (211) octal_psram: BurstType : 0x01 (Hybrid Wrap) I (217) octal_psram: BurstLen : 0x01 (32 Byte) I (223) octal_psram: Readlatency : 0x02 (10 cycles@Fixed) I (229) octal_psram: DriveStrength: 0x00 (1/1) I (234) esp_psram: Found 8MB PSRAM device I (239) esp_psram: Speed: 40MHz I (259) mmu_psram: Instructions copied and mapped to SPIRAM I (268) mmu_psram: Read only data copied and mapped to SPIRAM ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x10 (RTCWDT_RTC_RST),boot:0x8 (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3818,len:0x1764 load:0x403c9700,len:0x4 load:0x403c9704,len:0xc00 load:0x403cc700,len:0x2e04 entry 0x403c9908 I (27) boot: ESP-IDF v5.1.2-89-g5c61c89308-dirty 2nd stage bootloader I (27) boot: compile time Dec 8 2023 11:59:00 I (28) boot: Multicore bootloader I (32) boot: chip revision: v0.1 I (36) boot.esp32s3: Boot SPI Speed : 80MHz I (41) boot.esp32s3: SPI Mode : DIO I (46) boot.esp32s3: SPI Flash Size : 2MB I (50) boot: Enabling RNG early entropy source... I (56) boot: Partition Table: I (59) boot: ## Label Usage Type ST Offset Length I (67) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (74) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (82) boot: 2 factory factory app 00 00 00010000 00100000 I (89) boot: 3 storage1 Unknown data 01 81 00110000 00010000 I (97) boot: End of partition table I (101) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=0a570h ( 42352) map I (117) esp_image: segment 1: paddr=0001a598 vaddr=3fc92600 size=02d1ch ( 11548) load I (120) esp_image: segment 2: paddr=0001d2bc vaddr=40374000 size=02d5ch ( 11612) load I (129) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1835ch ( 99164) map I (152) esp_image: segment 4: paddr=00038384 vaddr=40376d5c size=0b7c4h ( 47044) load I (169) boot: Loaded app from partition at offset 0x10000 I (169) boot: Disabling RNG early entropy source... I (181) cpu_start: Multicore app I (181) octal_psram: vendor id : 0x0d (AP) I (181) octal_psram: dev id : 0x02 (generation 3) I (184) octal_psram: density : 0x03 (64 Mbit) I (190) octal_psram: good-die : 0x01 (Pass) I (195) octal_psram: Latency : 0x01 (Fixed) I (200) octal_psram: VCC : 0x01 (3V) I (205) octal_psram: SRF : 0x01 (Fast Refresh) I (211) octal_psram: BurstType : 0x01 (Hybrid Wrap) I (217) octal_psram: BurstLen : 0x01 (32 Byte) I (223) octal_psram: Readlatency : 0x02 (10 cycles@Fixed) I (229) octal_psram: DriveStrength: 0x00 (1/1) I (234) esp_psram: Found 8MB PSRAM device I (239) esp_psram: Speed: 40MHz I (259) mmu_psram: Instructions copied and mapped to SPIRAM

Done MacMiniM1:xip_from_psram mpm$