espressif / esp-idf

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

assert failed: block_trim_free heap_ulsf.c:377 (block_is_free(block) && "block must be free") (IDFGH-6657) #8293

Closed allard-potma closed 2 years ago

allard-potma commented 2 years ago

Environment

I got a assertion in malloc: assert failed: block_trim_free heap_ulsf.c:377 (block_is_free(block) && "block must be free")

The backtrace:

Backtrace:0x40081cce:0x3ffd83100x40091bd1:0x3ffd8330 0x40097ecd:0x3ffd8350 0x4009706a:0x3ffd8470 0x40097a95:0x3ffd8490 0x40081f31:0x3ffd84b0 0x40081f65:0x3ffd84d0 0x40097edd:0x3ffd84f0 0x40110f8b:0x3ffd8510 0x40111897:0x3ffd8530 0x40111a96:0x3ffd8550 0x40111c08:0x3ffd8570 0z40111c89:0x3ffd85c0 0x40111c99:0x3ffd85e0 0x400dbee5:0x3ffd8600 0x400da369:0x3ffd8620 0x4014033b:0x3ffd8640 0x40140b65:0x3ffd8680 0x40140c04:0x3ffd8710 0x4013f7fe:0x3ffd8w30 0x4013ec4a:0x3ffd8750 0x4117ba93:0x3ffd8770 0x4013e
eab:0x3ffd8790 0x4013ef13:0x3ffd87e0 0x40095679:0x3ffd8800
0x40081cce: panic_abort at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_system/panic.c:402

0x40091bd1: esp_system_abort at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_system/esp_system.c:121

0x40097ecd: __assert_func at F:/ESP/IDF/esp-idf-v4.4-rc1/components/newlib/assert.c:85

0x4009706a: block_trim_free at F:/ESP/IDF/esp-idf-v4.4-rc1/components/heap/heap_tlsf.c:377
 (inlined by) block_prepare_used at F:/ESP/IDF/esp-idf-v4.4-rc1/components/heap/heap_tlsf.c:460
 (inlined by) tlsf_malloc at F:/ESP/IDF/esp-idf-v4.4-rc1/components/heap/heap_tlsf.c:758

0x40097a95: multi_heap_malloc_impl at F:/ESP/IDF/esp-idf-v4.4-rc1/components/heap/multi_heap.c:197

0x40081f31: heap_caps_malloc at F:/ESP/IDF/esp-idf-v4.4-rc1/components/heap/heap_caps.c:145

0x40081f65: heap_caps_malloc_default at F:/ESP/IDF/esp-idf-v4.4-rc1/components/heap/heap_caps.c:177

0x40097edd: malloc at F:/ESP/IDF/esp-idf-v4.4-rc1/components/newlib/heap.c:24

0x40110f8b: cJSON_New_Item at F:/ESP/IDF/esp-idf-v4.4-rc1/components/json/cJSON/cJSON.c:243

0x40111897: parse_object at F:/ESP/IDF/esp-idf-v4.4-rc1/components/json/cJSON/cJSON.c:1633

0x40111a96: parse_value at F:/ESP/IDF/esp-idf-v4.4-rc1/components/json/cJSON/cJSON.c:1356

0x40111c08: cJSON_ParseWithLengthOpts at F:/ESP/IDF/esp-idf-v4.4-rc1/components/json/cJSON/cJSON.c:1116

0x40111c99: cJSON_Parse at F:/ESP/IDF/esp-idf-v4.4-rc1/components/json/cJSON/cJSON.c:1173

0x400dbee5: my_funtion() -> a http server POST body parser (JSON)

0x400da369: my_function() -> a http server POST handler

0x4014033b: httpd_uri at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_http_server/src/httpd_uri.c:329

0x40140b65: httpd_parse_req at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_http_server/src/httpd_parse.c:659 (discriminator 15)

0x40140c04: httpd_req_new at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_http_server/src/httpd_parse.c:784

0x4013f7fe: httpd_sess_process at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_http_server/src/httpd_sess.c:412 (discriminator 15)

0x4013ec4a: httpd_process_session at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_http_server/src/httpd_main.c:178 (discriminator 15)

0x4013eeab: httpd_server at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_http_server/src/httpd_main.c:228

0x4013ef13: httpd_thread at F:/ESP/IDF/esp-idf-v4.4-rc1/components/esp_http_server/src/httpd_main.c:250 (discriminator 15)

0x40095679: vPortTaskWrapper at F:/ESP/IDF/esp-idf-v4.4-rc1/components/freertos/port/xtensa/port.c:131

I've seen issue #7746, but that fix seems to have something to do with DHCP, I think my issue is not related. I think issue #8270 may be related.

Expected Behavior

malloc should not throw a assertion.

Steps to reproduce

I can't share my code here, but I'm able to provide more info when necessary.

allard-potma commented 2 years ago

This was due to a nasty traceable heap poisoning case, closing.

txf- commented 1 year ago

So I appear to still hit this bug. Which version of ESP-IDF has this been fixed in?

I'm on ESP-IDF v4.4.3-347-g9ee3c8337d.

I get exactly the same assertion.

zztiger123 commented 1 year ago

Hi all,

From the arduino-esp32#7274 https://github.com/espressif/arduino-esp32/issues/7274#issuecomment-1505067956, This issue still occurs on ESP-IDF 4.4.4.

Based on esp-idf v4.4.4 + esp32S3 + external spiram :

