LPUART first message fails

[Miguel Ferreira]

Hi,

Currently Im developing on a custom board that has a NRF52840 and a NRF9160. Both MCUs communicate using UART Async API and I added the support for LPUART on both sides - the firmware used in the NRF9160 is the SLM and on the NRF52840 a custom one. Without the using LPUART, this setup works as expected. However, with LPUART the first message doesn't have a reply from the NRF9160. In this case I sent "AT\r\n" and would expect a "\r\nOK\r\n" reply. Bellow are the logs from the LPUART driver.

Thank you!

NRF9160 SLM
*** Booting Zephyr OS build v3.3.99-ncs1-2 ***
[00:00:00.251,129] <dbg> slm: main: RR: 0x00000000
[00:00:00.493,835] <inf> slm: Serial LTE Modem
[00:00:00.493,865] <dbg> slm_at_host: slm_uart_configure: Set uart baudrate to: 115200, hw flow control 0
[00:00:00.594,055] <dbg> lpuart: api_rx_enable: RX: Enabling
[00:00:00.595,733] <dbg> slm_fota: slm_fota_post_process: FOTA result 0,0,0
[00:00:00.598,266] <inf> slm_at_host: at_host init done
[00:00:14.455,749] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
[00:00:14.455,810] <dbg> lpuart: activate_rx: RX: Ready
[00:00:14.456,329] <dbg> lpuart: rdy_pin_handler: RX: End detected.
[00:00:14.456,878] <dbg> lpuart: uart_callback: RX: Ready buf:0x20015f0b, offset: 0,len: 4
[00:00:14.456,909] <dbg> lpuart: uart_callback: Rx buf released
[00:00:14.456,939] <dbg> lpuart: uart_callback: Rx disabled
[00:00:14.456,970] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
[00:00:14.457,000] <dbg> slm_at_host: uart_callback: RX_DISABLED
[00:00:14.457,031] <dbg> slm_at_host: cmd_send: RX
                                      41 54                                            |AT               
[00:00:14.463,562] <dbg> slm_at_host: uart_send: TX
                                      0d 0a 4f 4b 0d 0a                                |..OK..  

// !THIS FIRST OK IS NOT SENT!        
[00:00:14.463,592] <dbg> lpuart: api_tx: tx len:6
[00:00:14.463,623] <dbg> lpuart: api_rx_enable: RX: Enabling
[00:00:19.458,801] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
[00:00:19.458,862] <dbg> lpuart: activate_rx: RX: Ready
[00:00:19.458,923] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:19.459,381] <dbg> lpuart: rdy_pin_handler: RX: End detected.
[00:00:19.459,472] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:19.459,930] <dbg> lpuart: uart_callback: RX: Ready buf:0x20015f0b, offset: 0,len: 4
[00:00:19.459,960] <dbg> lpuart: uart_callback: Rx buf released
[00:00:19.459,991] <dbg> lpuart: uart_callback: Rx disabled
[00:00:19.460,021] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
[00:00:19.460,083] <dbg> slm_at_host: uart_callback: RX_DISABLED
[00:00:19.460,113] <dbg> slm_at_host: cmd_send: RX
                                      41 54                                            |AT               
[00:00:19.466,644] <dbg> slm_at_host: uart_send: TX
                                      0d 0a 4f 4b 0d 0a                                |..OK..           
[00:00:19.466,674] <dbg> lpuart: api_tx: tx len:6
[00:00:19.466,705] <dbg> lpuart: api_rx_enable: RX: Enabling
[00:00:34.460,845] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
[00:00:34.460,906] <dbg> lpuart: activate_rx: RX: Ready
[00:00:34.460,968] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:34.461,425] <dbg> lpuart: rdy_pin_handler: RX: End detected.
[00:00:34.461,547] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:34.462,005] <dbg> lpuart: uart_callback: RX: Ready buf:0x20015f0b, offset: 0,len: 4
[00:00:34.462,036] <dbg> lpuart: uart_callback: Rx buf released
[00:00:34.462,066] <dbg> lpuart: uart_callback: Rx disabled
[00:00:34.462,066] <dbg> lpuart: api_rx_buf_rsp: buf rsp, state:5
[00:00:34.462,127] <dbg> slm_at_host: uart_callback: RX_DISABLED
[00:00:34.462,158] <dbg> slm_at_host: cmd_send: RX
                                      41 54                                            |AT               
[00:00:34.468,688] <dbg> slm_at_host: uart_send: TX
                                      0d 0a 4f 4b 0d 0a                                |..OK..           
