Patterns for heap corruption resolution ...

[kolban]

Imagine I am suffering from memory corruption issues. Using the latest ESP-IDF, I switch on "Comprehensive" heap memory debugging.

I then inject a call to:

heap_caps_check_integrity_all()

This detects a problem ... and reports:

CORRUPT HEAP: Invalid data at 0x3ffd0a90. Expected 0xfefefe got 0xfefefefd

My interpretation of this is that memory I previously allocated and then freed is still being accessed in the code. Ok ... so what do I know ... I see that I know the address of where invalid data has been detected. In this example, it is 0x3ffd0a90. Now my puzzle is to go deeper and figure out what this memory was used for when it was allocated and when/who freed it. And this is where the puzzles start.

I understand that I can perform a memory trace and record allocation and release records. Since I'm not looking for a leak (allocates but no frees) but am instead looking for allocation and then free but continued use .. I have to trace all the records. If I log all the records (and there are thousands of them) and then search for my address, I don't find it. Why? Well ... I suspect that if I allocate 100 bytes and then free that storage and then something "tinkers" with byte 20 within that range, the corrupt heap will not match a previous allocate/free.

Since an allocate "records" the start address and size, the I should be able to find my target address (x) as existing in one of the records such that

record_start <= x <= record_start + record_size

Since there are thousands of records, I can't do this by eyeball but instead have to code something to do this. And in there is the next puzzle ... when I call heap_caps_check_integrity_all() I get back a boolean indicating integrity is good or integrity is bad. If bad, the failed address is written to the console. That doesn't help me as I need the failing address in my app so I can then perform arithmetic against my array of trace records caught.

All this is starting to feel complex/strange ... and that makes me feel that I am not properly understanding the whole story. Is there a better technique that I should be using. If we find that a piece of heap has become corrupted and we suspect that it has been previously allocate, released but still being used ... how can I work this backwards to find out "To whom was this storage previously allocated so that I can examine to see if it recognizes that it was released?"

[cmorgan]

I'm having similar issues here with a v3.0-rc1 esp-idf based project. It shows up when hammering the libesphttpd server with the 'ab' utility but isn't always in the same location. I'm convinced its in my code but I'm having a really tough time tracking it down.

How did you enable the per-allocation memory tracing? How did you make out with your debugging?

[ESP_Angus]

Hi Kolban,

Sorry, I somehow missed this post when you made it back in November. Did you review the section in the documentatio about finding heap corruption?
https://esp-idf.readthedocs.io/en/lates ... corruption

It has quite a few suggested patterns.

Judging from the value you were getting, 0xfefefefd, I would guess that something is doing "x--" on the freed memory address (ie it's been freed so it's set to 0xfefefefe, then something subtracts 1 from this). This may give you a clue as to what the problem is.

How did you enable the per-allocation memory tracing? How did you make out with your debugging?

Heap tracing is documented here:
https://esp-idf.readthedocs.io/en/lates ... ap-tracing

[cmorgan]

I was unable to diagnose my issue with heap tracing. I was trying to trigger the heap trace output at intervals but I'm guessing it would have been more effective if I could have triggered it when the 'CORRUPT HEAP' was detected. Should I have modified the heap code to insert that tracing call at that point?


The failure was:

esp32> CORRUPT HEAP: Bad tail at 0x3ffe0a7c. Expected 0xbaad5678 got 0xcececece

but it wasn't particularly consistent, sometimes it would report a backtrace related to web server code, othertimes internal wifi memory allocation code. Sometimes I wouldn't occur at all.


After a bunch of analysis by inspection I was unable to find anything that looked wrong in terms of buffer access etc. I rewrote part of the web server to use static vs. dynamic memory and the issue has gone away. I'm under no illusion that the problem is actually fixed, only that by using static memory whatever overwrote the heap is no longer doing so.

[ESP_Angus]

I was unable to diagnose my issue with heap tracing. I was trying to trigger the heap trace output at intervals but I'm guessing it would have been more effective if I could have triggered it when the 'CORRUPT HEAP' was detected. Should I have modified the heap code to insert that tracing call at that point?

This might help. Or you can add calls like

Code: Select all

if (!heap_caps_check_integrity(MALLOC_CAP_8BIT, true)) {
   heap_trace_dump();
   abort();
}

Regularly and try to catch the heap corruption this way.

