Network changes PSM timing without notice ?

[Vincent44]

Hello,

I have a project based on nRF9160 and nRFCloud (CoAP), and uses a SIM from 1NCE. This SIM allows to connect to 3 different MNO at my location in France (Orange, Bouygues telecom, SFR).
For the most part, it's working as expected. However, I noticed a strange behavior when the device is in "standby mode".
In this mode, the device only needs to send a message every 24h. For this purpose, the device requests a TAU timer of 25h to the network, which gets accepted.
On some devices, I have no problem and it works as expected.
On others, the device gets stuck, causing a Watchdog reset, as follow :

#1 - Sleep for 24h
#2 - Wakeup and try to send a message
#3 - Gets stuck in firmware -> Message not send + Watchdog reset
#4 - Reboot FW, re-connect to the network, re-connect to nRFCloud
#5 - Send the message successfully
#6 - Negotiate PSM for 24h sleep
#7 - Back to step #1

Sample log from my device :

--------------------------------
------------ REBOOT ------------
--------------------------------

Reset cause (16): 	RESET_WATCHDOG

* * Perfom all HW inits ** 

- - Inits completed - -

Battery voltage: 3592mv

[Uptime 8 sec]
Build Status frame (acc: -1, 2, -96)

[Uptime 8 sec]
Measure probe ... Ok
Cellular enable ... Done
[MODEM] Searching network
[MODEM] Mode LTE-M
[MODEM] RRC Connected
[MODEM] Search done
[MODEM] Network connected
Connected in 4 sec
Connect to nRFCloud ... Done

Send: {"F":{"1733335826":["170010"],"1733335830":["19C12241330B","100011FF02A00000"],"1733335833":["1940F77409A20000"]}}
Send done
Send RSRP to nRFCloud
Send: {"messageType":"DATA","data":"-96","appId":"RSRP","ts": 1733335843120}
Send done

04/12/2024 18:10:47
First read after boot: full read ... Done

04/12/2024 18:10:47
Delta read nRF shadow ... No new data

04/12/2024 18:10:48
FOTA: Sending device info ... Ok

04/12/2024 18:10:57
Checking for FOTA ... No pending FOTA

04/12/2024 18:10:58
Prepare to sleep ...
PSM: TAU=1800, AT=60 don't match desired: TAU>86700, 0<AT<32
PSM request: TAU=90000, AT=0
(TAU 86700 rounded to 90000)
PSM is: TAU=90000, AT=0
Sleep
[MODEM] RCC Idle

05/12/2024 18:11:02
Build Status frame (acc: -1, 3, -96)

05/12/2024 18:11:02
Measure probe ... Ok	Perm. 4.339	ECb 0.0mS/m	14.0°C
Modem already ready

Send: {"F":{"1733422262":["100011FF03A00000"],"1733422265":["1940F86C21E60000"]}}
[MODEM] Search done
[MODEM] RRC Connected



--------------------------------
------------ REBOOT ------------
--------------------------------

Reset cause (16): 	RESET_WATCHDOG

* * Perfom all HW inits ** 

- - Inits completed - -

Battery voltage: 3602mv

[Uptime 8 sec]
Build Status frame (acc: -1, 3, -97)

[Uptime 8 sec]
Measure probe ... Ok
Cellular enable ... Done
[MODEM] Searching network
[MODEM] Mode LTE-M
[MODEM] RRC Connected
[MODEM] Search done
[MODEM] Network connected
Connected in 4 sec
Connect to nRFCloud ... Done

Send: {"F":{"1733422332":["170010"],"1733422336":["19C12241330B","100011FF039F0000"],"1733422339":["1940F86C226E0000"]}}
Send done
Send RSRP to nRFCloud
Send: {"messageType":"DATA","data":"-103","appId":"RSRP","ts": 1733422347356}
Send done

05/12/2024 18:12:28
First read after boot: full read ... Done

05/12/2024 18:12:28
Delta read nRF shadow ... No new data

05/12/2024 18:12:30
FOTA: Sending device info ... Ok

05/12/2024 18:12:37
Checking for FOTA ... No pending FOTA

05/12/2024 18:12:38
Prepare to sleep ...
PSM: TAU=1800, AT=60 don't match desired: TAU>86700, 0<AT<32
PSM request: TAU=90000, AT=0
(TAU 86700 rounded to 90000)
PSM is: TAU=90000, AT=0
Sleep
[MODEM] RCC Idle

06/12/2024 18:12:42
Build Status frame (acc: -3, 0, -96)

06/12/2024 18:12:42
Measure probe ... Ok
Modem already ready

Send: {"F":{"1733508762":["100011FD00A00000"],"1733508765":["1940F8000A240000"]}}
[MODEM] Search done
[MODEM] RRC Connected


