LTE connection timeout after 30x modem on/off

[MBeonas]

We are using nrf9160 and Modem firmware 1.2.3. This might be a regression of this bug.

Our concept is to switch the modem on via lte_lc_connect_async(), exchange some MQTT messages and then go back to low power idle by switching the modem off via. lte_lc_offline().

On the 30th cycle (31st time switching the modem on after power-on reset), we suddenly fail to get a LTE connection and run into our timeout handling. All subsequent tries also fail.

Attached you can find a trace of the last successful connection cycle (29.log) and the first unsuccessful cycle (30.log).

Fullscreen 8611.log Download

[00:17:19.126,464] <inf> modem_manager: Periodic wake up 29
[00:17:19.126,739] <inf> datastore: Ignoring Event 0x104: 0
[00:17:29.128,570] <inf> modem_manager: Battery state of charge: 95
[00:17:29.130,096] <inf> modem_manager: Powering on modem for forced upload...
[00:17:29.130,432] <inf> datastore: Ignoring Event 0x201: 0
[00:17:29.130,676] <inf> modem_manager: Trying to connect to LTE network
[00:17:29.130,981] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,1,0
[00:17:29.131,408] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=0,1,1,0
[00:17:29.137,969] <dbg> at_cmd.at_write: Awaiting response for AT%XSYSTEMMODE=0,1,1,0
[00:17:29.139,038] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[00:17:29.139,343] <dbg> at_cmd.at_write: Bytes sent: 22
[00:17:29.139,617] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
[00:17:29.139,923] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:29.140,258] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:29.146,148] <dbg> at_cmd.at_write: Awaiting response for AT+CFUN=1
[00:17:29.174,926] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[00:17:29.175,262] <dbg> at_cmd.at_write: Bytes sent: 9
[00:17:29.175,537] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:29.175,842] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:38.013,549] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 2,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:17:38.014,068] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:17:38.014,770] <dbg> lte_lc.parse_psm_cfg: TAU: -1 sec, active time: -1 sec

[00:17:38.015,136] <inf> modem_manager: LTE_LC_EVT_NW_REG_STATUS: 2
[00:17:38.015,411] <inf> modem_manager: LTE_LC_EVT_CELL_UPDATE id: 28451850 tac: 50050
[00:17:38.015,808] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:38.016,113] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:38.311,889] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 1

[00:17:38.312,255] <dbg> lte_lc.at_handler: +CSCON notification
[00:17:38.312,622] <inf> modem_manager: LTE_LC_EVT_RRC_UPDATE: 1
[00:17:38.312,927] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:38.313,262] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.189,819] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 5,"C382","01B2240A",9,,,"11100000","01011111"

[00:17:41.190,307] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"C382","01B2240A",9,,,"11100000","01011111"

[00:17:41.190,979] <dbg> lte_lc.parse_psm_cfg: TAU: 1116000 sec, active time: -1 sec

[00:17:41.191,406] <inf> modem_manager: LTE_LC_EVT_NW_REG_STATUS: 5
[00:17:41.191,711] <dbg> at_cmd.at_write: Sending command AT%XCBAND
[00:17:41.192,016] <dbg> at_cmd.so[00:17:41.192,260] <dbg> at_cmd.at_write: Awaiting response for AT%XCBAND
cket_thread_fn: Allocating memory slab for AT socket
[00:17:41.192,749] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.193,054] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 17 bytes, %XCBAND: 8
OK

[00:17:41.193,420] <dbg> at_cmd.at_write: Bytes sent: 9
[00:17:41.193,756] <dbg> at_cmd.at_write: Sending command AT%XCBAND=?
[00:17:41.194,091] <dbg> at_cmd.so[00:17:41.194,335] <dbg> at_cmd.at_write: Awaiting response for AT%XCBAND=?
cket_thread_fn: Allocating memory slab for AT socket
[00:17:41.194,824] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.195,129] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, %XCBAND: (1,2,3,4,5,8,12,13,17,19,20,25,26,28,66)
OK

