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 don't have a lot of devices on SFR.

The issue here is that, at my location, my devices can connect to 3 different MNO.They are all accessible (I am in a city with good coverage) and each device device decides on its own which to use since they are all supported by my SIM contract.

Is there a way to force a device to connect to a specific MNO, so I can force some tests ?

Thanks

[dejans]

Hi,

Regarding the selection of a specific MNO, you can look at this discussion.

Your issue might happen due to suboptimal application logic when TAU rejection happens and PDN gets deleted. If this is the case, application should monitor CEREG notifications and retry TCP connection after re-attachment. To get more information and investigate this issue further, it is usually very beneficial if we can get your modem trace. 

Please note that I can make this ticket private at any point if you plan to share any private or sensitive information. Please let me know if there is a need for that.

Best regards,
Dejan

[i21-mehdi]

Did you finally understand what happens with SFR?  I see similar behavior with some device connected specifically to SFR…

[Vincent44]

No, I was unable to fully understand.

Since this was not a major issue, I ended up coding a workaround to handle the issue in a different way.

[dejans]

Hi,

i21-mehdi, please open new support ticket.

Best regards,
Dejan