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]

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. 

[Susheel Nuguru]

issue created NRFFOSDK-13129