heap_caps_malloc() was called and failed to allocate memory

[kesha.modhia]

Hello

for ESP32 IDF4.2.3
In my source code I was calling heap_caps_malloc() to allocate memory
As I have enabled External ram to allocate memory

In my case heap_caps_malloc() called successfully but failed to allocate the memory

FYI,
Heap memory was still available
HEAP SIZE : 74291 bytes
And I was in need of 15 bytes only what could be the reason of the failure.

[MicroController]

what could be the reason of the failure.

1. PSRAM not set up to be added to the heap via menuconfig, and/or
2. Wrong capabilities passed to heap_caps_malloc().

[kesha.modhia]

Below mentioned is my menuconfig setting for SPIRAM

" ESP32_SPIRAM_SUPPORT(=y) "Support for external, SPI-connected RAM" SPIRAM(=y) "

And FYI
In my source code I am using this api to allocate memory for every msg received on UART, and it sucessfully allocated the memory for all messages
I kept my set up for weekend testing and it worked for 2 nights
See below I am attaching some logs and API for the referance [see the content in bold letters ]


static uint8_t* pu8SerialBufferAllocation(uint16_t Data_Length)
{
uint8_t *pBuffer = NULL;
pBuffer = heap_caps_malloc(Data_Length + 1, MALLOC_CAP_SPIRAM);
if (pBuffer == NULL)
{
DEBUG_LOGE(UART, TAG, "Memory Allocation failed\n");
return NULL;
}
else
{
DEBUG_LOGD(UART, TAG, "***** bytes allocated via heap_caps_malloc %d address is =%p", Data_Length,pBuffer);
}
return pBuffer;
}


