NB-Iot UDP recieve - Release assistance behavior

[optical]

Hello, 

i'm experiencing a issue regarding receiving UDP responses from our COAP server. Our server implements a piggy back response scheme, however in some cases it is either slow or the connection is not perfect.

Problem situation:
Device issues a  coap request to the server:

[08:56:42.018,000] <dbg> dt_coap_client: Init send Id: 39660, T: 2786, Tries: 5, pending: 0x200105f0

The server replies with ACK but it processes the request a afterwards will send result as piggy back response.
The ACK is correctly recieved by the device. Afterwards the device waits for the piggy back reponse.

[08:56:42.606,000] <dbg> dt_socket_manager: Recieve polled

[08:56:42.606,000] <dbg> dt_coap_client: Data recieved

[08:56:42.607,000] <dbg> dt_coap_client: Recieved coap id: 39660, token_len: 0, type: 02

[08:56:42.607,000] <dbg> dt_coap_client: Pending ACK recieved Id: 39660 - Duration: 589ms

However the device on the NB-IOT network due to transmission inactivity turns off the DATA Plane after 20s.

[08:57:01.841,000] <inf> dt_modem: Notif: %CESQ: 90,4,31,4

[08:57:03.499,000] <inf> dt_modem: Notif: +CSCON: 0

The request then timeouts due to not receiving the piggy back data. Even thought the server replied.

[08:58:18.268,000] <dbg> dt_coap_client: Force timeout run

[08:58:18.268,000] <wrn> dt_coap_client: Force timeout releasing data. Packet not delivered

[08:58:18.268,000] <err> dt_app_wait_for_cload: Cloud client failed

What needs to be done for the modem to periodically initiate the data plane for retrieval of incoming packets ?
Is there some AT command which  will disable this behavior ?  

How is implemented any UDP server behavior on device, which is not transmitting anything to the network ? 

This behavior will cause any UDP server application to not stop listening for any incoming packets.



Full log including modem notifications. Note we are unable to collect traces from our device.

Fullscreen at.log Download

