Long PSM delay problem in NB-IoT mode

[RoryL]

While testing CoAP with NB-IoT I normally get PSM (sleep) delay = 20s before PSM mode is set (0.5mA with UART enabled), but after awhile PSM delay increases to ~4.5min (at 34mA) after each transmission has finished. I enabled a modem trace and the Wireshark capture shows me that when PSM delay = 20s (from RRC Inactivity timer=20s + Active time=0) then "RRCConnectionRelease-NB" message is logged just before +CSCON=0, but when the delay is ~4.5min then "RRCConnectionRelease-NB" message is missing and +CSCON=0 takes 4.5min instead of 20s.

I'm using the sample nRF Cloud multi-service app with SDK 2.6.1, Modem v1.3.6, connected to nRF Cloud (using a Spark NZ NB-IoT SIM). After this problem has happened then it sometimes recovers after next data transmission, provided I'm using a slow enough data rate (e.g. 10min). If I test this with a 2min data rate then doesn't seem to recover. In this failed mode the first Tx request always fails (probably the modem thinks it's still connected), and the re-transmit only works after it's logged a +CSCON=0, +CSCON=1 cycle (a forced reconnection recovery by the modem?).  I haven't seen this problem at all with a LTE-M SIM (where PSM delay = 10, from the network RRC inactivity timer).

As a work around I tried enable RAI (e.g. AT%XRAI=3, with CONFIG_COAP_SEND_CONFIRMABLE=y), and found it nearly always helped set PSM immediately, but not always (e.g. still got sometimes got RRC idle delay = 4.5min delay).  I've disabled location reporting in my build, but the same problem happened with the default config (overlay_coap.conf), and also when I tested using the low power build (overlay_min_coap.conf).

Some questions:

1. Cellular coverage is normally reliable for me - so could the missing "RRCConnectionRelease-NB" be caused by: a network fault (failed to send it), or a comms error (not received), or an nRF9160 (modem or app) problem?  Are there any suggestions for how to avoid or work-around this problem?
   
   
2. I'm curious where the 4.5min delay comes from - when +CSCON: 0 is set after this delay (with missing "RRCConnectionRelease-NB") - does the modem implement this timeout? (e.g. to ensure PSM gets set, and avoid wasting ~34mA forever)
   
   
3. When the problem has happened - does the modem or the SDK do the recovery sequence (+CSCON:0, +CSCON:1 cycle), seen in Terminal log (2) below - for the 2min data rate, to re-establish comms?

Logs with the "RRCConnectionRelease-NB" missing problem:

1) Terminal log - 10min data rate: 4.5min RCC idle delays after 00:50:25 and 01:10:25