--------------------------------------------------------------------------------------------------------------------------------------------------
[2024-05-19 04:16:12.253]
[2024-05-19 04:16:12.253] I app_serial_commands.c: 328: NODE ID : 0x33f0
[2024-05-19 04:16:12.253]
[2024-05-19 04:16:12.253] I app_serial_commands.cI app_seI app_serial_commands.cD app_serial.cD app_serial.c: 260: State = E_FRAME_CRC_SECOND_BYTE
[2024-05-19 04:16:12.253]
[2024-05-19 04:16:12.253] D app_serial.c: 260: State = E_FRAME_CRC_SECOND_BYTE
[2024-05-19 04:16:12.253]
[2024-05-19 04:16:12.253] D app_serial.cI app_serial_commands.c: I app_serial_commands.c: 333: STATUS : 0x00
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] D app_serial.c: 267: CRC Valid = 0xa794
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] I app_node_db.c: 603: DEV ID : 0x0002, ENDPOINT CNT : 0x02
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] I app_serial.c: 701: teCheckMessageType u16MessageType 0x4010
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] I app_serial_commands.c: 395: ZHA_ON_OFF_OUD app_serial.c: 767: EFR reset timer re-evaluate its expiry time
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] I app_node_db.c: 652: FOUND ENDPOINT : 0x11
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] vAPPSerialReaderTask ESP UART RX Cmd [4010] Ln [ 000B ] CRC [A794] Data [ A6 9E 40 10 00 0B 39 16 I (04:16:12.166) ZHA_OnOffOutputSensor.c: ON/OFF STATE : OFF
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] 01 0B 08 00 00 00 20 01 64 A7 94 ]
[2024-05-19 04:16:12.254] D app_serial.c: 494: ****** NCP firmware NOT in progress,UART data passing to process *****
[2024-05-19 04:16:12.254] I (04:16:12.184) MQTTS_EXAMPLE: sent publish successful, TOPIC: 200A001B/HeartBeat msg_id=0
[2024-05-19 04:16:12.254] D app_serial.c: 218: u16MessageType = 0x4010
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] I (04:16:12.204) MQTTS_EXAMPLE: sent publish successful, TOPIC: 200A001B/HeartBeat msg_id=0
[2024-05-19 04:16:12.254] D app_serial.c: 234: u16Length = 0x000b
[2024-05-19 04:16:12.254]
[2024-05-19 04:16:12.254] D app_serial.c: 253: State = FRAME_CRC_FIRST_BYTE
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D app_serial.c: 260: State = E_FRAME_CRC_SECOND_BYTE
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D app_serial.c: 402: ***** bytes allocated via heap_caps_malloc 15 address is =0x3fbfffe4
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_blink_led.c: 742: LED_DEVICE_COMMAND_HANDLED
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D app_serial.c: 267: CRC Valid = 0xa794
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D (04:16:12.234) esp.emac: receive len= 60
[2024-05-19 04:16:12.255] I app_serial.c: 296: Receive Frame Valid 3fbfffe4
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial.c: 305: RECV MSG_TYPE : 0x4010
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial.c: 305: RECV MSG_TYPE : 0x4010
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial.c: 374: SND Free HEAP SIZE : 72895 space available = 400 stored = 0
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D app_blink_led.c.c: 368: RCVD Free HEAP SIZE : 72895 space available = 400 msg stored = 0
[2024-05-19 04:16:12.255] D app_zigbee_main.cD app_zigbee_main.c: 371: ****** in vAPPHAMainTask
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_zigbee_main.c: 67: vProcessIncommingCommands 0x4010
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D app_serial_commands.c: 306: vHandleReportAttribute
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D (04:16:12.296) esp.emac: receive len= 60
[2024-05-19 04:16:12.255] I app_serial_commands.c: 327: u16MessageType : 0x4010
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial_commands.c: 328: NODE ID : 0x1639
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial_commands.c: 329: SRC EPID : 0x01
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial_commands.c: 330: DEST EPID : 0x0b
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial_commands.c: 331: CLU ID : 0x0008
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial_commands.c: 332: ATT ID : 0x0000
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_serial_commands.c: 333: STATUS : 0x64
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_node_db.c: 603: DEV ID : 0x0101, ENDPOINT CNT : 0x01
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] D app_serial_commands.c: 354: ZHA_DIMMABLE_LIGHT_DEVICE_ID
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I app_node_db.c: 652: FOUND ENDPOINT : 0x01
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.255] I (04:16:12.347) ZHA_DimmableLightDevice.c: DL: CURRENT LEVEL : 0x64
[2024-05-19 04:16:12.255] I app_node_db.c: 652: FOUND ENDPOINT : 0x01
[2024-05-19 04:16:12.255]
[2024-05-19 04:16:12.256] I (04:16:12.361) MQTTS_EXAMPLE: sent publish successful, TOPIC: 200A001B/HeartBeat msg_id=0
[2024-05-19 04:16:12.256] I (04:16:12.367) p_commands: DL: CURRENT LEVEL : 0x64
[2024-05-19 04:16:12.256] I (04:16:12.375) MQTTS_EXAMPLE: sent publish successful, TOPIC: 200A001B/HeartBeat msg_id=0
[2024-05-19 04:16:12.256] D app_node_db.c: 972: Device Info updated at the index = 27
[2024-05-19 04:16:12.256]
[2024-05-19 04:16:12.256] D (04:16:12.401) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
[2024-05-19 04:16:12.301] D (04:16:12.404) esp.emac: receive len= 60
[2024-05-19 04:16:12.301] I app_blink_led.c: 742: LED_DEVICE_COMMAND_HANDLED
[2024-05-19 04:16:12.301]
[2024-05-19 04:16:12.301] D app_blink_led.c: 406: LED GPIO : 51
[2024-05-19 04:16:12.301]
[2024-05-19 04:16:12.301] D app_blink_led.c: 444: led_number = 2 blink_number = 3 HighFreqLedNumber = 16
[2024-05-19 04:16:12.301]
[2024-05-19 04:16:12.301] D app_blink_led.c: 460: HighFreqLedNumber = 16
[2024-05-19 04:16:12.301]
[2024-05-19 04:16:12.317] D (04:16:12.452) esp.emac: receive len= 60
[2024-05-19 04:16:13.296] D (04:16:13.418) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
[2024-05-19 04:16:13.955] D uart_handler.c: 210: *********UART [2] Q data RCVD ************** eS [19] eT[0]
[2024-05-19 04:16:13.955] D (04:16:13.885) uart_handler.c: uart[2] event:
[2024-05-19 04:16:13.955]
[2024-05-19 04:16:13.955] D (04:16:13.886) uart_handler.c: ************ Q Recieved data to pass on serial reader task =A6
[2024-05-19 04:16:13.955]
[2024-05-19 04:16:13.955] I (04:16:13.895) uart_handler.c: UART_2 MSG _QUEUED
[2024-05-19 04:16:13.955] D app_serial.c: 218: u16MessageType = 0x4010
[2024-05-19 04:16:13.955]
[2024-05-19 04:16:13.955] D (04:16:13.900) uart_handler.c: ********************at end of the for loop ***********************
[2024-05-19 04:16:13.955] D app_serial.c: 234: u16Length = 0x000b
[2024-05-19 04:16:13.955]
[2024-05-19 04:16:13.955] D (04:16:13.914) uart_handler.c: ****************inside UART 2 for loop
[2024-05-19 04:16:13.955] D (04:16:13.924) uart_handler.c: **********UART 2 WAITING for QRCV
[2024-05-19 04:16:13.955]
[2024-05-19 04:16:13.955] D app_serial.c: 253: State = FRAME_CRC_FIRST_BYTE
[2024-05-19 04:16:13.955]
[2024-05-19 04:16:13.956] D app_serial.c: 260: State = E_FRAME_CRC_SECOND_BYTE
[2024-05-19 04:16:13.956]
[2024-05-19 04:16:13.956] D app_serial.c: 402: ***** bytes allocated via heap_caps_malloc 15 address is =0x3fbfffd0
[2024-05-19 04:16:13.956]
[2024-05-19 04:16:13.956] D app_serial.c: 267: CRC Valid = 0x91b3
[2024-05-19 04:16:13.956]
[2024-05-19 04:16:13.956] D uart_handler.c: 210: *********UART [2] Q data RCVD ************** eS [19] eT[0]
[2024-05-19 04:16:13.956] I app_serial.c: 701: teCheckMessageType u16MessageType 0x4010
[2024-05-19 04:16:13.956]
[2024-05-19 04:16:13.956] D (04:16:13.959) uart_handler.c: uart[2] event:
[2024-05-19 04:16:13.956]
[2024-05-19 04:16:13.956] D app_serial.c: 767: EFR reset timer re-evaluate its expiry time
[2024-05-19 04:16:13.956]
[2024-05-19 04:16:13.956] D (04:16:13.970) uart_handler.c: ************ Q Recieved data to pass on serial reader task =A6
[2024-05-19 04:16:13.956]
[2024-05-19 04:16:13.956] vAPPSerialReaderTask ESP UART RX Cmd [4010] Ln [ 000B ] CRC [91B3] Data [ A6 I (04:16:13.985) uart_handler.c: UART_2 MSG _QUEUED
[2024-05-19 04:16:13.956] 9E 40 10 00 0B 21 AB D (04:16:13.997) uart_handler.c: ********************at end of the for loop ***********************
[2024-05-19 04:16:13.956] 01 0B 08 00 00 00 20 D (04:16:14.008) uart_handler.c: ****************inside UART 2 for loop
[2024-05-19 04:16:13.956] 01 64 91 B3 ]
[2024-05-19 04:16:13.956] D (04:16:14.017) uart_handler.c: **********UART 2 WAITING for QRCV
[2024-05-19 04:16:13.956] D app_serial.c: 494: ****** NCP firmware NOT in progress,UART data passing to process *****
[2024-05-19 04:16:13.956] D app_serial.c: 218: u16MessageType = 0x4010
[2024-05-19 04:16:13.956] D app_serial.c: 234: u16Length = 0x000b
[2024-05-19 04:16:13.956] D app_serial.c: 253: State = FRAME_CRC_FIRST_BYTE
[2024-05-19 04:16:13.956] D app_serial.c: 260: State = E_FRAME_CRC_SECOND_BYTE
[2024-05-19 04:16:13.956] D app_serial.c: 402: ***** bytes allocated via heap_caps_malloc 15 address is =0x3fbfffe4
[2024-05-19 04:16:13.957] D app_serial.c: 267: CRC Valid = 0x91b3
[2024-05-19 04:16:13.957] I app_serial.c: 296: Receive Frame Valid 3fbfffe4
[2024-05-19 04:16:13.957] I app_serial.c: 305: RECV MSG_TYPE : 0x4010
[2024-05-19 04:16:13.957] I app_serial.c: 374: SND Free HEAP SIZE : 74291 space available = 400 stored = 0
[2024-05-19 04:16:14.234] D app_serial.c: 218: u16MessageType = 0x4010
[2024-05-19 04:16:14.234]
[2024-05-19 04:16:14.234] D app_serial.c: 234: u16Length = 0x000b
[2024-05-19 04:16:14.234]
[2024-05-19 04:16:14.234] D app_serial.c: 253: State = FRAME_CRC_FIRST_BYTE
[2024-05-19 04:16:14.234]
[2024-05-19 04:16:14.234] D app_serial.c: 260: State = E_FRAME_CRC_SECOND_BYTE
[2024-05-19 04:16:14.234]
[2024-05-19 04:16:14.234] E app_serial.c: 397: Memory Allocation failed
[2024-05-19 04:16:14.234]

[MicroController]

allocate memory for every msg received on UART, and it sucessfully allocated the memory for all messages
I kept my set up for weekend testing and it worked for 2 nights

Uhm... how many messages/buffers did you allocate up to the error? Do you free() any of them at some point? What else lives in the PSRAM?
Might be the case that you're actually just running out of PSRAM space...

Heap memory was still available
HEAP SIZE : 74291 bytes

Doesn't necessarily tell anything about the available memory in external RAM.