[00:17:41.195,617] <dbg> at_cmd.at_write: Bytes sent: 11
[00:17:41.195,892] <dbg> at_cmd.at_write: Sending command AT+CGDCONT?
[00:17:41.196,228] <dbg> at_cmd.so[00:17:41.196,472] <dbg> at_cmd.at_write: Awaiting response for AT+CGDCONT?
cket_thread_fn: Allocating memory slab for AT socket
[00:17:41.196,960] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.197,265] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CGDCONT: 0,"IP","iot.1nce.net","100.70.44.4",0,0
OK

[00:17:41.197,723] <dbg> at_cmd.at_write: Bytes sent: 11
[00:17:41.198,211] <dbg> at_cmd.at_write: Sending command AT+CEMODE?
[00:17:41.198,547] <dbg> at_cmd.socket_thread_fn: Allocating me[00:17:41.198,913] <dbg> at_cmd.at_write: Awaiting response for AT+CEMODE?
mory slab for AT socket
[00:17:41.199,340] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.199,645] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 17 bytes, +CEMODE: 0
OK

[00:17:41.200,012] <dbg> at_cmd.at_write: Bytes sent: 10
[00:17:41.200,378] <dbg> at_cmd.at_write: Sending command AT+COPS?
[[00:17:41.200,805] <dbg> at_cmd.at_write: Awaiting response for AT+COPS?
00:17:41.200,714] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.201,446] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.201,721] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 27 bytes, +COPS: 0,2,"26201",9
OK

[00:17:41.202,117] <dbg> at_cmd.at_write: Bytes sent: 8
[00:17:41.202,514] <dbg> at_cmd.at_write: Sending command AT+CEREG?
[[00:17:41.202,941] <dbg> at_cmd.at_write: Awaiting response for AT+CEREG?
00:17:41.202,850] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.203,582] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.203,887] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 62 bytes, +CEREG: 5,5,"C382","01B2240A",9,,,"11100000","01011111"
OK

[00:17:41.204,376] <dbg> at_cmd.at_write: Bytes sent: 9
[00:17:41.204,895] <dbg> at_cmd.at_write: Sending command AT+CEREG?
[00[00:17:41.205,322] <dbg> at_cmd.at_write: Awaiting response for AT+CEREG?
:17:41.205,230] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.205,963] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.206,268] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 62 bytes, +CEREG: 5,5,"C382","01B2240A",9,,,"11100000","01011111"
OK

[00:17:41.206,756] <dbg> at_cmd.at_write: Bytes sent: 9
[00:17:41.207,305] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE?
[00:17:41.[00:17:41.207,794] <dbg> at_cmd.at_write: Awaiting response for AT%XSYSTEMMODE?
207,641] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.208,404] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.208,679] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 28 bytes, %XSYSTEMMODE: 0,1,1,0
OK

[00:17:41.209,075] <dbg> at_cmd.at_write: Bytes sent: 15
[00:17:41.209,503] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE?
[[00:17:41.209,930] <dbg> at_cmd.at_write: Awaiting response for AT%XSYSTEMMODE?
00:17:41.209,838] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.210,601] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.210,876] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 28 bytes, %XSYSTEMMODE: 0,1,1,0
OK

[00:17:41.211,273] <dbg> at_cmd.at_write: Bytes sent: 15
[00:17:41.211,639] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE?
[[00:17:41.212,097] <dbg> at_cmd.at_write: Awaiting response for AT%XSYSTEMMODE?
00:17:41.212,005] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.212,738] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.213,043] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 28 bytes, %XSYSTEMMODE: 0,1,1,0
OK