*** Booting nRF Connect SDK v3.5.99-ncs1-1 ***
[00:00:00.257,904] <inf> main: nRF Cloud multi-service sample has started, version: 0.8.3, protocol: CoAP
[00:00:00.258,026] <inf> cloud_connection: Enabling connectivity...
[00:00:00.489,746] <inf> nrf_modem_lib_trace: Trace thread ready
[00:00:00.497,375] <inf> nrf_modem_lib_trace: Trace level override: 2
[00:00:00.536,926] <inf> cloud_connection: Setting up nRF Cloud library...
[00:00:00.538,116] <inf> cloud_connection: Waiting for network ready...
+CEREG: 2,"951B","00070E79",7
+CSCON: 1
+CNEC_ESM: 111,0
+CEREG: 2,"951B","00070E79",7,0,15
+CSCON: 0
+CEREG: 2
+CEREG: 2,"9903","00070EDD",9
+CSCON: 1
%XTIME: ,"42902032929484",
+CGEV: ME PDN ACT 0,0
+CNEC_ESM: 50,0
+CEREG: 1,"9903","00070EDD",9,,,"00000000","00000110"
[00:00:12.989,868] <inf> cloud_connection: Network connectivity gained!
[00:00:13.990,051] <inf> cloud_connection: Network is ready
[00:00:13.990,081] <inf> cloud_connection: Connecting to nRF Cloud
[00:00:13.990,722] <inf> cloud_connection: Device ID: nrf-351901936740707
[00:00:14.818,115] <inf> dtls: IMEI:                  351901936740707
[00:00:14.818,145] <inf> dtls: Modem FW version:      mfw_nrf9160_1.3.6
[00:00:18.429,595] <inf> nrf_cloud_coap_transport: Request authorization with JWT
[00:00:19.526,885] <inf> nrf_cloud_coap_transport: Authorization result_code: 2.01
[00:00:19.526,977] <inf> nrf_cloud_coap_transport: Authorized
[00:00:19.527,221] <inf> nrf_cloud_coap_transport: DTLS CID is active
[00:00:20.186,706] <inf> nrf_cloud_codec_internal: Encode modem_info_network
[00:00:20.187,194] <inf> nrf_cloud_codec_internal: Network mode = LTE-M, LTE-M=1, NB-IoT=1
[00:00:20.187,316] <inf> nrf_cloud_codec_internal: Encode modem_info_device
[00:00:21.343,078] <inf> cloud_connection: Connected to nRF Cloud
[00:00:21.343,170] <inf> shadow_support_coap: Checking for shadow delta...
[00:00:21.345,001] <inf> nrf_cloud_fota_poll: Checking for FOTA job...
[00:00:22.267,974] <inf> nrf_cloud_coap: No pending FOTA job
[00:00:22.268,005] <inf> nrf_cloud_fota_poll: No pending FOTA job
[00:00:22.942,047] <inf> application: Waiting for modem to determine current date and time
[00:00:22.942,077] <inf> application: Current date and time determined
[00:00:24.173,858] <inf> application: Temperature is 23 degrees C
[00:00:24.741,149] <inf> message_queue: Coap send complete
[00:00:33.533,172] <inf> shadow_support_coap: Checking for shadow delta...
[00:00:34.237,487] <inf> shadow_support_coap: Checking again in 1800 seconds
+CSCON: 0		//PSM delay = 20s

[00:10:24.173,889] <inf> application: Temperature is 22 degrees C
+CSCON: 1
[00:10:25.831,542] <inf> message_queue: Coap send complete
+CSCON: 0       //PSM delay = 20s

[00:20:24.173,919] <inf> application: Temperature is 22 degrees C
+CEREG: 1,"9903","09BCBCE7",9,,,"00000000","00000110"
[00:20:27.176,849] <err> net_coap: Timeout in poll, retrying send
+CSCON: 1
[00:20:27.842,254] <inf> message_queue: Coap send complete
+CSCON: 0		//PSM delay = 20s

[00:30:22.268,127] <inf> nrf_cloud_fota_poll: Checking for FOTA job...
[00:30:22.270,233] <err> net_coap: Unexpected ACK
[00:30:22.270,233] <err> net_coap: Error handling response
+CEREG: 1,"9903","00070EDD",9,,,"00000000","00000110"
+CSCON: 1
[00:30:23.895,111] <inf> nrf_cloud_coap: No pending FOTA job
[00:30:23.895,111] <inf> nrf_cloud_fota_poll: No pending FOTA job
[00:30:24.174,011] <inf> application: Temperature is 23 degrees C
[00:30:25.741,210] <inf> message_queue: Coap send complete
[00:30:34.237,579] <inf> shadow_support_coap: Checking for shadow delta...
[00:30:35.240,539] <inf> shadow_support_coap: Checking again in 1800 seconds
+CSCON: 0		//PSM delay = 20s

[00:40:24.174,072] <inf> application: Temperature is 22 degrees C
+CSCON: 1
[00:40:26.224,670] <inf> message_queue: Coap send complete
+CSCON: 0		//PSM delay = 20s

