UART interrupt missing

[Carlos]

Hello,

I am using SDK SDK_15.3.0_59ac345 with soft device in application that controls a GPS IC from UART (AT command), also the application is running in background beacon adv. (timeslot) and from time to time ble normal adv and gatt connection etc.

Everything is working fine but from time to time UART gets freeze, I mean cannot get data from UART.

I use flow control on, and UART (not UARTE), together with app_uart_fifo at 115200, init is like this:

app_uart_comm_params_t const comm_params =
{
.rx_pin_no = RX_PIN_NUMBER,
.tx_pin_no = TX_PIN_NUMBER,
.rts_pin_no = RTS_PIN_NUMBER,
.cts_pin_no = CTS_PIN_NUMBER,
.flow_control = eFlow,
.use_parity = false,
.baud_rate = uiUartSpeed
};

APP_UART_FIFO_INIT(&comm_params,
UART_RX_BUF_SIZE,
UART_TX_BUF_SIZE,
uart_event_handle,
APP_IRQ_PRIORITY_HIGHEST,
err_code);
APP_ERROR_CHECK(err_code);

What I found after several days of investigation, is that the lose happens when Nordic is loaded with many task.

I can reproduce if I force to pair during UART transmission (with beacon timeslot in background), from this point even I wait forever I cannot get any interrupt (nor data if try to force reading) from app_uart_get() in the interrupt handler.

Going down to the driver I found that if in this situation I make a manual byte read from UART (DataArray[uiIndex] = NRF_UART0->RXD) the data is there and just after this read everthing continue normally without any data lose till next freeze.

Actually I have a background task that if there are more than 150ms without interrupts while I am reading from UART it makes this manual data reading to unlock the system.

I added some prints on nrfx_uart.c on uart_irq_handler at top of the function I added:

NRFX_LOG_INFO("Function: %s, interrrupt (rx)%d (tx)%d (txrdy)%d (rxrdy)%d (err)%d", __func__,
nrf_uart_int_enable_check(p_uart, NRF_UART_INT_MASK_RXDRDY),
nrf_uart_int_enable_check(p_uart, NRF_UART_INT_MASK_TXDRDY),
nrf_uart_event_check(p_uart, NRF_UART_EVENT_TXDRDY),
nrf_uart_event_check(p_uart, NRF_UART_EVENT_RXDRDY),
nrf_uart_event_check(p_uart, NRF_UART_EVENT_ERROR));

This means every interrupt I get a print out but when system becomes locked no printout is done so the interrupt doesn't come.

From the log (RTT) I get this:

***** Here I send AT+QGPSLOC=2 commadn by UART*********

<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)1 (rxrdy)0 (err)0
<00> info> app: UART APP_UART_TX_EMPTY

***** Here I start reading from UART echo+command reply*********

<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading

***** Here system is waiting more than 150ms without any new character read from UART and mannually read a 'S' byte 5th of the reply buffer*********

<00> info> app: at_read_command: Cannot receive message, S byte 5

***** From here everything goes on normally*********

<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading
<00> info> UART: Function: uart_irq_handler, interrrupt (rx)1 (tx)1 (txrdy)0 (rxrdy)1 (err)0
<00> info> UART: Function: rx_byte, reading

***** Here reply echo+answer end and took 184ms (150ms elapsed) normally doesn't take more than 30ms with log on and without log 3/4ms*********

<00> info> app: sleep_duration(OK)=6051-184

<00> info> AT+QGPSLOC=2
+CME ERROR: 516

This happens randomly at different position, most of the times works fine.

It seems that NRF_UART_EVENT_RXDRDY doesn't come (before manual NRF_UART0->RXD I check RXDRDY but it is not set), I read documentation and the it seems that but only way that this event is not generated is because already set to 0 after a read but this case is not because byte is on NRF_UART0->RXD and the only place the byte is read is on rx_byte function (also in log) which always set to 0 and then read which is normal sequence.

Is there any clue or way to understand why this happen?

Thank you!

[Carlos]

Hi Susheel,

I am using Nordic SDK code as it is for uart, and the nrf_drv_uart_rx I think is called by event_handler in app_uart_fifo.c and not by my code.

The only thing I am doing is calling init using the macro I copied in top of this case:

APP_UART_FIFO_INIT(&comm_params,
UART_RX_BUF_SIZE,
UART_TX_BUF_SIZE,
uart_event_handle,
APP_IRQ_PRIORITY_HIGHEST,
err_code);
APP_ERROR_CHECK(err_code);

And in my uart_event_handle in case of APP_UART_DATA_READY just get data from app_uart_get()

The code running below is Nordic's original code.

Therefore, in my checking the app_uart_init() in app_uart_fifo.c install the handler with the priority APP_IRQ_PRIORITY_HIGHEST and this is the code which is calling to nrf_drv_uart_rx() every NRF_DRV_UART_EVT_RX_DONE event after it adds data to the fifo and call to my handler.

Then going down, nrfx_uart_init() in nrfx_uart.c is the function that install uart fifo event handler together with the nrfx_uart_0_irq_handler

nrfx_uart_0_irq_handler()->uart_irq_handler()->rx_byte()->nrf_uart_event_clear()+nrf_uart_rxd_get()->rx_done_event()->call fifo handler that calls to nrf_drv_uart_rx ()->rx_enable()->nrf_uart_event_clear(NRF_UART_EVENT_RXDRDY) again that is the one deleted by my test

 

If I do not clear the NRF_UART_EVENT_RXDRDY in rx_enable() seems to be everthing working fine and therefore the only possibility is that the UART task which sets NRF_UART_EVENT_RXDRDY to 1 is called between nrf_uart_rxd_get() and rx_enable() interrumping the interrupt.

I am a bit lost but I am sure you can check this better than me!

Thanks

[Susheel Nuguru]

sorry for the late reply, it seems you are right, I did some experimenting in nrfx_uart.c and it seems that clearing the RXDRDY event in rx_enable creates a race condition. Not clearing it seems to solve the issue. I will forward this behavior to the developer team.

Carlos said:

I am a bit lost but I am sure you can check this better than me!

You don't seem to be lost, seems to have good understanding on the nrfx_uart :)

[Carlos]

Thanks Susheel! :-)

From our side, on the extensive testing of the patch during these days we could not reproduce again this problem and could not find any side effect so we applied this change.

If finally, your developement team confirm this changer or find a better solution or any any possible side effect I appreciate you can update the ticket. Thank you.

Best regards,

[Susheel Nuguru]

Sure Carlos, I will keep this ticket open as a reminder to myself until I can update you in the future.

[Susheel Nuguru]

I have now tested this myself extensively and I was now able to reproduce this myself. I am going to create an internal ticket that it was a bug before and the suggested fix and I will close this case.