[00:17:41.213,439] <dbg> at_cmd.at_write: Bytes sent: 15
[00:17:41.213,806] <dbg> at_cmd.at_write: Sending command AT+CGDCONT?
[[00:17:41.214,233] <dbg> at_cmd.at_write: Awaiting response for AT+CGDCONT?
00:17:41.214,141] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.214,874] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.215,179] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CGDCONT: 0,"IP","iot.1nce.net","100.70.44.4",0,0
OK

[00:17:41.215,637] <dbg> at_cmd.at_write: Bytes sent: 11
[00:17:41.216,125] <dbg> at_cmd.at_write: Sending command AT%XSIM?
[[00:17:41.216,552] <dbg> at_cmd.at_write: Awaiting response for AT%XSIM?
00:17:41.216,461] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.217,193] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.217,468] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 15 bytes, %XSIM: 1
OK

[00:17:41.217,834] <dbg> at_cmd.at_write: Bytes sent: 8
[00:17:41.218,200] <dbg> at_cmd.at_write: Sending command AT+CRSM=176,12258,0,0,10
[00:17:41.218,[00:17:41.218,780] <dbg> at_cmd.at_write: Awaiting response for AT+CRSM=176,12258,0,0,10
566] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.219,360] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.238,616] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 42 bytes, +CRSM: 144,0,"98888260660020892915"
OK

[00:17:41.239,044] <dbg> at_cmd.at_write: Bytes sent: 24
[00:17:41.239,471] <dbg> at_cmd.at_write: Sending command AT+CIMI
[[00:17:41.239,868] <dbg> at_cmd.at_write: Awaiting response for AT+CIMI
00:17:41.239,776] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.240,509] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.240,814] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 22 bytes, 901405100298925
OK

[00:17:41.241,180] <dbg> at_cmd.at_write: Bytes sent: 7
[00:17:41.241,546] <dbg> at_cmd.at_write: Sending command AT+CGMR
[[00:17:41.241,943] <dbg> at_cmd.at_write: Awaiting response for AT+CGMR
00:17:41.241,851] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.242,584] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.242,889] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 24 bytes, mfw_nrf9160_1.2.3
OK

[00:17:41.243,255] <dbg> at_cmd.at_write: Bytes sent: 7
[00:17:41.243,591] <dbg> at_cmd.at_write: Sending command AT%XVBAT
[[00:17:41.244,018] <dbg> at_cmd.at_write: Awaiting response for AT%XVBAT
00:17:41.243,927] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.244,659] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.244,964] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 19 bytes, %XVBAT: 4375
OK

[00:17:41.245,330] <dbg> at_cmd.at_write: Bytes sent: 8
[00:17:41.245,666] <dbg> at_cmd.at_write: Sending command AT+CGSN
[[00:17:41.246,063] <dbg> at_cmd.at_write: Awaiting response for AT+CGSN
00:17:41.245,971] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.246,704] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:41.247,009] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 22 bytes, 352656100353419
OK

