drivers: serial: nrf_uart & nrf_uarte infinite hang

[JordanYates]

Describe the bug
Both drivers fail to properly mediate access to the underlying hardware when used in poll mode.
Both drivers (uart_nrfx_uart.c and uart_nrfx_uarte.c) in their poll_out implementations, immediately start modifying hardware registers, then busy-wait on a hardware register.

Once one thread starts sending and blocks, a second thread will go through the same motions and block on the same register. Given that they clear the register on success, only one will ever be unblocked, leaving the other stuck.

The simplest scenario in which this happens is when using the logging subsystem and printk in a thread. When the TX's collide, the lower priority thread hangs. The uart_nrfx_uart.c variant I can only reproduce when trying to TX using the async api, even though the same issue appears to effect both drivers.

The issues only occurs when CONFIG_UART_ASYNC_API is enabled.

To Reproduce`

The simplest way to reproduce this issue is to smash the logger with log messages, and try and use printk. The easiest application for that is samples/bluetooth/scan_adv

UART Variant
proj.conf additions:

CONFIG_UART_ASYNC_API=y
CONFIG_BT_LOG_LEVEL_DBG=y

main.c additions:

#include <device.h>
#include <drivers/uart.h>
/* In the infinite loop */
u8_t test[8] = "TEST\n";
uart_tx(dev, test, 5, K_FOREVER);

UARTE Variant
proj.conf additions:

CONFIG_UART_ASYNC_API=y
CONFIG_BT_LOG_LEVEL_DBG=y
CONFIG_UART_0_NRF_UARTE=y

main.c additions:

/* In the infinite loop */
printk("TEST\n");

add nrf52840_pca10056.overlay

&uart0 {
	compatible = "nordic,nrf-uarte";
	status = "okay";
	current-speed = <115200>;
	tx-pin = <6>;
	rx-pin = <8>;
	rts-pin = <5>;
	cts-pin = <7>;
};

Compile and run:

west build -b nrf52840_pca10056 zephyr/samples/bluetooth/scan_adv
west flash

Open your serial program of choice, and the bluetooth log messages will typically stop the first time "TEST" prints.

Expected behavior
The logging thread should not infinitely hang.

Impact
Major problem, UART subsystem should not break on timing collisions.

Screenshots or console output
Example output of the time at which the logger hangs

[00:00:00.266,113] <dbg> bt_hci_core.bt_recv: buf 0x20003288 len 44
[00:00:00.266,113] <dbg> bt_hci_core.hci_event: event 0x3e
[00:00:00.266,113] <dbg> bt_hci_core.hci_le_meta_event: subevent 0x02
[00:00:00.266,143] <dbg> bt_hci_core.le_adv_report: Adv number of reports 1EST
TEST
TEST
TEST
TEST
TEST

Environment (please complete the following information):

• Commit SHA: 5af5407

[Mierunski]

I haven't noticed the bug in UARTE. Proposed a PR with fix for UART.
Note that using single UART instance from multiple contexts can result in fragmented/altered data. If you want such functionality, check tty API

[JordanYates]

I will try and replicate the UARTE version on another zephyr installation on another computer. I understand the fragmented data problem, given the current polling implementation of sending one character per call. However from my understanding the async api should never result in fragmented data.

[JordanYates]

Performed a clean install of zephyr from the v2.1 branch on a different computer.
After following the UARTE variant instructions, problem occurs 100% of the time on the first print.
Perhaps your environment does not have enough bluetooth packets to fill the logger?
Do you get dropped packets on the log?

[Mierunski]

I managed to reproduce the error (idk why it didn't reproduce first time), proposed a fix in PR.