--------------------------------
------------ REBOOT ------------
--------------------------------

Reset cause (16): 	RESET_WATCHDOG

* * Perfom all HW inits ** 

- - Inits completed - -

Battery voltage: 3600mv

[Uptime 8 sec]
Build Status frame (acc: -1, 2, -97)

[Uptime 8 sec]
Measure probe ... Ok
Cellular enable ... Done
[MODEM] Searching network
[MODEM] Mode LTE-M
[MODEM] RRC Connected
[MODEM] Search done
[MODEM] Network connected
Connected in 4 sec
Connect to nRFCloud ... Done

Send: {"F":{"1733508832":["170010"],"1733508836":["19C12241330B","100011FF029F0000"],"1733508839":["1940F7FC0A320000"]}}
Send done
Send RSRP to nRFCloud
Send: {"messageType":"DATA","data":"-98","appId":"RSRP","ts": 1733508847945}
Send done

06/12/2024 18:14:08
First read after boot: full read ... Done

06/12/2024 18:14:08
Delta read nRF shadow ... No new data

06/12/2024 18:14:11
FOTA: Sending device info ... Ok

06/12/2024 18:14:19
Checking for FOTA ... No pending FOTA

06/12/2024 18:14:20
Prepare to sleep ...
PSM: TAU=1800, AT=60 don't match desired: TAU>86700, 0<AT<32
PSM request: TAU=90000, AT=0
(TAU 86700 rounded to 90000)
PSM is: TAU=90000, AT=0
Sleep
[MODEM] RCC Idle

07/12/2024 18:14:23
Build Status frame (acc: -2, 0, -97)

07/12/2024 18:14:23
Measure probe ... Ok
Modem already ready

Send: {"F":{"1733595263":["100011FE009F0000"],"1733595267":["1940F77009420000"]}}
[MODEM] Search done
[MODEM] RRC Connected


--------------------------------
------------ REBOOT ------------
--------------------------------

...

The only difference I was able to spot between a working and non-working device is the network : it looks like the devices with the unexpected reboots always connect to the same MNO: SFR.
Here is what I can see on the SIM events, from the SIM provider:

"events": [
{
  "timestamp": "2024-12-05 06:10:12.677Z",
  "event_type": "Delete PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-05 18:11:10.332Z",
  "event_type": "Create PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-05 18:11:10.723Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-05 18:12:22.368Z",
  "event_type": "Delete PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-05 18:12:22.496Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-05 18:12:22.605Z",
  "event_type": "Create PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-05 18:12:23.230Z",
  "event_type": "Update location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-05 18:12:23.768Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-06 06:11:57.733Z",
  "event_type": "Delete PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-06 18:12:49.362Z",
  "event_type": "Create PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-06 18:12:49.800Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-06 18:14:02.203Z",
  "event_type": "Delete PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-06 18:14:02.381Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-06 18:14:02.713Z",
  "event_type": "Create PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-06 18:14:03.323Z",
  "event_type": "Update location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-06 18:14:03.676Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-07 06:13:50.697Z",
  "event_type": "Delete PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-07 18:14:30.894Z",
  "event_type": "Create PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-07 18:14:31.287Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-07 18:15:43.896Z",
  "event_type": "Delete PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-07 18:15:44.032Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-07 18:15:44.187Z",
  "event_type": "Create PDP Context",
  "operator": "SFR Cegetel",
  "mcc": "208", "mnc": "10",
},
{
  "timestamp": "2024-12-07 18:15:44.836Z",
  "event_type": "Update location",
  "operator": "SFR Cegetel",
},
{
  "timestamp": "2024-12-07 18:15:45.225Z",
  "event_type": "Update GPRS location",
  "operator": "SFR Cegetel",
},
]

My hint it that the network accepts the PSM TAU at 25h (90000 sec), but cancels that after 12h.