[00:17:41.247,375] <dbg> at_cmd.at_write: Bytes sent: 7
[00:17:41.247,711] <inf> modem_manager: cellposition mcc 262 mnc 1 lac 50050 cellid 28451850
[00:17:41.248,107] <inf> modem_manager: LTE_LC_EVT_PSM_UPDATE tau: 1116000 active_time: -1
[00:17:41.248,474] <inf> datastore: Ignoring Event 0x202: 0
[00:17:41.248,748] <inf> modem_manager: Connected to LTE network
[00:17:41.249,084] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:41.250,183] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:49.465,362] <dbg> moto_cloud.moto_mqtt_evt_handler: MQTT_EVT_CONNACK: 0
[00:17:49.465,667] <inf> modem_manager: CLOUD_EVT_CONNECTED
[00:17:49.466,583] <inf> datastore: Written 38 bytes for 2 records
[00:17:49.468,322] <inf> moto_cloud: mqtt_input: 0
[00:17:49.468,627] <inf> modem_manager: Transmission ok for 38 bytes
[00:17:50.057,952] <dbg> moto_cloud.moto_mqtt_evt_handler: MQTT_EVT_SUBACK: id=88 result=0
[00:17:50.058,288] <inf> datastore: Ignoring Event 0x404: 0
[00:17:50.059,600] <inf> moto_cloud: mqtt_input: 0
[00:17:50.540,496] <dbg> moto_cloud.moto_mqtt_evt_handler: MQTT_EVT_PUBLISH: id=0 len=0 topic=$aws/things/%s/shadow/get
[00:17:50.540,954] <inf> moto_cloud: mqtt_input: 0
[00:17:50.621,093] <dbg> moto_cloud.moto_mqtt_evt_handler: MQTT_EVT_PUBLISH: id=0 len=2 topic=embedded/%s/delta
[00:17:50.621,643] <inf> datastore: Ignoring Event 0x410: 0
[00:17:50.621,917] <inf> datastore: Ignoring Event 0x401: 0
[00:17:50.622,192] <inf> moto_cloud: Nothing new in received shadow from cloud
[00:17:50.622,528] <inf> moto_cloud: mqtt_input: 0
[00:17:50.725,341] <dbg> moto_cloud.moto_mqtt_evt_handler: MQTT_EVT_DISCONNECT: result=0
[00:17:50.725,677] <inf> modem_manager: CLOUD_EVT_DISCONNECTED
[00:17:51.726,074] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
[00:17:51.732,604] <dbg> at_cmd.at_write: Awaiting response for AT+CFUN=4
[00:17:52.440,063] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 0,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:17:52.440,582] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:17:52.441,284] <dbg> lte_lc.parse_psm_cfg: TAU: -1 sec, active time: -1 sec

[00:17:52.441,680] <inf> modem_manager: LTE_LC_EVT_NW_REG_STATUS: 0
[00:17:52.441,955] <inf> modem_manager: LTE_LC_EVT_PSM_UPDATE tau: -1 active_time: -1
[00:17:52.442,321] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:52.442,626] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:52.530,273] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 0

[00:17:52.530,639] <dbg> lte_lc.at_handler: +CSCON notification
[00:17:52.531,005] <inf> modem_manager: LTE_LC_EVT_RRC_UPDATE: 0
[00:17:52.531,311] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:52.531,646] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:52.559,570] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[00:17:52.559,906] <dbg> at_cmd.at_write: Bytes sent: 9
[00:17:52.560,180] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:17:52.560,577] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:17:52.561,096] <inf> modem_manager: Going back to sleep

Fullscreen 1830.log Download

[00:17:57.561,645] <inf> modem_manager: Periodic wake up 30
[00:17:57.561,920] <inf> datastore: Ignoring Event 0x104: 0
[00:18:07.563,751] <inf> modem_manager: Battery state of charge: 95
[00:18:07.565,277] <inf> modem_manager: Powering on modem for forced upload...
[00:18:07.565,612] <inf> datastore: Ignoring Event 0x201: 0
[00:18:07.565,856] <inf> modem_manager: Trying to connect to LTE network
[00:18:07.566,162] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,1,0
[00:18:07.566,589] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=0,1,1,0
[00:18:07.573,150] <dbg> at_cmd.at_write: Awaiting response for AT%XSYSTEMMODE=0,1,1,0
[00:18:07.574,218] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[00:18:07.574,523] <dbg> at_cmd.at_write: Bytes sent: 22
[00:18:07.574,798] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
[00:18:07.575,103] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:18:07.575,439] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:18:07.581,329] <dbg> at_cmd.at_write: Awaiting response for AT+CFUN=1
[00:18:07.610,107] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[00:18:07.610,443] <dbg> at_cmd.at_write: Bytes sent: 9
[00:18:07.610,717] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:18:07.611,053] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:18:08.956,054] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 2,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:18:08.956,573] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:18:08.957,275] <dbg> lte_lc.parse_psm_cfg: TAU: -1 sec, active time: -1 sec

