peripheral_uart sample crashes with a lot of data

[BDA]

I am doing some profiling with the peripheral_uart sample.  It works as expected when I send small pieces of data, but when I start running a lot through it I get a crash.  The log indicates it's a heap corruption issue due to free being called twice on the same pointer?  I've captured the log at the point of the crash, and there does appear to be a double "rx_buf_released" right before it happens.  This is also the first point in the log where I see "rx_disabled", if that matters.  Any advice on how to debug this further and move forward would be greatly appreciated.

[00:01:06.398,406] <dbg> peripheral_uart.uart_cb: rx_buf_request
[00:01:06.403,686] <dbg> peripheral_uart.uart_cb: rx_rdy
[00:01:06.403,717] <dbg> peripheral_uart.uart_cb: rx_buf_released
[00:01:06.403,717] <dbg> peripheral_uart.uart_cb: rx_buf_request
[00:01:06.407,165] <dbg> peripheral_uart.uart_cb: rx_rdy
[00:01:06.407,196] <dbg> peripheral_uart.uart_cb: rx_buf_released
[00:01:06.407,196] <dbg> peripheral_uart.uart_cb: rx_buf_request
[00:01:06.467,315] <dbg> peripheral_uart.uart_cb: rx_rdy
[00:01:06.467,834] <dbg> peripheral_uart.uart_cb: rx_rdy
[00:01:06.467,864] <dbg> peripheral_uart.uart_cb: rx_buf_released
[00:01:06.467,864] <dbg> peripheral_uart.uart_cb: rx_buf_released
[00:01:06.467,895] <dbg> peripheral_uart.uart_cb: rx_disabled
[00:01:06.467,926] <dbg> peripheral_uart.uart_cb: rx_buf_request

ASSERTION FAIL [chunk_used(h, c)] @ WEST_TOPDIR/zephyr/lib/os/heap.c:154

unexpected heap state (double-free?) for memory at 0x20008f6c

[00:01:06.959,167] <err> os: r0/a1: 0x00000004 r1/a2: 0x0000009a r2/a3: 0x20001758
[00:01:06.959,167] <err> os: r3/a4: 0xfffffffc r12/ip: 0x00000000 r14/lr: 0x00011073[0m
[00:01:06.959,197] <err> os: xpsr: 0x61000000
[00:01:06.959,197] <err> os: Faulting instruction address (r15/pc): 0x00027ad4
[00:01:06.959,197] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
[00:01:06.959,228] <err> os: Current thread: 0x20001670 (unknown)
[00:01:07.537,811] <err> fatal_error: Resetting system

[Sigurd Hellesvik]

Hi

Try increasing the CONFIG_HEAP_MEM_POOL_SIZE.

Also, if you set CONFIG_THREAD_NAME, the name of the current thread will be listed instead of unknown, which can be useful for debugging.

Regards,
Sigurd Hellesvik

[BDA]

Increasing the size of the heap doesn't fix this problem.  I've verified via logging that the code as-written does try to free the same address twice.  Specifically, the loop processing the queue in ble_write_thread will free an address that has already been free'd by the UART state machine.  The only fix I've found so far is to allocate a second copy of the data for the queue to work on, and always free the uart copy in the UART_RX_BUF_RELEASED state.  The existing code tracks "current_buf" and "buf_release" variables to determine if it thinks it should free a buffer, but deleting those and doing this for the queue data seems to work consistently:

            bufCopy = k_malloc(sizeof(*buf));

            memcpy(bufCopy, buf, sizeof(*buf));

            k_fifo_put(&fifo_uart_rx_data, bufCopy);

[Sigurd Hellesvik]

Just to check:

Have you made any changes to the sample when you saw the error first?

Regards,
Sigurd Hellesvik

[BDA]

The sample without any changes crashes when I send it a lot of data over the serial port.  It still crashes if the only change I make is quadrupling the amount of heap.  With the changes I've described, it doesn't.

[Sigurd Hellesvik]

Perfect, just what I wanted to confirm.

I will report the bug to our developers, thank you for the report.

Let me know (or create a new ticket) if you face any more issues with the sample.

Regards,
Sigurd Hellesvik

[Sigurd Hellesvik]

Hi

This fix have been merged in https://github.com/nrfconnect/sdk-nrf/pull/7190.

Regards,
Sigurd Hellesvik