Using the nimble client function, we have an interface in the BLE_GAP_EVENT_NOTIFY_RX event to process the received data, analyze and package the received data and push it into the queue, and then other threads will report the data in the queue to the cloud; This interface will report an error in malloc when Bluetooth data is reported frequently

_assert failed: block_trim_free heap_tlsf.c:371 (block_isfree(block) && "block must be free")

However, this interface has never reported this error when the reporting frequency is low or the interface reads data from the serial port (instead of nimble).

We also use malloc to test the allocation of internal ram and psram, and the same error occurs, and the malloc API will not be fully executed to the last return line; the error has already started to be reported directly inside the call to malloc() or heap_caps_malloc(). The detailed log is as follows:

assert failed: block_trim_free heap_tlsf.c:371 (block_is_free(block) && "block must be free")

0x42016cb8:0x3fcdb2e0 0x42016cc3:0x3fcdb300 0x4201e166:0x3fcdb320 0x420094de:0x3fcdb340
0x40375d6e: panic_abort at C:/Espressif/frameworks/esp-idf-v4.4.4/components/esp_system/panic.c:408

0x4037f8e9: esp_system_abort at C:/Espressif/frameworks/esp-idf-v4.4.4/components/esp_system/esp_system.c:137

0x40386b6d: __assert_func at C:/Espressif/frameworks/esp-idf-v4.4.4/components/newlib/assert.c:85

0x40385352: block_locate_free at C:/Espressif/frameworks/esp-idf-v4.4.4/components/heap/heap_tlsf.c:441
  (inlined by) tlsf_malloc at C:/Espressif/frameworks/esp-idf-v4.4.4/components/heap/heap_tlsf.c:849

0x40385d25: multi_heap_malloc_impl at C:/Espressif/frameworks/esp-idf-v4.4.4/components/heap/multi_heap.c:200

0x403760de: heap_caps_malloc_base at C:/Espressif/frameworks/esp-idf-v4.4.4/components/heap/heap_caps.c:154
  (inlined by) heap_caps_malloc_base at C:/Espressif/frameworks/esp-idf-v4.4.4/components/heap/heap_caps.c:99

0x403760f1: heap_caps_malloc at C:/Espressif/frameworks/esp-idf-v4.4.4/components/heap/heap_caps.c:174
zerotot commented 1 year ago

首先添加了allocation failure callback相关接口,但是崩溃时并不会出现相关的错误打印

void heap_caps_alloc_failed_hook(size_t requested_size, uint32_t caps, const char *function_name)
{
  printf("%s was called but failed to allocate %d bytes with 0x%X capabilities. \n",function_name, requested_size, caps);
}

void app_main()
{
    ...
    esp_err_t error = heap_caps_register_failed_alloc_callback(heap_caps_alloc_failed_hook);
    ...
    void *ptr = heap_caps_malloc(allocation_size, MALLOC_CAP_DEFAULT);
    ...
}

之后我启用了heap tracing,设置等级Comprehensive;Standalone Mode,设置其中buffer(1000)在我怀疑的函数接口内使用ESP_ERROR_CHECK( heap_trace_start(HEAP_TRACE_LEAKS) );&&ESP_ERROR_CHECK( heap_trace_stop() );在这一过程中除了有我接口里调用的malloc这两个

250 bytes (@ 0x3fcddf8c) allocated CPU 0 ccount 0xd9f42c6c caller 0x4200d1d8:0x4200e7e5:0x4200f6af:0x42009ee6:0x4201a0e8:0x4201a132
0x4200d1d8: packetShadowPublishTopic at D:/shadow_report_task/shadow_process.c:604
173 bytes (@ 0x3fcde09c) allocated CPU 0 ccount 0xda15bfc4 caller 0x4200d2f8:0x4200e811:0x4200f6af:0x42009ee6:0x4201a0e8:0x4201a132
0x4200d2f8: packetShadowsToPayload at D:/Yshadow_process.c:730 (discriminator 13)

还会有下面的一次或多次下面几组的malloc

24 bytes (@ 0x3fcf2af8) allocated CPU 0 ccount 0xd9d2bc24 caller 0x42047e5f:0x42047ece:0x42047f38:0x4204885f:0x42048a41:0x420922a8
0x42047e5f: mem_malloc at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/mem.c:237

0x42047ece: do_memp_malloc_pool at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/memp.c:254

0x42047f38: memp_malloc at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/memp.c:350 
(discriminator 2)

0x4204885f: pbuf_alloc_reference at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/pbuf.c:337 (discriminator 2)

0x42048a41: pbuf_alloc at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/pbuf.c:237

0x420922a8: wlanif_input at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/port/esp32/netif/wlanif.c:197

16 bytes (@ 0x3fcf2b24) allocated CPU 0 ccount 0xd9d2c920 caller 0x42047e5f:0x42047ece:0x42047f38:0x42046d97:0x42046ddc:0x420922bb
0x42047e5f: mem_malloc at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/mem.c:237

0x42047ece: do_memp_malloc_pool at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/memp.c:254

0x42047f38: memp_malloc at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/core/memp.c:350 
(discriminator 2)

0x42046d97: tcpip_inpkt at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/api/tcpip.c:260 
(discriminator 2)

0x42046ddc: tcpip_input at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/lwip/src/api/tcpip.c:296

0x420922bb: wlanif_input at C:/Espressif/frameworks/esp-idf-v4.4.4/components/lwip/port/esp32/netif/wlanif.c:208