nRF9160 wakeup from RRC idle on incoming traffic, but data is lost

[Stephan Walter]

We are using the nRF9160 with firmware 1.3.6 to establish a DTLS connection to a server, using the Zephyr TLS stack.

The following problem occurs quite frequently: After some idle time, the modem will enter RRC idle and signal this with +CSCON: 0. If the server now sends data, the modem will wake up from RRC idle, but we don't actually receive the packet.

Such a case is documented here and in the attached files.

Packet trace on the server (server has local IP 172.18.16.75): /cfs-file/__key/communityserver-discussions-components-files/4/0284.trace0_2D00_server.pcapng

Packet #30 is an uplink packet from the nRF91 to the server. The server then tries to send data to the client (packets #31-#34). The modem wakes up for each of them, but no data is received:

10:11:11,633	+CSCON: 0
10:11:16,796	+CSCON: 1
10:11:20,263	+CSCON: 0
10:11:22,236	+CSCON: 1
10:11:25,596	+CSCON: 0
10:11:27,996	+CSCON: 1
10:11:33,560	+CSCON: 0
10:11:36,956	+CSCON: 1

At 10:11:38, packet #35 is finally received by the client and a response is sent to the server. This indicates that the connection remained active in the software stack and also in any middleware (NAT etc.).

Modem trace: /cfs-file/__key/communityserver-discussions-components-files/4/1754.trace0.bin The modem trace starts with packet #30 at 10:11:08.

We are aware that being layered on top of UDP, DTLS packets are not guaranteed to be delivered. But the packet loss is so frequent and severe that we suspect some problem in the interaction between modem and LTE-M network.

[Achim Kraus]

Not that sure, but if an (unintended/unaware) ip-addr/port change happens, and the modem uses 

connect(fd, &dest, sizeof(dest);

then that may drop/filter UDP messages.

[Simon D-M]

Hi Stephan,

Sorry, I'm not coming back with an answer yet, but instead I have more questions...

What version of NCS is your firmware based on?

Can you please do another attempt with MBedTLS logging enabled?

It should more or less look something like this (depending on your NCS version) :

CONFIG_MBEDTLS_DEBUG=y
CONFIG_MBEDTLS_SSL_DEBUG_ALL=y
CONFIG_MBEDTLS_LOG_LEVEL_DBG=y
CONFIG_MBEDTLS_DEBUG_C=y
CONFIG_MBEDTLS_DEBUG_LEVEL=4

MBedTLS logs are quite big, you may need to increase the log buffer size:

CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_BUFFER_SIZE=2048

If you can enable logging from your custom protocol it would be nice too (at least some indications about if data is going out from the app level).

And finally, if you are able to enable the full modem trace it would be also better. Your current modem log is quite limited. You can enable it using this KConfig:

CONFIG_NRF_MODEM_LIB_TRACE_LEVEL_FULL=y

Best regards,

Simon

[Stephan Walter]

Hi Simon,

I was unable to reproduce the issue with mbedTLS logging enabled. There seemed to be too much of a slowdown, so that the DTLS handshake would fail.

I did however enable full modem tracing and was able to record cases in which 3 consecutive packets were lost. While UDP has no reliability guarantee, the ARQ mechanism in LTE should help in my opinion. As seen before, the modem would wake up (+CSCON 1/0) exactly the same number of times as the number of expected packets, but no data seems to be incoming.

In packet trace recorded on the server (trace1-server.pcapng), packets 183, 184 and 185 starting from 14:41:03 are lost.

trace1.zip

Unfortunately when opening the trace in Wireshark from the Cellular Monitor tool, only 11 trace packets show up despite the binary file containing over 400 trace events. I don't know what's going on there.

Best regards,
--Stephan Walter

[Simonr]

Hi Stephan

Simon is away this week, so I'm looking after this ticket in his place. We will need some time to review the modem traces you provided and will get back to you when we have some ideas to what could cause this. Thank you for your patience.

Best regards,

Simon

[Simon D-M]

Hi Stephan,

From the trace we can see that your device indeed connect to the network, entering RCC connected mode, and that the data radio bearer is set up, but the network doesn't deliver any IP data, thus releasing the RRC connection a few seconds later.

This matches the +CSCON notification you reported.

I would recommend you checking this further with the network provider directly as we can't really see more than this from the device perspective...

Best regards,

Simon