SLM modem sometimes doesn't process AT#XSEND

[Konstantin Klitenik]

I'm seeing an issue where nrf91 SLM, running as an AT modem over UART, sometimes chokes on XSEND command and doesn't respond until the host (nrf54) sends another AT command, and then the commands get concattenated and error.

Here's the log on the HOST (nrf54):

[00:00:13.189,568] <dbg> modem_cmd_handler: modem_cmd_send_ext: SENT DATA
                                41 54 23 58 53 45 4e 44 |AT#XSEND
[00:00:17.735,136] <wrn> comms: Not connected to AWS, waiting 5 seconds
[00:00:18.192,960] <err> modem_nrf91: AT#XSEND failed or timed out (err -116)
[00:00:18.192,992] <err> net_sock_tls: TLS handshake error: -0x4e
[00:00:18.195,872] <dbg> modem_cmd_handler: modem_cmd_send_ext: SENT DATA
                                41 54 23 58 53 4f 43 4b 45 54 3d 30 |AT#XSOCK ET=0
[00:00:18.201,280] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: RECV
                                45 52 52 4f 52 |ERROR
[00:00:18.201,280] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [ERROR] (len:5)

And here's the log on nrf91 SLM: 

[00:00:12.397,003] <dbg> slm_sock: update_work_fn: Update poll events
[00:00:12.397,155] <dbg> slm_sock: update_apoll_fds: fd: 1, events: 0x0001, revents: 0x0000
[00:00:12.397,186] <dbg> slm_sock: update_apoll_fds: fd: 2, events: 0x0001, revents: 0x0000
[00:00:12.397,216] <dbg> nrf9x_sockets: nrf9x_poll_prepare: nrf9x_poll_prepare: modem socket 0 (app FD 1), events: 0x0001
[00:00:12.397,247] <dbg> nrf9x_sockets: nrf9x_poll_prepare: nrf9x_poll_prepare: modem socket 1 (app FD 2), events: 0x0001
[00:00:12.713,714] <inf> slm: I'm alive 3
[00:00:15.713,806] <inf> slm: I'm alive 4
[00:00:17.527,038] <dbg> slm_at_host: cmd_send: RX
                                41 54 23 58 53 45 4e 44 0a 41 54 23 58 53 4f 43 |AT#XSEND .AT#XSOC
                                4b 45 54 3d 30 |KET=0
[00:00:17.527,099] <err> slm_at_host: AT command syntax invalid: AT#XSEND
AT#XSOCKET=0
[00:00:17.527,191] <dbg> slm_at_host: slm_at_send_indicate: TX
                                0d 0a 45 52 52 4f 52 0d 0a |..ERROR. .

nRF SDK: 3.1.0

SLM app unmodified

Modem FW:  mfw_nrf91x1_2.0.2

SLM prj.conf and device tree are attached.

slm_nrf9151_ns.dts3058.prj.confslm_nrf9151_ns_defconfig.conf

[Øyvind]

Hello, 

From the added HOST (nrf54) logs we can see the following:

[00:00:17.735,136] <wrn> comms: Not connected to AWS, waiting 5 seconds
[00:00:18.192,960] <err> modem_nrf91: AT#XSEND failed or timed out (err -116)
[00:00:18.192,992] <err> net_sock_tls: TLS handshake error: -0x4e

Are you able to share modem traces from the nRF91, and full logs from both HOST and NRF91?

Thanks

Kind regards,
Øyvind

[Konstantin Klitenik]

I don't have traces but I did more digging and it seems to be related to the timing between sending AT#XSEND and the EOL (\r\n). Zephyr's `modem_cmd_handler.c` handles this as 2 writes

iface->write(iface, buf, strlen(buf));

iface->write(iface, data->eol, data->eol_len);

So, depending on what else is happening in the application, there could be a meaningful delay between the two. I noticed that when the delay is right around 2ms, the last byte of the EOL (\n) is missed.If the delay is shorter or longer (>3ms), then everything works fine. 2ms just happens to be the UART_RX_TIMEOUT_US on the SLM.

In this case, note that the logic analyzer shows \r\n being sent. But only \r is received. I'll post the AI assessment of the UART issue below. 

AI assessment:

The Race Condition

When the delay is just over 2ms:

1. First part of command arrives (e.g., AT#XSEND=...)

2. Timer starts counting down from 2000us

3. At ~2000us: timeout fires → rx_timeout() executes

4. At ~2000us: RXDRDY is checked → likely false (no new byte yet)

5. At ~2001us: \n byte arrives on UART line

6. At ~2001us: STOPRX is triggered (from step 4)

7. Result: \n may be missed because:

• It arrives after the timeout check

• STOPRX may interrupt an in-flight byte

• The ENDRX event may fire before \n is fully received

Why Shorter/Longer Delays Work

• Shorter delay (< 2ms): All bytes arrive within the timeout window → batched together → \n included

• Longer delay (>> 2ms): First part times out and is sent → \r\n arrives later as a separate transmission → gets its own event

[Øyvind]

Hello, 

do you have the following settings in prj.conf? If not could you please try adding and test your application?

CONFIG_UART_2_NRF_HW_ASYNC_TIMER=2
CONFIG_UART_2_NRF_HW_ASYNC=y

Kind regards,
Øyvind

[Konstantin Klitenik]

That seems to have fixed it. I'll keep monitoring to see if the issue comes back.

Please make sure this config makes it into the new SLM repo: https://github.com/nrfconnect/ncs-serial-modem

Thanks.