Since the device is sleeping, its not notified (I don't have any modem event related). Therefore, when it tries to send a new message after waking up, the modem still considers that it is registered to the network and the nrf_coap_functions() fails/get stuck.

Note that on working devices, which seem to connect to other network, I don't have any "event_type": "Delete PDP Context" on the SIM events.

Is this behavior possible or is my issue comming from something else ? Is there a way to check that the connection is still active, without wasting power and data ? Some sort of ping ?

Thanks !

[Achim Kraus]

> On others, the device gets stuck, causing a Watchdog reset, as follow

What exactly means "gets stuck"?  "Message not send" is detected how?

In my experience, the message is passed to the modem with "send". If the modem sleeps, that may not report an error, but later, if the modem detects some issues actually sending, it reports an error via:

int error = -ENOTCONN;

socklen_t len = sizeof(error);

int result = getsockopt(fd, SOL_SOCKET, SO_ERROR, &error, &len);

or when the devices polls or tries to (re)send the message.

[dejans]

Hi Vincent44 

It could be that the network parameters received from the network differ than the values you expect. Which AT command did you use to check accepted PSM TAU value?

Best regards,
Dejan

[Vincent44]

I am using SDK 2.7.0 and the following function to request and check PSM timings :

lte_lc_psm_param_set

lte_lc_psm_get

Here is what the code looks like

// Set my PSM needs
desiredPSM.tau_min = 86700;	// 24 h and 5 minutes
desiredPSM.at_min = 0 ;
desiredPSM.at_max = 32 ;


lte_lc_psm_get(&currentPSM.tau, &currentPSM.at) ;

// Check if the current PSM timing match what we want
if( CELLULAR_MODEM_PSMSettingMatchMyNeeds(desiredPSM.at_min, desiredPSM.at_max, desiredPSM.tau_min) )
{
	// The PSM timing match was is desired.
	// -> Nothing to do. Modem will automatically go idle.
	DEBUG_PRINT("PSM TAU=%d, AT=%d match needs: TAU>%d, %d<AT<%d\r\n",currentPSM.tau, currentPSM.at, desiredPSM.tau_min, desiredPSM.at_min, desiredPSM.at_max) ;
}
else
{
	DEBUG_PRINT("PSM TAU=%d, AT=%d don't match needs: TAU>%d, %d<AT<%d\r\n",currentPSM.tau, currentPSM.at, desiredPSM.tau_min, desiredPSM.at_min, desiredPSM.at_max) ;

	// Request new PSM timing.
	// The function below encodes the provided timing with the timer format, and request PSM using : lte_lc_psm_param_set()
	// It also ensures that PSM is enabled with lte_lc_psm_req(true)
	// Because of the way the timing are coded, not all values are possible. Therefore, the value requested might have be rounded, which is why there are 4 params.
	CELLULAR_MODEM_RequestNewPSMParams(desiredPSM.tau_min, desiredPSM.at_min, &desiredPSM.tau_min, &desiredPSM.at_min) ;


	// Wait until the network confirm the PSM settings (max 10 sec)
	// = Wait for event LTE_LC_EVT_PSM_UPDATE
	int psmConfirmTimeCounter = 0 ;
	while( !CELLULAR_MODEM_hasPSMRequestCompleted() )
	{
		k_msleep(1000) ;
		psmConfirmTimeCounter++ ;
		
		// Max 10 sec
		if(psmConfirmTimeCounter >= 10){
			DEBUG_PRINT("* * * PSM request not confirmed * * *\r\n") ;	// Should not occur ?
			break ;
		}
	}


	// Check what was returned by the network : the network is the master, and can return some timing that we don't match what we want.
	// For example, not all service provider will allow a TAU of 6h or more.
	if(CELLULAR_MODEM_PSMSettingMatchMyNeeds(desiredPSM.at_min, desiredPSM.at_max, desiredPSM.tau_min))
	{
		lte_lc_psm_get(&currentPSM.tau, &currentPSM.at) ;
		DEBUG_PRINT("PSM is: TAU=%d, AT=%d\r\n",currentPSM.tau, currentPSM.at) ;
	}
	else
	{
		// Either the new timing still don't match, or the network did not responded
		DEBUG_PRINT("PSM still not match the needs. Switch off modem.\r\n");							
		CELLULAR_MODEM_Disconnect() ;		
	}						
}	


//------------------------------------

bool CELLULAR_MODEM_PSMSettingMatchMyNeeds(int min_desired_AT, int max_desired_AT, int min_desired_TAU)
{
	int tau, at ;

	lte_lc_psm_get(&tau, &at) ;					

	// The TAU should be at least what is desired.
	// The AT should be within the specified range
	if( (tau < min_desired_TAU) || (at < min_desired_AT) || (at > max_desired_AT) ){
		return false ;
	}
	return true ;
}

The initial PSM timining suaully don't match. So the  firmware request what is needed, and waits for the next LTE_LC_EVT_PSM_UPDATE event; After that, it checks again the timing.

I already have tens or hundreds devices running with this code, so I doubt that the issue is there, but who knows. :)

[dejans]

Hi,

Which PSM configuration do you get on each of the networks using lte_lc_psm_get()?
Have you tried to read modem parameters using %XMONITOR command?

Best regards,
Dejan

[Vincent44]

I haven't tried, but the result will be same.

In SDK 2.7.0, function lte_lc_psm_get() is a high level function that calls %XMONITOR.

https://github.com/nrfconnect/sdk-nrf/blob/f783fe7fd18a11a95045cb0f1b1a6a901f43e185/lib/lte_link_control/lte_lc.c#L973

[dejans]

Hi,

How many devices do you have that connect to the SFR network? Do you see the same problem on all devices?

Best regards,
Dejan