LTE connection timeout after 30x modem on/off

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).

8611.log
[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

1830.log
[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

Related