[00:50:24.174,133] <inf> application: Temperature is 22 degrees C
+CEREG: 1,"9903","09BCBCE7",9,,,"00000000","00000110"
+CSCON: 1
[00:50:25.865,173] <inf> message_queue: Coap send complete
> AT+CPINR="SIM PIN"
+CPINR: "SIM PIN",3
OK
> AT+CPINR="SIM PIN2"
+CPINR: "SIM PIN2",3
OK
> AT+CPINR="SIM PUK"
+CPINR: "SIM PUK",10
OK
> AT+CPINR="SIM PUK2"
+CPINR: "SIM PUK2",10
OK
> AT+CSCON?
+CSCON: 1,1
OK
+CSCON: 0		//PSM delay = 4.5min - Problem

[01:00:23.895,233] <inf> nrf_cloud_fota_poll: Checking for FOTA job...
[01:00:24.174,194] <inf> application: Temperature is 23 degrees C
+CEREG: 1,"9903","00070EDD",9,,,"00000000","00000110"
+CSCON: 1
[01:00:25.744,140] <inf> nrf_cloud_coap: No pending FOTA job
[01:00:25.744,140] <inf> nrf_cloud_fota_poll: No pending FOTA job
[01:00:26.273,193] <inf> message_queue: Coap send complete
[01:00:35.240,692] <inf> shadow_support_coap: Checking for shadow delta...
[01:00:36.287,536] <inf> shadow_support_coap: Checking again in 1800 seconds
+CSCON: 0	//PSM delay = 20s
> 
[01:10:24.174,255] <inf> application: Temperature is 22 degrees C
+CEREG: 1,"9903","09BCBCE7",9,,,"00000000","00000110"
+CSCON: 1
[01:10:25.826,599] <inf> message_queue: Coap send complete
+CSCON: 0	//PSM delay = 4.5min - Problem

Wireshark capture of same events - 10min data rate: missing "RRCConnectionRelease-NB" before 4.5min RRC idle delays at line 308 (3291s), and line 361 (4491s):

8623.cms_Spark_20240903_2_nbiot_10min.pcapng

2) Excerpt of terminal log - 2min data rate. First RRC idle failed after 00:08:29, no PSM idle before the next transmission + forced recovery before each resend (00:10:36):

...
+CSCON: 0		//PSM delay = 20s

[00:08:27.609,222] <inf> application: Temperature is 22 degrees C
+CEREG: 1,"9903","09BCBCE7",9,,,"00000000","00000110"
+CSCON: 1
[00:08:29.732,788] <inf> message_queue: Coap send complete
//Failed - no PSM

	//Wireshark 627..635s
[00:10:27.609,283] <inf> application: Temperature is 24 degrees C
[00:10:30.612,182] <err> net_coap: Timeout in poll, retrying send
+CSCON: 0		//RRC reconnect forced by modem for Tx retry?
+CSCON: 1
[00:10:36.170,806] <inf> message_queue: Coap send complete
//Failed - no PSM

Wireshark capture of same events - 2min data rate: first missing "RRCConnectionRelease-NB" after line 303 (509s)

6052.cms_Spark_20240902_1_nbiot_2min.pcapng

[RoryL]

Just to follow up on this fault report - after further investigation I found that the long PSM sleep delay (~300s) only happened when connected to a certain cell ID. It didn't happen when connected to other NB-IoT cell IDs from the same location. After sharing the problem with our network provider they agreed that one of their (3) suppliers had a fault in their equipment. This is why our devices sometimes did not receive "RRCConnectionRelease-NB" from the network. In the last month they have now fixed this and the problem isn't happening any more (PSM takes about 1s with CP-RAI instead of ~300s).

If possible I would still like to hear confirmation from Nordic Semi about the 300s PSM delay from the modem (v1.3.6)  when this fail condition existed. This is a very long default idle timeout - that is very hard on a battery. I suggest to consider if a shorter default timeout could be used or enabled in the future?

[Hakon]

RoryL said:

I suggest to consider if a shorter default timeout could be used or enabled in the future?

Hello,

thanks for the suggestion. Can you please make a separate ticket for this to have it formally submitted as a feature request?