Attached is a project that exhibits this problem. In addition to reporting BUSY, the uart_tx call actually takes the buffer and sends it out, calling TX_DONE for it. The problem there is that it produces a double free because when BUSY is reported the buffer gets put on a fifo, and then when the first TX DONE comes in, the callback tries to send it again, and free it again when the second TX_DONE is issued.
If line 202 of appUart.c is commented out, it all works fine (at least no crashes). But when the buffer is put on the fifo, it is used and freed twice. Below is a log that shows this happening:
The first uart_tx is issued in uart_init() a leftover from the uart sample code. The application tries to send something for the first time at time index 16.069.396. The uart_tx() function reports BUSY correctly here (TX_DONE has not been issued yet for the first call). The buffer is queued on the FIFO.
The first TX_DONE comes in at time index 16.072.113, the buffer 0x20009ad8 is freed, and the buffer 0x20009d58 that was queued is pooped and sent. The TX_DONE for that buffer comes in at time index 16.073.242, and the buffer is freed.
The next transmission attempt is at time index 17.069.854. Here, uart_tx() reports BUSY incorrectly, so the buffer gets queued on the fifo. However, the buffer was actually used as the TX_DONE for it come back at time index 17.070.892, and as such gets freed. The problem is, it is also in the fifo, so it gets popped and sent again. The TX_DONE comes in for it, it gets freed again, which of course causes a crash.
I have run this basic code on a PCA10040 which has a 52832 and it appears to run correctly. It is only on the 52840 boards that this occurs. I saw a similar question posted a couple years ago, but there was no resolution to it. Any insight as to what I might be missing, or how to fix this issue, is appreciated!
The project is below the log.
*** Booting Zephyr OS build v3.3.99-ncs1-1 ***
[00:00:16.068,725] <wrn> lcm_log_main: appUart_init: Sending startup uart_dat_t= 0x0x20009ad8
[00:00:16.068,756] <inf> lcm_log_main: uart_cb: ENTERED
[00:00:16.068,786] <inf> lcm_log_main: UART_RX_BUF_REQUEST
[00:00:16.068,847] <inf> lcm_log_main: uart_cb: LEAVING
[00:00:16.068,908] <inf> lcm_log_main: Blinking...0
[00:00:16.068,939] <inf> lcm_log_main: lcmCmdProcessIncommingCommand: Got cmd string: hello there, length 11
[00:00:16.069,183] <inf> lcm_log_main: lcmCmd_WorkHandler: Got cmd string: hello there, length 11
[00:00:16.069,183] <inf> lcm_log_main: ipc_host_uart_txBuf
[00:00:16.069,274] <inf> lcm_log_main: appUart_Transmit: ENTERED: Got 11 bytes to send.....
[00:00:16.069,305] <inf> lcm_log_main: Uart Tx Data:
68 65 6c 6c 6f 20 74 68 65 72 65 |hello th ere
[00:00:16.069,396] <inf> lcm_log_main: appUart_Transmit: Sending uart_data_t= 0x0x20009d58
[00:00:16.069,427] <wrn> lcm_log_main: appUart_Transmit: Failed to send data: -16, retrying...0x0x20009d58
[00:00:16.069,519] <inf> lcm_log_main: appUart_Transmit: LEAVING
[00:00:16.072,082] <inf> lcm_log_main: uart_cb: ENTERED
[00:00:16.072,113] <inf> lcm_log_main: UART_TX_DONE
[00:00:16.072,143] <inf> lcm_log_main: uart_cb: Freeing uart_data_t= 0x0x20009ad8
[00:00:16.072,174] <inf> lcm_log_main: uart_cb: Popped and sending uart_data_t 0x0x20009d58
[00:00:16.072,235] <inf> lcm_log_main: uart_cb: UART_TX_DONE LEAVING 3
[00:00:16.072,265] <inf> lcm_log_main: uart_cb: LEAVING
[00:00:16.073,242] <inf> lcm_log_main: uart_cb: ENTERED
[00:00:16.073,242] <inf> lcm_log_main: UART_TX_DONE
[00:00:16.073,272] <inf> lcm_log_main: uart_cb: Freeing uart_data_t= 0x0x20009d58
[00:00:16.073,303] <inf> lcm_log_main: uart_cb: UART_TX_DONE LEAVING 2
[00:00:17.069,305] <inf> lcm_log_main: Blinking...1
[00:00:17.069,[00:00:17.069,610] <inf> lcm_log_main: lcmCmd_WorkHandler: Got cmd string: hello there, length 11
[00:00:17.069,641] <inf> lcm_log_main: ipc_host_uart_txBuf
[00:00:17.069,732] <inf> lcm_log_main: appUart_Transmit: ENTERED: Got 11 bytes to send.....[0m
[00:00:17.069,763] <inf> lcm_log_main: Uart Tx Data:
68 65 6c 6c 6f 20 74 68 65 72 65 |hello th ere
[00:00:17.069,854] <inf> lcm_log_main: appUart_Transmit: Sending uart_data_t= 0x0x20009cf8
[00:00:17.069,976] <wrn> lcm_log_main: appUart_Transmit: Failed to send data: -16, retrying...0x0x20009cf8
[00:00:17.070,007] <inf> lcm_log_main: appUart_Transmit: LEAVING
[00:00:17.070,861] <inf> lcm_log_main: uart_cb: ENTERED
[00:00:17.070,892] <inf> lcm_log_main: UART_TX_DONE
[00:00:17.070,922] <inf> lcm_log_main: uart_cb: Freeing uart_data_t= 0x0x20009cf8
[00:00:17.070,983] <inf> lcm_log_main: uart_cb: Popped and sending uart_data_t 0x0x20009cf8
[00:00:17.071,014] <inf> lcm_log_main: uart_cb: UART_TX_DONE LEAVING 3
[00:00:17.071,044] <inf> lcm_log_main: uart_cb: LEAVING
[00:00:17.071,990] <inf> lcm_log_main: uart_cb: ENTERED
[00:00:17.071,990] <inf> lcm_log_main: UART_TX_DONE
[00:00:17.072,021] <inf> lcm_log_main: uart_cb: Freeing uart_data_t= 0x0x20009cf8
[00:00:17.072,052] <err> os: ***** BUS FAULT *****
[00:00:17.072,052] <err> os: Precise data bus error
[00:00:17.072,082] <err> os: BFAR Address: 0x6c0080
[00:00:17.072,113] <err> os: r0/a1: 0x006c0080 r1/a2: 0x20009cf4 r2/a3: 0x0000000f
[00:00:17.072,113] <err> os: r3/a4: 0x00000040 r12/ip: 0x00000002 r14/lr: 0x0002bdef
[00:00:17.072,143] <err> os: xpsr: 0x21000012
[00:00:17.072,143] <err> os: Faulting instruction address (r15/pc): 0x0002c0c4
[00:00:17.072,204] <err> os: >>> ZEPHYR FATAL ERROR 25: Unknown error on CPU 0