[00:00:34.468,719] <dbg> lpuart: api_tx: tx len:6
[00:00:34.468,719] <dbg> lpuart: api_rx_enable: RX: Enabling
[00:00:44.475,982] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
[00:00:44.476,013] <dbg> lpuart: activate_rx: RX: Ready
[00:00:44.476,104] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:44.476,562] <dbg> lpuart: rdy_pin_handler: RX: End detected.
[00:00:44.476,654] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:44.477,111] <dbg> lpuart: uart_callback: RX: Ready buf:0x20015f0b, offset: 0,len: 4
[00:00:44.477,142] <dbg> lpuart: uart_callback: Rx buf released
[00:00:44.477,172] <dbg> lpuart: uart_callback: Rx disabled

NRF52840

[00:00:00.119,323] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.119,354] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:00.119,354] <inf> fs_nvs: data wra: 0, 0
[00:00:00.492,187] <dbg> lpuart: api_rx_enable: RX: Enabling
[00:00:00.765,411] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
[00:00:00.765,808] <dbg> lpuart: activate_rx: RX: Ready
[00:00:01.037,780] <dbg> lpuart: rdy_pin_handler: RX: End detected.
[00:00:01.038,330] <dbg> lpuart: uart_callback: Rx buf released
[00:00:01.038,360] <err> lpuart: Empty receiver state:4
[00:00:01.038,391] <dbg> lpuart: uart_callback: Rx disabled
[00:00:01.038,421] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
[00:00:01.038,757] <dbg> lpuart: activate_rx: RX: Ready
[00:00:15.492,553] <dbg> lpuart: api_tx: tx len:4
[00:00:15.492,736] <dbg> lpuart: rdy_pin_handler: RX: End detected.
[00:00:15.492,767] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:15.493,164] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:15.493,286] <dbg> lpuart: uart_callback: Rx buf released
[00:00:15.493,316] <err> lpuart: Empty receiver state:4
[00:00:15.493,347] <dbg> lpuart: uart_callback: Rx disabled
[00:00:15.493,774] <dbg> lpuart: rdy_pin_handler: RX: Request detected.
[00:00:15.494,079] <dbg> lpuart: activate_rx: RX: Ready
Ping failed
Sending ping
[00:00:20.495,178] <dbg> lpuart: api_tx: tx len:4
[00:00:20.495,300] <dbg> lpuart: rdy_pin_handler: RX: End detected.
[00:00:20.495,361] <dbg> lpuart: req_pin_handler: TX: Confirmed, starting.
[00:00:20.495,727] <dbg> lpuart: tx_complete: TX completed, pin idle
[00:00:20.495,880] <dbg> lpuart: uart_callback: RX: Ready buf:0x2000b088, offset: 0,len: 5
RECEIVED:
OK

[Kazi Afroza Sultana]

Hello,

How have you set the LPUART configurations? If the packet size and buffer size are accordance to the message size?

[Miguel Ferreira]

Hi,

Meanwhile I found a "dirty" solution to this. But first going to your question. The LPUART configs are being set by using uart_configure function.

struct uart_config uart_cfg = {
/* data */
.baudrate = 115200,
.parity = UART_CFG_PARITY_NONE,
.stop_bits = UART_CFG_STOP_BITS_1,
.data_bits = UART_CFG_DATA_BITS_8,
.flow_ctrl = UART_CFG_FLOW_CTRL_NONE};

Device Tree:

&uart1 {
/* UART to NRF91 */
compatible = "nordic,nrf-uarte";
status = "okay";
current-speed = <115200>;
pinctrl-0 = <&uart1_default>;
pinctrl-1 = <&uart1_sleep>;
pinctrl-names = "default", "sleep";
lpuart: nrf-sw-lpuart {
compatible = "nordic,nrf-sw-lpuart";
status = "okay";
req-pin = <6>;
rdy-pin = <12>;
};
};

&gpiote {
interrupts = <6 NRF_DEFAULT_IRQ_PRIORITY>;
};

A similar config applies to the NRF9160 side.
Packet size and message size are ok.

Regarding the solution I currently found, the change introduced is basically on the NRF52840 side. So, after sending a message I will wait 25 ms and force the RDY and REQ pins. By forcing I mean, call the rdy_pin_blink and req_pin_idle from the LPUART driver. By doing this the system behaves as expected - I receive the whole payload and the first message is sent. Maybe what Im seeing is a timing issue regarding the REQ and RDY lines. Do you have any idea what could cause this ?

Thank you!