[06:56:38.409,000] <inf> dt_modem: Notif: %XSIM: 1
[08:56:39.717,000] <inf> dt_modem: Notif: %CESQ: 87,4,27,3
[08:56:39.717,000] <inf> dt_modem: Notif: %XSNRSQ: 43,4,214,0
[08:56:39.717,000] <inf> dt_modem: Notif: +CEREG: 2,"BC48","000A5C21",9
[08:56:39.723,000] <inf> main: Modem firmware version: nrf9160_1.3.1
[08:56:40.413,000] <inf> dt_modem: Notif: +CSCON: 1
[08:56:40.820,000] <inf> dt_modem: Notif: %XSNRSQ: 46,4,213,0
[08:56:41.342,000] <inf> dt_modem: Notif: +CGEV: ME PDN ACT 0
[08:56:41.343,000] <inf> dt_modem: Notif: +CEREG: 5,"BC48","000A5C21",9,,,"11100000","00101000"
[08:56:41.348,000] <inf> main: Resuming Socket Manager
[08:56:41.351,000] <dbg> dt_socket_manager: Send handler: 0
[08:56:41.351,000] <inf> dt_app_wait_for_cload: Transition
[08:56:41.351,000] <dbg> dt_socket_manager: Resolving address
[08:56:41.792,000] <inf> dt_modem: Notif: %XTIME: ,"22809060657380","01"
[08:56:42.017,000] <dbg> dt_socket_manager: IPv4 Address found ***********
[08:56:42.017,000] <dbg> dt_socket_manager: Connecting socket
[08:56:42.018,000] <inf> dt_socket_manager: Connected
[08:56:42.018,000] <inf> dt_app_wait_for_cload: Connected starting dt cloud client
[08:56:42.018,000] <dbg> dt_coap_client: Init send Id: 39660, T: 2786, Tries: 5, pending: 0x200105f0
[08:56:42.018,000] <dbg> dt_socket_manager: Send handler: 1
[08:56:42.018,000] <dbg> dt_socket_manager: Msg fifo: 1
[08:56:42.018,000] <dbg> dt_socket_manager: Sending data: 100
[08:56:42.463,000] <inf> dt_modem: Notif: %XSNRSQ: 49,4,213,0
[08:56:42.606,000] <dbg> dt_socket_manager: Recieve polled
[08:56:42.606,000] <dbg> dt_coap_client: Data recieved
[08:56:42.607,000] <dbg> dt_coap_client: Recieved coap id: 39660, token_len: 0, type: 02
[08:56:42.607,000] <dbg> dt_coap_client: Pending ACK recieved Id: 39660 - Duration: 589ms
[08:56:42.841,000] <inf> dt_modem: Notif: %CESQ: 82,4,31,4
[08:56:44.804,000] <dbg> dt_coap_client: Id: 39660, T0: 6906, T: 2786, Tries: 5, Ack: 1, pending: 0x200105f0
[08:56:44.804,000] <wrn> dt_coap_client: Retransmittion waiting for data
[08:56:44.804,000] <dbg> dt_coap_client: Retransmittion schedule: 5572ms
[08:56:45.641,000] <inf> dt_modem: Notif: %CESQ: 86,4,26,3
[08:56:46.041,000] <inf> dt_modem: Notif: %XSNRSQ: 46,4,213,0
[08:56:46.464,000] <inf> dt_modem: Notif: %CESQ: 82,4,31,4
[08:56:50.377,000] <dbg> dt_coap_client: Id: 39660, T0: 9692, T: 5572, Tries: 4, Ack: 1, pending: 0x200105f0
[08:56:50.377,000] <wrn> dt_coap_client: Retransmittion waiting for data
[08:56:50.377,000] <dbg> dt_coap_client: Retransmittion schedule: 11143ms
[08:56:53.464,000] <inf> dt_modem: Notif: %CESQ: 87,4,31,4
[08:56:55.841,000] <inf> dt_modem: Notif: %CESQ: 88,4,26,3
[08:56:56.841,000] <inf> dt_modem: Notif: %CESQ: 87,4,31,4
[08:57:01.041,000] <inf> dt_modem: Notif: %CESQ: 90,4,26,3
[08:57:01.520,000] <dbg> dt_coap_client: Id: 39660, T0: 15264, T: 11144, Tries: 3, Ack: 1, pending: 0x200105f0
[08:57:01.520,000] <wrn> dt_coap_client: Retransmittion waiting for data
[08:57:01.520,000] <dbg> dt_coap_client: Retransmittion schedule: 22288ms
[08:57:01.841,000] <inf> dt_modem: Notif: %CESQ: 90,4,31,4
[08:57:03.499,000] <inf> dt_modem: Notif: +CSCON: 0
[08:57:03.858,000] <inf> dt_modem: Notif: %CESQ: 90,4,25,3
[08:57:03.858,000] <inf> dt_modem: Notif: %XSNRSQ: 49,4,217,0
[08:57:04.682,000] <inf> dt_modem: Notif: %CESQ: 88,4,33,4
[08:57:07.242,000] <inf> dt_modem: Notif: %CESQ: 83,4,32,4
[08:57:07.487,000] <dbg> dt_bt_adv: Advertising Connectable stopping
[08:57:07.492,000] <inf> dt_bt_adv: Advertising Connectable stopped
[08:57:07.996,000] <inf> dt_bt_adv: Advertising connactable start
[08:57:07.999,000] <inf> bt_hci_core: Actual Tx Power: 8
[08:57:08.006,000] <inf> dt_bt_adv: Advertising connactable started
[08:57:09.803,000] <inf> dt_modem: Notif: %CESQ: 73,3,33,4
[08:57:14.923,000] <inf> dt_modem: Notif: %XSNRSQ: 44,4,202,0
[08:57:17.491,000] <inf> dt_modem: Notif: %CESQ: 67,3,33,4
[08:57:17.491,000] <inf> dt_modem: Notif: %XSNRSQ: 41,4,194,0
[08:57:20.058,000] <inf> dt_modem: Notif: %CESQ: 64,3,23,3
[08:57:22.614,000] <inf> dt_modem: Notif: %CESQ: 58,2,14,2
[08:57:22.614,000] <inf> dt_modem: Notif: %XSNRSQ: 34,3,185,0
[08:57:23.808,000] <dbg> dt_coap_client: Id: 39660, T0: 26408, T: 22288, Tries: 2, Ack: 1, pending: 0x200105f0
[08:57:23.808,000] <wrn> dt_coap_client: Retransmittion waiting for data
[08:57:23.808,000] <dbg> dt_coap_client: Retransmittion schedule: 44576ms
[08:57:25.163,000] <inf> dt_modem: Notif: %CESQ: 60,3,20,2
[08:57:27.723,000] <inf> dt_modem: Notif: %CESQ: 63,3,31,4
[08:57:27.723,000] <inf> dt_modem: Notif: %XSNRSQ: 38,3,190,0
[08:57:30.294,000] <inf> dt_modem: Notif: %CESQ: 62,3,26,3
[08:57:32.843,000] <inf> dt_modem: Notif: %CESQ: 79,3,34,4
[08:57:32.844,000] <inf> dt_modem: Notif: %XSNRSQ: 41,4,206,0
[08:57:37.964,000] <inf> dt_modem: Notif: %CESQ: 88,4,34,4
[08:57:38.006,000] <dbg> dt_bt_adv: Advertising Connectable stopping
[08:57:38.011,000] <inf> dt_bt_adv: Advertising Connectable stopped
[08:57:38.248,000] <dbg> dt_memfault_fs: No more data avaiable to read
[08:57:38.248,000] <inf> dt_memfault_fs: Memfault packetizer finished successfuly
[08:57:38.515,000] <inf> dt_bt_adv: Advertising connactable start
[08:57:38.518,000] <inf> bt_hci_core: Actual Tx Power: 8
[08:57:38.525,000] <inf> dt_bt_adv: Advertising connactable started
[08:57:43.084,000] <inf> dt_modem: Notif: %CESQ: 82,4,34,4
[08:57:45.644,000] <inf> dt_modem: Notif: %CESQ: 73,3,30,4
[08:57:45.644,000] <inf> dt_modem: Notif: %XSNRSQ: 46,4,200,0
[08:57:48.204,000] <inf> dt_modem: Notif: %CESQ: 83,4,34,4
[08:57:53.324,000] <inf> dt_modem: Notif: %CESQ: 74,3,34,4
[08:58:06.124,000] <inf> dt_modem: Notif: %CESQ: 79,3,33,4
[08:58:08.384,000] <dbg> dt_coap_client: Id: 39660, T0: 48696, T: 44576, Tries: 1, Ack: 1, pending: 0x200105f0
[08:58:08.384,000] <wrn> dt_coap_client: Retransmittion waiting for data
[08:58:08.384,000] <dbg> dt_coap_client: Retransmittion schedule: 89152ms
[08:58:08.525,000] <dbg> dt_bt_adv: Advertising Connectable stopping
[08:58:08.529,000] <inf> dt_bt_adv: Advertising Connectable stopped
[08:58:08.684,000] <inf> dt_modem: Notif: %XSNRSQ: 49,4,206,0
[08:58:09.034,000] <inf> dt_bt_adv: Advertising connactable start
[08:58:09.037,000] <inf> bt_hci_core: Actual Tx Power: 8
[08:58:09.044,000] <inf> dt_bt_adv: Advertising connactable started
[08:58:11.244,000] <inf> dt_modem: Notif: %XSNRSQ: 46,4,209,0
[08:58:16.365,000] <inf> dt_modem: Notif: %CESQ: 72,3,32,4
[08:58:18.268,000] <dbg> dt_coap_client: Force timeout run
[08:58:18.268,000] <wrn> dt_coap_client: Force timeout releasing data. Packet not delivered
[08:58:18.268,000] <err> dt_app_wait_for_cload: Cloud client failed

[Albrecht Markus Schellenberger]

Hello Tomas, 

What needs to be done for the modem to periodically initiate the data plane for retrieval of incoming packets ?
Is there some AT command which  will disable this behavior ?  

The modem will automatically wake up in RRC Idle for incoming data. This is expected behaviour, hence there are no AT commands for it. What you potentially could do to go around the issue you are facing is to send a COAP notification on an observation every amount of time.

How is implemented any UDP server behavior on device, which is not transmitting anything to the network ? 

The nRF9160 modem meets 3GPP standards and should act accordingly. At this point, I do not suspect it to be a modem problem rather than that Network Address Translation (NAT) times out on the network side. But I would need a modem trace for deeper analysis. 

Cheers, 

Markus 

[optical]

What is by your experience the timeout of the NAT of the carrier networks ?

[Albrecht Markus Schellenberger]

optical said:

What is by your experience the timeout of the NAT of the carrier networks ?

In many networks, the timeout is around 50-60s. But we have seen NATs timing out after <20s as well. You should talk to your carrier to get an exact number.  

Cheers, 

Markus 

[optical]

Thank you, 
we will contact our carrier and perform further testing focusing on the NAT timeout.