libUARTe sending TX buffer twice

[Jeff]

I'm having an odd issue with libUARTe sending a TX buffer twice.

I have a custom board using an nRF52832 running an application based on SDK 15.3.0.  The libUARTe code was backported from SDK 16.0.0.  It's using libUARTe to communicate data with an STM32.  The system has a debug interface board that provides JLink connections to both the Nordic and the STM32.

The normal operation is for the Nordic to receive some data over BLE and forward some of it to the STM32 via the UART.  Once the buffer containing the data is sent, it's cleared. 

What I've captured with a logic analyzer is that if the debug board is detached (I don't have any Nordic logging at this point since my only access is via RTT) is that I see the normal data getting transmitted and then about 7 ms later the cleared buffer is being transmitted.  Normal operation would be to see a packet getting sent to the STM32 about every 120 ms.

I haven't been able to reproduce the issue with the debug board attached.

I'm going to try enabling logging to flash and enabling the debugging on libUARTe and see if that sheds any light on the issue.

I'm looking for suggestions as to a possible cause of an unexpected transmission from libUARTe or if anyone has seen something like this before.  I don't think it's the software doing it since it's only happening with the debug board detached, but that's one of the things I hope to prove with the flash logging of debug messages.

thanks,

Jeff

[Susheel Nuguru]

I see the normal data getting transmitted and then about 7 ms later the cleared buffer is being transmitted.  Normal operation would be to see a packet getting sent to the STM32 about every 120 ms.

 This sounds like a software bug inside app or library which can be time critical behavior.

Very hard to tell what is the issue here without seeing your usage of the libuarte and also how you handle the RX and TX events.

[Stetina]

Hello, Did you managed to solve that issue? I see similar behavior and I'm not able to debug it.

[Jeff]

Yes we did find it.

It wasn't an issue with libUARTE, rather an error in our code.  It turned out to be a race condition due to setting a flag indicating that the port was in use after the transmission started rather than before.  That allowed two transmissions to start at nearly the same time with the second overwriting the first's buffer.

We ended up needed to enable CLI and flash logging to debug this since it was only happening for us after a DFU without a debug board attached.

Getting flash logging to work with a DFU was a bit challenging too since we needed to protect the flash log area from being erased during the DFU.  That involved setting NRF_DFU_APP_DATA_AREA_SIZE in the bootloader to account for the pages reserved in the app with FDS_VIRTUAL_PAGES_RESERVED, NRF_LOG_BACKEND_FLASH_START_PAGE and NRF_LOG_BACKEND_PAGES.