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!

[Susheel Nuguru]

.flow_control = eFlow,

What is the value of eFlow here? if it is false, then there is a possibility that there are some overflow errors in the driver that are not handled. For testing purposes, I would recommend to enable flow control just to confirm that it is infact an overflow error in the driver.

[Carlos]

It is APP_UART_FLOW_CONTROL_ENABLED

Baud is NRF_UART_BAUDRATE_115200

PIN numbers are default ones

and buffers size is 512

These are the missing values.

Flow control I am sure it is working because as I explained even waiting 150ms the data is there and it is not lost and I can follow reading next character without any missing one means that other ic is waiting to send more characters till I read. The problem is that rxrdy is not raised.

Regards,

[Susheel Nuguru]

I am not sure we can trust those logs 100%.

Normally there are latencies to flush the log from the time NRF_LOG_INFO is being called. And during that time, the real state in the register might have changed.

I would suggest you to do two things.

1. Set a breakpoint in nrfx_uart.c -> uart_irq_handler-> inside the if condition which is executed if there is NRF_UART_EVENT_ERROR set. 
2. Start your program in debugger mode, and try to repeat this error condition. If you notice the delay in reply is more than it should then halt/pause the execution (do not stop the debugger or reset the device, but halt the state to retain hardware state). At this point check if the RXRDY register bit is still set. 

If the breakpoint from 1. is hit, then we know that the error handling is something that you would like to handle differently. Inside nrf_log_backend_uart.c the uart_evt_handler shows that the error is simple ignored, which for some application could be a issue.

[Carlos]

Hi Susheel,

I understood your suggestions, thank you for checking.

In the meantime I was trying to check places where RXDRDY is cleared. I found a possible problem however I am not sure about the structure of your driver.

If I remove clearing the RXDRDY in rx_enable() function in nrfx_uart.c I cannot reproduce the problem, I have been checking long time and could not reproduce it again, additionally I removed all log and set original enviroment and also could not reproduce the problem. I would need more time to fully check but it is very significative because without this change problem can be reproduced easilly when activating ble paring (flash write inside) and beacon timeslot together with uart and now cannot reproduce it after several hours of trying.

My guess:

Just after every interrupt of Rx the uart_event_handler in app_uart_fifo.c driver restart by calling nrf_drv_uart_rx() to read a new byte, at this point the function will call to rx_enable that clears the RXDRDY bit without checking if it has been already raised by a new interrupt. I think this is wrong, in normal environment the delay from processing the interrupt till nrf_drv_uart_rx() is may be very few but with cpu overload could be the case that new uart byte arrived from interrupt process ends till a new call to nrf_drv_uart_rx is done (115200bps and cpu overload), if this happens then the RXDRDY may be cleared and then a new interrupt is not generated... This is my guess 

Additionally, I think this call to clear RXDRDY here is not necessary because it is already done when received last byte inside interrupt before reading as specs says. In fact, without this call my software is working fine now, however I don't know all possible test cases and why this was introduced.

Would you please review my suggestion?

Change:

static void rx_enable(nrfx_uart_t const * p_instance)
{
nrf_uart_event_clear(p_instance->p_reg, NRF_UART_EVENT_ERROR);
- nrf_uart_event_clear(p_instance->p_reg, NRF_UART_EVENT_RXDRDY);
+// nrf_uart_event_clear(p_instance->p_reg, NRF_UART_EVENT_RXDRDY);
nrf_uart_task_trigger(p_instance->p_reg, NRF_UART_TASK_STARTRX);
}

Thank you

[Susheel Nuguru]

Carlos said:

Just after every interrupt of Rx the uart_event_handler in app_uart_fifo.c driver restart by calling nrf_drv_uart_rx() to read a new byte, at this point the function will call to rx_enable that clears the RXDRDY bit without checking if it has been already raised by a new interrupt. I think this is wrong, in normal environment the delay from processing the interrupt till nrf_drv_uart_rx() is may be very few but with cpu overload could be the case that new uart byte arrived from interrupt process ends till a new call to nrf_drv_uart_rx is done (115200bps and cpu overload), if this happens then the RXDRDY may be cleared and then a new interrupt is not generated... This is my guess 

 You are onto something here. Let me try to explain you the flow. The RXRDY EVENT is not set by the interrupt, it is the other way around. The UART sets this event bit first which infact is communicated to ARM->NVIC. 

Well I think you are calling nrf_drv_uart_rx from a context that is higher in priority than the UART ISR priority. Otherwise the context that called nrf_drv_uart_rx should not continue from the instant a new RXRDY_EVENT is pended. Can you please confirm from which context you are calling the RX function? I cannot see any other possible scenario that the nrf_drv_uart_rx function is able to clear a new pended event bit. 

If nrf_drv_uart_rx is called from lower priority context (than UART_ISR priority) then it will be without question only be able to clear a processed RXRDY bit