After a bunch of analysis by inspection I was unable to find anything that looked wrong in terms of buffer access etc. I rewrote part of the web server to use static vs. dynamic memory and the issue has gone away. I'm under no illusion that the problem is actually fixed, only that by using static memory whatever overwrote the heap is no longer doing so.

If it was crashing with CORRUPT HEAP during malloc/free then it is possible that the corruption just moved around. You can try calling heap_caps_check_integrity() regularly - as shown above - to verify if there's still corruption somewhere in the heap.

If heap_caps_check_integrity() always succeeds, probably the buffer you were overflowing is a buffer that you've moved to static memory. You may want to check that code again, as it's possible it's still overflowing the static buffer (heap checking can't find this).

[cmorgan]

Hi @ESP_Angus.

I've been continuing to debug, audit, and rewrite code here. I've found a handful of potential issues and fixed them.

I'm using latest master as of today (1c3dd23f) but had the same issues with 2.1 and the 3.0 release branch.

At this point I'm still able to reproduce the failure under a heavy wifi traffic load even after changing much of my memory allocation to static and fixing basically any corner case that I can find in my code.

My test process is to use the 'ab' utility to hit a http endpoint with a number of simultaneous connections, 8 currently.

There are some areas that I suspect:

- libesphttpd (I've been auditing this code like crazy and its getting tough finding suspects. I've considered switching http servers but I'm not aware of other stable alternatives.)
- cJSON (This is where most of the heap corruption crashes are detected as cJSON reallocates memory frequently as it appends data. cJSON has a suite of tests and runs under Valgrind. I haven't found any issues in this code.)
- lwip (are we using the latest version? are there known memory issues?)
- wifi (The issues I'm seeing are closely tied to traffic)
- hardware (is there something wrong with the module I have here? This is low on my list of suspects.)

At this point I'm getting stuck and looking for ideas. It's been so tough to debug and concerning for production stability, I can't ship with things in this state.

I've considered building up from a basic app to try to reproduce but I'm not looking forward to the amount of time to work my way up from scratch in case the issue does require all of the components I'm using in order to cause the error to occur.

Here are a number of just the heap issues, I've been tracking all of them separately:

CORRUPT HEAP: multi_heap.c:370 detected at 0x3ffe0a78
abort() was called at PC 0x4008870f on core 0
...
CORRUPT HEAP: Bad tail at 0x3ffe046c. Expected 0xbaad5678 got 0xcececece
CORRUPT HEAP: Bad head at 0x3ffe0474. Expected 0xabba1234 got 0xcececece
CORRUPT HEAP: Block 0xcecececc is outside heap (last valid block 0x3ffe0470)
430
abort() was called at PC 0x40135e1f on core 1
...
CORRUPT HEAP: multi_heap.c:173 detected at 0x3ffe0eb0
abort() was called at PC 0x4008834a on core 0
0x4008834a: multi_heap_assert at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:339
(inlined by) get_prev_free_block at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:173
...
CORRUPT HEAP: Bad tail at 0x3ffe1b7c. Expected 0xbaad5678 got 0xcececece
CORRUPT HEAP: Bad head at 0x3ffe1b84. Expected 0xabba1234 got 0xcececece
CORRUPT HEAP: Block 0xcecececc is outside heap (last valid block 0x3ffe1b80)

[cmorgan]

@ESP_Angus:

esp_buf_alloc() looks like a potential suspect, look at this trace:

CORRUPT HEAP: Bad tail at 0x3ffe0f70. Expected 0xbaad5678 got 0xcececece
CORRUPT HEAP: Bad head at 0x3ffe0f78. Expected 0xabba1234 got 0xcececece
CORRUPT HEAP: Block 0xcecececc is outside heap (last valid block 0x3ffe0f74)
l 433, needed 4
pBefore 0x0x3ffdf128, p->buff 0x0x3ffdf128
100 allocations trace (100 entry buffer)

8 bytes (@ 0x3ffe0f68) allocated CPU 1 ccount 0x7490f874 caller 0x4013f694:0x400f1a53
0x4013f694: ensure at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x400f1a53: esf_buf_alloc at ??:?
freed by 0x400f1c15:0x400ea0d2

0x400f1c15: esf_buf_recycle at ??:?

0x400ea0d2: ppRecycleRxPkt at ??:?


So while cJSON picked up on the error due to its allocation, esf_buf_alloc() was the last piece of code to allocate and free memory that is only a few bytes away from the corruption.

This is a closed binary library so its tough to review but this, combined with the fact that most crashes are related to heavy traffic and that I've switched almost everything in my system to static memory that is far away from these addresses, makes me wonder if there is an issue in libpp or related to packet handling.

Thoughts on how I can debug further?

[ESP_Angus]

Hi cmorgan,

It does look like you've closed in something here!

8 bytes (@ 0x3ffe0f68) allocated CPU 1 ccount 0x7490f874 caller 0x4013f694:0x400f1a53
0x4013f694: ensure at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x400f1a53: esf_buf_alloc at ??:?

This can't be right. This is a call stack which says esf_buf_alloc() calls ensure() in cJSON, but the WiFi drivers don't call any JSON functions and the ensure() function itself is a static function with no external linkage (if inlined into another function, this is shown in the monitor dump). If everything is working as intended, the caller of ensure() can only be a function defined in cJSON.c.

Impossible call stacks usually mean either the .elf file doesn't match the .bin on the device, or stack corruption (the first symptom of stack corruption may be heap corruption as cJSON calls realloc() on some random pointer). Some things to try:

• In "Toolchain options", set "Stack smashing protection mode" to "Overall".
• In Components->FreeRTOS config, set ""Set a debug watchpoint as a stack overflow check"

[cmorgan]

I'm testing now with the breakpoint change, already had stack protection overall enabled. I also suspected a bad stack but wasn't sure how the heap tracing worked and thought maybe because the heap was corrupted that could have resulted in the heap trace being corrupted. Imo this didn't seem likely but wasn't sure.

To keep things interesting, this is another related crash that doesn't have any heap tracing output but notice the call stack:

Code: Select all

CORRUPT HEAP: Bad tail at 0x3ffe0b14. Expected 0xbaad5678 got 0xcececece
CORRUPT HEAP: Bad head at 0x3ffe0b1c. Expected 0xabba1234 got 0xcececece
CORRUPT HEAP: Block 0xcecececc is outside heap (last valid block 0x3ffe0b18)
CORRUPT HEAP: multi_heap.c:173 detected at 0x3ffe0b18
abort() was called at PC 0x4008a612 on core 0
0x4008a612: multi_heap_assert at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:636
 (inlined by) get_prev_free_block at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:173


Backtrace: 0x4008b79b:0x3ffd0880 0x4008b8f4:0x3ffd08b0 0x4008a612:0x3ffd08e0 0x4008acdd:0x3ffd0910 0x4008b200:0x3ffd0940 0x4008364d:0x3ffd0970 0x40083c31:0x3ffd09a0 0x40083d4a:0x3ffd09d0 0x400f1c18:0x3ffd0a00 0x400ea0cf:0x3ffd0a20 0x400e4e55:0x3ffd0a50 0x400e1db2:0x3ffd0a70 0x400e1e09:0x3ffd0b40 0x400eae85:0x3ffd0b60 0x400ec9d3:0x3ffd0bb0
0x4008b79b: invoke_abort at /Users/cmorgan/projects/loadcontrol/esp-idf/components/esp32/./panic.c:582

0x4008b8f4: abort at /Users/cmorgan/projects/loadcontrol/esp-idf/components/esp32/./panic.c:582

0x4008a612: multi_heap_assert at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:636
 (inlined by) get_prev_free_block at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:173

0x4008acdd: multi_heap_free_impl at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:636

0x4008b200: multi_heap_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap_poisoning.c:313

0x4008364d: heap_caps_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./heap_caps.c:402

0x40083c31: trace_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./heap_trace.c:139

0x40083d4a: __wrap_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./heap_trace.c:139

0x400f1c18: esf_buf_recycle at ??:?

0x400ea0cf: ppRecycleRxPkt at ??:?

0x400e4e55: ic_ebuf_recycle_rx at ??:?

0x400e1db2: sta_input at ??:?

0x400e1e09: sta_rx_cb at ??:?

0x400eae85: ppRxPkt at ??:?

0x400ec9d3: ppTask at ??:?

[cmorgan]

I like the idea that this could be stack size related. I've considered that but I could have missed something.

I'm tracking stack usage through a console 'stack' command that retrieves the information from freertos and prints it out. The stack where the cJSON code is executed(esphttpd task) has approximately 1400 bytes of head room (high water mark) after I run the test for a few thousand requests, ie. the same code path in cJSON that sees the failure has been run a thousand times and I'm still seeing 1400 bytes of unused stack space. A few other stacks were within 200 bytes so I increased some of them such that their high water mark is 300 bytes or more.

Here is the output after processing a few thousand of the requests that eventually will crash the system:

Code: Select all

stack
18 tasks
CLI                     528	0	<1% 
esphttpd                1452	0	<1% 
IDLE                    340	0	<1% 
IDLE                    344	0	<1% 
temperature             400	0	<1% 
main                    1772	0	<1% 
Tmr Svc                 1248	0	<1% 
wsbcast                 1412	0	<1% 
tiT                     1508	0	<1% 
captdns_task            380	0	<1% 
ipc1                    384	0	<1% 
eventTask               1796	0	<1% 
mdns                    2060	0	<1% 
wifiStateThread         388	0	<1% 
wifi                    940	0	<1% 
esp_timer               3776	0	<1% 
pmT                     1904	0	<1% 
ipc0                    392	0	<1%

Here are two crashes caught after enabling the breakpoint on stack overflow and after increasing a few of the closest stacks. I suspect these stacks are closer due to the heap tracing, they never got as close prior to enabling all of the debug features in the heap.

Code: Select all

CORRUPT HEAP: multi_heap.c:173 detected at 0x3ffe1d70
abort() was called at PC 0x4008a666 on core 0
0x4008a666: multi_heap_assert at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:636
 (inlined by) get_prev_free_block at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:173


Backtrace: 0x4008b7ef:0x3ffd0aa0 0x4008b948:0x3ffd0ad0 0x4008a666:0x3ffd0b00 0x4008ad31:0x3ffd0b30 0x4008b254:0x3ffd0b60 0x40083651:0x3ffd0b90 0x40083c35:0x3ffd0bc0 0x40083d4e:0x3ffd0bf0 0x400f1c0c:0x3ffd0c20 0x400ea0cf:0x3ffd0c40 0x400e4e55:0x3ffd0c70 0x400e1db2:0x3ffd0c90 0x400e1e09:0x3ffd0d60 0x400eae85:0x3ffd0d80 0x400ec9d3:0x3ffd0dd0
0x4008b7ef: invoke_abort at /Users/cmorgan/projects/loadcontrol/esp-idf/components/esp32/./panic.c:582

0x4008b948: abort at /Users/cmorgan/projects/loadcontrol/esp-idf/components/esp32/./panic.c:582

0x4008a666: multi_heap_assert at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:636
 (inlined by) get_prev_free_block at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:173

0x4008ad31: multi_heap_free_impl at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:636

0x4008b254: multi_heap_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap_poisoning.c:313

0x40083651: heap_caps_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./heap_caps.c:402

0x40083c35: trace_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./heap_trace.c:139

0x40083d4e: __wrap_free at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./heap_trace.c:139

0x400f1c0c: esf_buf_recycle at ??:?

0x400ea0cf: ppRecycleRxPkt at ??:?

0x400e4e55: ic_ebuf_recycle_rx at ??:?

0x400e1db2: sta_input at ??:?

0x400e1e09: sta_rx_cb at ??:?

0x400eae85: ppRxPkt at ??:?

0x400ec9d3: ppTask at ??:?

And here is another one that looks like it came from inside of the http server task:

Code: Select all

CORRUPT HEAP: Bad tail at 0x3ffe1a84. Expected 0xbaad5678 got 0xfebaad56
assertion "head != NULL" failed: file "/Users/cmorgan/projects/loadcontrol/esp-idf/Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Register dump:
PC      : 0x400898b6  PS      : 0x00060b34  A0      : 0x800887ca  A1      : 0x3ffde480  
0x400898b6: vListInsert at /Users/cmorgan/projects/loadcontrol/esp-idf/components/freertos/./list.c:188 (discriminator 1)

A2      : 0x3ffcc5d8  A3      : 0x3ffdefc4  A4      : 0x3ffb1034  A5      : 0x00000001  
A6      : 0x00060b23  A7      : 0x3ffdeb30  A8      : 0x3ffdefc4  A9      : 0x3ffdefc4  
A10     : 0x00000015  A11     : 0x00000015  A12     : 0x3ffde690  A13     : 0x00000001  
A14     : 0x00060b23  A15     : 0xfefefefe  SAR     : 0x00000005  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xffffffff  

Backtrace: 0x400898b6:0x3ffde480 0x400887c7:0x3ffde4b0 0x40086df7:0x3ffde4e0 0x40086e85:0x3ffde520 0x40084159:0x3ffde550 0x40084312:0x3ffde580 0x40130ddd:0x3ffde5b0 0x401305c3:0x3ffde5e0 0x4000bd83:0x3ffde610 0x4000117d:0x3ffde630 0x400592fe:0x3ffde650 0x4005937a:0x3ffde670 0x401272e1:0x3ffde690 0x40124189:0x3ffde7b0 0x4011db0d:0x3ffdeac0 0x4008b171:0x3ffdeb10 0x4008b42a:0x3ffdeb40 0x4008af22:0x3ffdeb70 0x400f711d:0x3ffdebb0 0x4013f6a6:0x3ffdebe0 0x4013f9bf:0x3ffdec10 0x4013fdd1:0x3ffdec40 0x4013fd10:0x3ffdec70 0x4013fe0c:0x3ffdeca0 0x4013fd10:0x3ffdecd0 0x4013ff25:0x3ffded00 0x401405c6:0x3ffded50 0x40112da5:0x3ffded80 0x40142030:0x3ffdede0 0x401422d5:0x3ffdee20 0x40141332:0x3ffdee60
0x400898b6: vListInsert at /Users/cmorgan/projects/loadcontrol/esp-idf/components/freertos/./list.c:188 (discriminator 1)

0x400887c7: vTaskPlaceOnEventList at /Users/cmorgan/projects/loadcontrol/esp-idf/components/freertos/./tasks.c:4571

0x40086df7: xQueueGenericReceive at /Users/cmorgan/projects/loadcontrol/esp-idf/components/freertos/./queue.c:2037

0x40086e85: xQueueTakeMutexRecursive at /Users/cmorgan/projects/loadcontrol/esp-idf/components/freertos/./queue.c:2037

0x40084159: lock_acquire_generic at /Users/cmorgan/projects/loadcontrol/esp-idf/components/newlib/./locks.c:155

0x40084312: _lock_acquire_recursive at /Users/cmorgan/projects/loadcontrol/esp-idf/components/newlib/./locks.c:169

0x40130ddd: uart_write at /Users/cmorgan/projects/loadcontrol/esp-idf/components/vfs/./vfs_uart.c:295

0x401305c3: esp_vfs_write at /Users/cmorgan/projects/loadcontrol/esp-idf/components/vfs/./vfs.c:506

0x401272e1: __sbprintf at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vfprintf.c:486 (discriminator 1)

0x40124189: _vfprintf_r at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vfprintf.c:875

0x4011db0d: printf at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/printf.c:58

0x4008b171: verify_allocated_region at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap_poisoning.c:313

0x4008b42a: multi_heap_internal_check_block_poisoning at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap_poisoning.c:327

0x4008af22: multi_heap_check at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./multi_heap.c:636

0x400f711d: heap_caps_check_integrity at /Users/cmorgan/projects/loadcontrol/esp-idf/components/heap/./heap_caps.c:413

0x4013f6a6: ensure at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x4013f9bf: print_string_ptr at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x4013fdd1: print_object at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x4013fd10: print_value at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x4013fe0c: print_object at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x4013fd10: print_value at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x4013ff25: print at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x401405c6: cJSON_Print at /Users/cmorgan/projects/loadcontrol/esp-idf/components/json/library/cJSON.c:2655

0x40112da5: cgiTemperature at /Users/cmorgan/projects/loadcontrol/app/main/api/cgiTemperature.c:108

0x40142030: httpdProcessRequest at /Users/cmorgan/projects/loadcontrol/app/components/libesphttpd/core/httpd.c:603

0x401422d5: httpdRecvCb at /Users/cmorgan/projects/loadcontrol/app/components/libesphttpd/core/httpd.c:821

0x40141332: platHttpServerTask at /Users/cmorgan/projects/loadcontrol/app/components/libesphttpd/core/httpd-freertos.c:720