[00:18:08.957,672] <inf> modem_manager: LTE_LC_EVT_NW_REG_STATUS: 2
[00:18:08.957,977] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:18:08.958,312] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:19:07.610,778] <inf> datastore: Ignoring Event 0x204: 1
[00:19:07.611,022] <err> modem_manager: lte_lc_connect timed out: -11
[00:20:12.567,138] <err> modem_manager: timeout while waiting for shadow sync. Disconnecting anyway.
[00:20:12.567,504] <dbg> at_cmd.at_write: Sending command AT+CFUN=4
[00:20:12.574,035] <dbg> at_cmd.at_write: Awaiting response for AT+CFUN=4
[00:20:12.586,791] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 0,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:20:12.587,310] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0,"C382","01B2240A",9,0,0,"11100000","11100000"

[00:20:12.588,012] <dbg> lte_lc.parse_psm_cfg: TAU: -1 sec, active time: -1 sec

[00:20:12.588,378] <inf> modem_manager: LTE_LC_EVT_NW_REG_STATUS: 0
[00:20:12.588,714] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:20:12.589,019] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:20:12.741,302] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK

[00:20:12.741,607] <dbg> at_cmd.at_write: Bytes sent: 9
[00:20:12.741,882] <dbg> at_cmd.socket_thread_fn: Allocating memory slab for AT socket
[00:20:12.742,279] <dbg> at_cmd.socket_thread_fn: Allocation done
[00:20:12.742,828] <inf> modem_manager: Going back to sleep

[Heidi-Irene Harvey Sollie]

Hi!

Thanks for the report. Are you able to take a modem trace when this issue occurs?

Best regards,

Heidi

[Heidi-Irene Harvey Sollie]

Hi again,

On the 30th cycle (31st time switching the modem on after power-on reset), we suddenly fail to get a LTE connection and run into our timeout handling. All subsequent tries also fail.

 Could you check if it is able to connect again after one hour?

You're only allowed to do 30 attaches per hour, so if you exceed this limit you have to wait another hour before you can connect again.

[MBeonas]

Hi Heidi,

I was about to start preparing a Modem Trace. Is this still needed?

Where is this threshold of 30 attaches per hour defined/documented? Is this defnied by the modem or by the LTE standard? Is there any way to change this limit?

We are planning on a low-latency tracking mode with our software in which we are recording GPS for one minute, then enable the LTE modem to upload the data and then switch back to GPS tracking as fast as possible.

We need to put the modem in offline state for that. If we would rely on the modem for re-enabling the GPS while we are still connected to a LTE network, the modem needs to wait in LTE mode for the RRC timeout until it can switch back to GPS. That timeout is >20s with our carrier which is hardly acceptable regarding lost GPS data points.

[Heidi-Irene Harvey Sollie]

It's the GSMA specified Radio Policy Manager (RPM) feature which is blocking the ATTACH command. RPM is used for protecting the network from excessive signaling loads in various scenarios. In this case, the default value 30 is used for PDP Context Activation Requests (TS.34 - IoT Device Connection Efficiency Guidelines page 43 TS.34_8.2.4_REQ_010).

This is implemented in the modem firmware. I don't believe there's any way for the user to change this default value, but I will double-check with the developers. 

MBeonas said:

I was about to start preparing a Modem Trace. Is this still needed?

If you have confirmed that the device is able to connect to the network again if you wait an hour, a modem trace is not needed as this isn't a bug.

 

If you're enabling/disabling the LTE modem to get a GPS fix, you could try setting a higher priority on the GPS process (https://github.com/nrfconnect/sdk-nrf/pull/2711).

And putting a lower accuracy threshold on the GPS fix will give you a lower TTFF as well (https://github.com/nrfconnect/sdk-nrf/pull/3427).

Best regards,

Heidi

[MBeonas]

Looks like the modem is able to get a LTE connection again after a while.

Thank you for your helpful answer and your pointers.

Best Regards

Martin