This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

nRF9160 behavior when changing mode and switching SIM

Hi,

We are currently trying to create a small test code to test multiple operator with different modes:

- lte-m1 or lte-nb1

- edrx 0s, 5.12s, 10.24s

- with and without psm

Our board has multiple SIM slot, with a SIM switch rerouting the SIM_xxx signals from the nRF9160.

After an initial lte_lc_init(), we setup the link control to use the configuration for the test.

Then we wait for a connection, turn the modem off, reconfigure the modem etc...

for (int i = 0; i < ARRAY_SIZE(test); i++) {
	const struct test_data *data = &test[i];

	LOG_WRN("====Starting test %d in 3 seconds=====", i);

	k_sleep(K_SECONDS(3));

	lte_lc_system_mode_set(data->mode, 0);
	lte_lc_psm_req(false);

	if (!data->use_edrx) {
		lte_lc_edrx_req(false);
	}
	else {
		lte_lc_edrx_param_set(LTE_LC_LTE_MODE_LTEM,
			data->ltem_edrx_value);
		lte_lc_edrx_param_set(LTE_LC_LTE_MODE_NBIOT,
			data->nbiot_edrx_value);
		lte_lc_edrx_req(true);
	}

	err = lte_lc_connect();
	if (err) {
		LOG_ERR("Test %d fails: no connection", i);
	}
	else {
		LOG_WRN("Connected ! Checking eDRX value");
		at_cmd_write("AT+CEDRXRDP", NULL, 0, NULL);
		k_sleep(K_SECONDS(2));
		at_cmd_write("AT+CEDRXRDP", NULL, 0, NULL);
		k_sleep(K_SECONDS(2));
		at_cmd_write("AT+CEDRXRDP", NULL, 0, NULL);
	}

	LOG_WRN("====Test %d done. "
		"Starting next one in 10 seconds====", i);
	lte_lc_power_off();
	k_sleep(K_SECONDS(10));
}

Once we are done with a SIM card, we turn off the modem, switch sim card and we go again.

The main issue that we have is that the modem is not reliable at all in that configuration.

Sometimes, a SIM card can connect when we start the test with it, but if it's the second SIM card to be tested, the connection is stuck at +CEREG=2 forever (literally)

With CONFIG_LTE_NETWORK_TIMEOUT=90, I would expect the connection to return an error once the timeout is reached, but not stuck forever.

What is the correct workflow to set the modem in multiple configuration in a short amount of time without the firmware being unreliable ?

Regards

Giuliano

Parents
  • Hi,

    How long is "forever"?

    Could you take a modem trace, and share the application log?

    What modem firmware version are you using?

    It would also be interresting if you could enable unsolicited responses from the %XSIM (1), %CESQ (1), +CEREG (5), +CMEE (1), +CNEC(24) and, if you are using mfw v1.3.0 %MDEV (1).

    Best regards,

    Didrik

  • Hi,

    Forever is until next reboot of the board. The longest time I've had before running out of patience was something around 30 minutes.

    I'll send you the result today.

    However, I cannot get the trace, as I don't have any available UART.

    Is there any possibility to get trace through SWD using SEGGER RTT?

    Regards

    Giuliano

  • Hi,

    I've attached the log received during our test.

    As you can see, the modem stops responding after the SIM card is switched (more than 15 minutes without any log at all)

    ==> What can you learn from these logs?

    [00:00:00.225,372] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
    [00:00:00.225,799] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
    [00:00:00.226,257] <dbg> at_cmd.at_cmd_set_notification_handler: Setting notification handler to 0x15659
    [00:00:00.226,745] <wrn> app: Starting test in 10 seconds
    [00:00:00.227,142] <dbg> at_cmd.socket_thread_fn: AT socket thread started
    [00:00:00.227,539] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:00.227,935] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.227,172] <inf> pwr_mngr: Pin 14 set to 0
    [00:00:10.227,539] <wrn> app: ====Calling lte_lc_init()====
    [00:00:10.227,905] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE?
    [00:00:10.236,938] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE?
    [00:00:10.239,776] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 28 bytes, %XSYSTEMMODE: 1,0[00:02:19.731,414] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:02:19.731,964] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:02:19.738,708] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:02:19.744,079] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.744,506] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.744,964] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS=
    [00:02:19.745,391] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.745,819] <dbg> at_cmd.at_write: Sending command AT+CPSMS=
    [00:02:19.750,274] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:19.752,716] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.753,143] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.753,601] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for LTE-M
    [00:02:19.754,028] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for NB-IoT
    [00:02:19.754,516] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,4,"0001"
    [00:02:19.755,004] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.761,047] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,4,"0001"
    [00:02:19.767,730] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:19.770,294] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.770,721] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.771,209] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,5,"0001"
    [00:02:19.771,697] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.772,094] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,5,"0001"
    [00:02:19.776,489] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:19.778,747] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.779,174] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.779,693] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:02:19.780,242] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:02:19.780,700] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.791,717] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:02:19.798,400] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:19.803,833] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.804,229] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.804,718] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:02:19.805,145] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.805,541] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:02:19.810,028] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:19.812,194] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.812,622] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.813,079] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:02:19.813,507] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.819,580] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:02:19.826,232] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:19.828,399] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.828,796] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.829,284] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=1
    [00:02:19.829,742] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.830,139] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
    [00:02:19.834,594] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:19.892,761] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:19.893,188] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:19.893,646] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:19.894,073] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:00.222,808] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
    [00:00:00.223,236] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
    [00:00:00.223,693] <dbg> at_cmd.at_cmd_set_notification_handler: Setting notification handler to 0x15699
    [00:00:00.224,182] <wrn> app: Starting test in 10 seconds
    [00:00:00.224,578] <dbg> at_cmd.socket_thread_fn: AT socket thread started
    [00:00:00.224,945] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:00.225,372] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.224,609] <inf> pwr_mngr: Pin 14 set to 0
    [00:00:10.224,975] <wrn> app: ====Calling lte_lc_init()====
    [00:00:10.225,341] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE?
    [00:00:10.232,055] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE?
    [00:00:10.234,527] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 28 bytes, %XSYSTEMMODE: 0,1,0,0
    OK
    
    [00:00:10.235,015] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.235,717] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:00:10.236,267] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:00:10.236,724] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.237,152] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:00:10.240,875] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.246,185] <dbg> at_[00:00:00.222,778] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
    [00:00:00.223,205] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
    [00:00:00.223,663] <dbg> at_cmd.at_cmd_set_notification_handler: Setting notification handler to 0x15699
    [00:00:00.224,151] <wrn> app: Starting test in 10 seconds
    [00:00:00.224,548] <dbg> at_cmd.socket_thread_fn: AT socket thread started
    [00:00:00.224,914] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:00.225,341] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.224,578] <inf> pwr_mngr: Pin 14 set to 0
    [00:00:10.224,945] <wrn> app: ====Calling lte_lc_init()====
    [00:00:10.225,311] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE?
    [00:00:10.231,994] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE?
    [00:00:10.234,893] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 28 bytes, %XSYSTEMMODE: 0,1,0,0
    OK
    
    [00:00:10.235,382] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.236,083] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:00:10.236,633] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:00:10.237,091] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.237,518] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:00:10.241,088] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.246,459] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.246,887] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.247,344] <dbg> lte_lc.init_and_config: System mode (1) and preference (0) configured
    [00:00:10.253,479] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XMODEMTRACE=1,2
    [00:00:10.253,936] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.254,364] <dbg> at_cmd.at_write: Sending command AT%XMODEMTRACE=1,2
    [00:00:10.261,047] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.264,160] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.264,587] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.265,045] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:00:10.265,472] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.265,899] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:00:10.270,355] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.272,521] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.283,538] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.283,996] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:00:10.284,423] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.284,851] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:00:10.291,503] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.293,670] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.294,067] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.294,525] <wrn> app: ====Registering %XSIM urc====
    [00:00:10.294,921] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSIM=1
    [00:00:10.295,349] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.295,776] <dbg> at_cmd.at_write: Sending command AT%XSIM=1
    [00:00:10.299,865] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.302,001] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.307,403] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.307,830] <wrn> app: ====Registering %CESQ urc====
    [00:00:10.308,868] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%CESQ=1
    [00:00:10.309,326] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.309,753] <dbg> at_cmd.at_write: Sending command AT%CESQ=1
    [00:00:10.316,406] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.318,542] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.318,969] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.319,427] <wrn> app: ====Registering %MDEV urc====
    [00:00:10.319,793] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%MDEV=1
    [00:00:10.320,251] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.336,242] <dbg> at_cmd.at_write: Sending command AT%MDEV=1
    [00:00:10.342,895] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.344,909] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 8 bytes, ERROR
    
    [00:00:10.345,367] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.345,794] <wrn> app: ====Registering +CMEE urc====
    [00:00:10.346,160] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CMEE=1
    [00:00:10.346,618] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.347,015] <dbg> at_cmd.at_write: Sending command AT+CMEE=1
    [00:00:10.351,135] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.353,271] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.353,698] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.354,156] <wrn> app: ====Registering +CNEC urc====
    [00:00:10.365,142] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CNEC=24
    [00:00:10.365,570] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.365,997] <dbg> at_cmd.at_write: Sending command AT+CNEC=24
    [00:00:10.372,650] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.374,786] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.375,213] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.375,671] <wrn> app: ====Using SIM 0====
    [00:00:10.376,007] <wrn> app: ====Starting test 0 in 3 seconds=====
    [00:00:10.376,403] <wrn> app: Mode: 1, edrx: 1, ltem: 0001, nbiot: 0001
    [00:00:10.376,892] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.377,288] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.376,953] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.377,502] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.384,185] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.389,587] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.390,014] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.390,472] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS=
    [00:00:13.390,899] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.391,326] <dbg> at_cmd.at_write: Sending command AT+CPSMS=
    [00:00:13.395,782] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.398,223] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.398,651] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.399,108] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for LTE-M
    [00:00:13.399,536] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for NB-IoT
    [00:00:13.400,054] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,4,"0001"
    [00:00:13.400,512] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.400,939] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,4,"0001"
    [00:00:13.418,212] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.420,776] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.421,173] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.421,691] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,5,"0001"
    [00:00:13.422,149] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.422,576] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,5,"0001"
    [00:00:13.426,971] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.429,229] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.429,656] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.430,145] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.430,694] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.436,798] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.437,225] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.443,908] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.449,310] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.449,737] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.450,195] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:00:13.450,653] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.451,049] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:00:13.455,505] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.457,672] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.458,068] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.458,526] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:00:13.458,984] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.459,381] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:00:13.463,867] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.466,033] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.471,405] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.471,893] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=1
    [00:00:13.472,991] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.473,419] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
    [00:00:13.480,072] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.538,574] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.539,001] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.539,459] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.539,886] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.525,787] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 11 bytes, %XSIM: 1
    
    [00:00:14.526,916] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.527,343] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.571,502] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 19 bytes, %CESQ: 66,3,15,2
    
    [00:00:14.572,021] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.572,418] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.572,875] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 2,"767C","07F0E208",7,0,0,"11100000","11100000"
    
    [00:00:14.582,550] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"767C","07F0E208",7,0,0,"11100000","11100000"
    
    [00:00:14.583,343] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    [00:00:14.583,801] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:14.584,289] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.584,686] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.620,819] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 19 bytes, %CESQ: 66,3,22,3
    
    [00:00:14.638,793] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.639,221] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.639,648] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 1
    
    [00:00:14.640,106] <dbg> lte_lc.at_handler: +CSCON notification
    [00:00:14.640,594] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.641,021] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:15.988,555] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CNEC_ESM: 50,0
    
    [00:00:15.989,044] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:15.989,471] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:15.989,929] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 5,"767C","07F0E208",7,,,"11100000","11100000"
    
    [00:00:15.990,509] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"767C","07F0E208",7,,,"11100000","11100000"
    
    [00:00:15.991,302] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 5
    [00:00:15.991,760] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:15.992,156] <dbg> lte_lc_helpers.parse_psm: TAU: -1 sec, active time: -1 sec
    
    [00:00:15.992,706] <wrn> app: Connected ! Checking eDRX value
    [00:00:15.993,103] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:15.993,530] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:16.003,875] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 16 bytes, +CNEC_EMM: 13
    
    [00:00:16.004,364] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:16.004,791] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:17.389,160] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 0
    
    [00:00:17.390,289] <dbg> lte_lc.at_handler: +CSCON notification
    [00:00:17.390,808] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:17.391,204] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:17.426,879] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 21 bytes, %CESQ: 255,0,255,0
    
    [00:00:17.457,641] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:17.458,068] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:17.458,496] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 59 bytes, +CEREG: 2,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:17.459,777] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:17.460,571] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    [00:00:17.461,029] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:17.461,517] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:17.461,914] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:17.994,354] <dbg> at_cmd.at_write: Sending command AT+CEDRXRDP
    [00:00:17.994,964] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXRDP
    [00:00:17.997,314] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEDRXRDP: 4,"0001","",""
    OK
    
    [00:00:17.998,168] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:17.998,626] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:17.999,053] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:19.998,657] <dbg> at_cmd.at_write: Sending command AT+CEDRXRDP
    [00:00:19.999,237] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXRDP
    [00:00:20.005,615] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEDRXRDP: 4,"0001","",""
    OK
    
    [00:00:20.006,103] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:20.006,561] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:20.006,988] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.006,591] <dbg> at_cmd.at_write: Sending command AT+CEDRXRDP
    [00:00:22.013,275] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXRDP
    [00:00:22.016,296] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEDRXRDP: 4,"0001","",""
    OK
    
    [00:00:22.016,784] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:22.017,211] <wrn> app: ====Test 0 done. Starting next one in 10 seconds====
    [00:00:22.017,700] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=0
    [00:00:22.018,127] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.018,554] <dbg> at_cmd.at_write: Sending command AT+CFUN=0
    [00:00:22.022,491] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.051,727] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 59 bytes, +CEREG: 0,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:22.052,978] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:22.053,802] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 0
    [00:00:22.054,260] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:22.054,718] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.055,145] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.140,289] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 11 bytes, %XSIM: 0
    
    [00:00:22.140,777] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.141,174] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.152,740] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:22.153,167] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:22.153,625] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.154,052] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:32.153,625] <wrn> app: ====Starting test 1 in 3 seconds=====
    [00:00:32.154,052] <wrn> app: Mode: 2, edrx: 1, ltem: 0001, nbiot: 0001
    [00:00:35.154,571] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.155,120] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.161,834] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.163,574] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.169,036] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.169,494] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS=
    [00:00:35.169,921] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.170,349] <dbg> at_cmd.at_write: Sending command AT+CPSMS=
    [00:00:35.177,001] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.179,443] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.179,870] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.180,297] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for LTE-M
    [00:00:35.180,755] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for NB-IoT
    [00:00:35.181,243] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,4,"0001"
    [00:00:35.181,701] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.182,128] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,4,"0001"
    [00:00:35.185,638] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.187,896] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.188,323] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.188,812] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,5,"0001"
    [00:00:35.194,915] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.195,343] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,5,"0001"
    [00:00:35.202,026] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.204,589] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.205,017] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.205,505] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.206,054] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.206,512] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.206,939] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.210,784] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.216,217] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.216,644] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.217,102] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:00:35.217,529] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.223,571] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:00:35.230,255] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.232,421] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.232,818] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.233,276] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:00:35.233,734] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.234,130] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:00:35.238,616] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.240,844] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.251,861] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.252,349] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=1
    [00:00:35.252,777] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.253,204] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
    [00:00:35.259,857] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.319,732] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.320,129] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.320,617] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.321,044] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:05.321,746] <inf> lte_lc: Network connection attempt timed out
    [00:02:05.322,143] <err> app: Test 1 fails: no connection
    [00:02:05.322,479] <wrn> app: ====Test 1 done. Starting next one in 10 seconds====
    [00:02:05.322,967] <dbg> at_cmd.at_write: Sending command AT+CFUN=0
    [00:02:05.323,547] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=0
    [00:02:05.339,599] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 0,"FFFE","FFFFFFFF",7,0,0,"11100000","11100000"
    
    [00:02:05.340,179] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0,"FFFE","FFFFFFFF",7,0,0,"11100000","11100000"
    
    [00:02:05.341,003] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 0
    [00:02:05.341,430] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:02:05.341,918] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:05.342,315] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:05.344,543] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:05.344,970] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:05.345,428] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:05.345,855] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:15.345,458] <wrn> app: ====Using SIM 1====
    [00:02:15.345,825] <wrn> app: ====Starting test 0 in 3 seconds=====
    [00:02:15.346,221] <wrn> app: Mode: 1, edrx: 1, ltem: 0001, nbiot: 0001
    [00:02:18.346,740] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:02:18.347,290] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:02:18.353,973] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:02:18.355,743] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.360,229] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.360,687] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS=
    [00:02:18.361,114] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.361,541] <dbg> at_cmd.at_write: Sending command AT+CPSMS=
    [00:02:18.368,194] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:18.370,635] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.371,063] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.371,520] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for LTE-M
    [00:02:18.371,948] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for NB-IoT
    [00:02:18.372,467] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,4,"0001"
    [00:02:18.372,924] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.378,967] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,4,"0001"
    [00:02:18.385,650] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:18.388,214] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.388,610] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.389,129] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,5,"0001"
    [00:02:18.389,587] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.390,014] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,5,"0001"
    [00:02:18.394,409] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:18.396,667] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.397,094] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.408,172] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:02:18.408,721] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:02:18.409,210] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.409,606] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:02:18.416,290] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:18.421,691] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.422,119] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.422,576] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:02:18.423,034] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.423,431] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:02:18.427,917] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:18.435,058] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.435,455] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.435,913] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:02:18.436,370] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.436,767] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:02:18.441,253] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:18.443,420] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.443,847] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.444,335] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=1
    [00:02:18.444,763] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.445,190] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
    [00:02:18.449,615] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:18.507,812] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:18.508,239] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:18.508,697] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:18.509,124] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:47.649,322] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 2,"07A1","00A12301",7,0,0,"11100000","11100000"
    
    [00:02:47.649,902] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"07A1","00A12301",7,0,0,"11100000","11100000"
    
    [00:02:47.650,726] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    [00:02:47.651,184] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:02:47.651,641] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:47.652,069] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:47.837,066] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 1
    
    [00:02:47.837,524] <dbg> lte_lc.at_handler: +CSCON notification
    [00:02:47.838,012] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:47.838,409] <dbg> at_cmd.socket_thread_fn: Listening on socket
    
    *** test stopped after no more log received for 15 minutes ***
    

    Here is a small extract of our testing code:

    struct test_data {
    	enum lte_lc_system_mode mode;
    	bool use_edrx;
    	const char *ltem_edrx_value;
    	const char *nbiot_edrx_value;
    };
    
    static const struct test_data test[] = {
    	{
    		.mode = LTE_LC_SYSTEM_MODE_LTEM,
    		.use_edrx = true,
    		.ltem_edrx_value = "0001",
    		.nbiot_edrx_value = "0001",
    	},
    	{
    		.mode = LTE_LC_SYSTEM_MODE_NBIOT,
    		.use_edrx = true,
    		.ltem_edrx_value = "0001",
    		.nbiot_edrx_value = "0001",
    	},
    };
    
    int main(void)
    {
    	int err;
    
        ... uninteresting init ...
        
        gpio_pin_configure(gpio, 31, GPIO_OUTPUT);
    
    	LOG_WRN("====Calling lte_lc_init()====");
    	lte_lc_init();
    
    	LOG_WRN("====Registering %%XSIM urc====");
    	at_cmd_write("AT%XSIM=1", NULL, 0, NULL);
    
    	LOG_WRN("====Registering %%CESQ urc====");
    	at_cmd_write("AT%CESQ=1", NULL, 0, NULL);
    
    	LOG_WRN("====Registering %%MDEV urc====");
    	at_cmd_write("AT%MDEV=1", NULL, 0, NULL);
    
    	LOG_WRN("====Registering +CMEE urc====");
    	at_cmd_write("AT+CMEE=1", NULL, 0, NULL);
    
    	LOG_WRN("====Registering +CNEC urc====");
    	at_cmd_write("AT+CNEC=24", NULL, 0, NULL);
    
    	for (int sim = 0; sim < 2; sim++) {
    		LOG_WRN("====Using SIM %d====", sim);
    		gpio_pin_set(gpio, 31, sim);
    
    		for (int i = 0; i < ARRAY_SIZE(test); i++) {
    			const struct test_data *data = &test[i];
    
    			LOG_WRN("====Starting test %d in 3 seconds=====", i);
    			LOG_WRN("Mode: %d, edrx: %d, ltem: %s, nbiot: %s",
    				data->mode, data->use_edrx,
    				str_or_null(data->ltem_edrx_value),
    				str_or_null(data->nbiot_edrx_value));
    
    			k_sleep(K_SECONDS(3));
    
    			lte_lc_system_mode_set(data->mode, 0);
    			lte_lc_psm_req(false);
    
    			if (!data->use_edrx) {
    				lte_lc_edrx_req(false);
    			}
    			else {
    				lte_lc_edrx_param_set(LTE_LC_LTE_MODE_LTEM,
    					data->ltem_edrx_value);
    				lte_lc_edrx_param_set(LTE_LC_LTE_MODE_NBIOT,
    					data->nbiot_edrx_value);
    				lte_lc_edrx_req(true);
    			}
    
    			err = lte_lc_connect();
    			if (err) {
    				LOG_ERR("Test %d fails: no connection", i);
    			}
    			else {
    				LOG_WRN("Connected ! Checking eDRX value");
    				k_sleep(K_SECONDS(2));
    				at_cmd_write("AT+CEDRXRDP", NULL, 0, NULL);
    				k_sleep(K_SECONDS(2));
    				at_cmd_write("AT+CEDRXRDP", NULL, 0, NULL);
    				k_sleep(K_SECONDS(2));
    				at_cmd_write("AT+CEDRXRDP", NULL, 0, NULL);
    			}
    
    			LOG_WRN("====Test %d done. "
    				"Starting next one in 10 seconds====", i);
    			lte_lc_power_off();
    			k_sleep(K_SECONDS(10));
    		}
    	}
    
    	return 0;
    }
    

    And our prj.conf:

    # General config
    CONFIG_NEWLIB_LIBC=y
    CONFIG_ASSERT=y
    CONFIG_REBOOT=y
    CONFIG_SERIAL=n
    
    # Network
    CONFIG_NETWORKING=y
    CONFIG_NET_NATIVE=n
    CONFIG_NET_SOCKETS=y
    CONFIG_NET_SOCKETS_OFFLOAD=y
    
    # LTE link control
    CONFIG_LTE_LINK_CONTROL=y
    CONFIG_LTE_NETWORK_MODE_LTE_M=y
    CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y
    CONFIG_LTE_NETWORK_USE_FALLBACK=n
    CONFIG_LTE_NETWORK_TIMEOUT=90
    CONFIG_LTE_AUTO_INIT_AND_CONNECT=n
    
    # Modem info
    CONFIG_NRF_MODEM_LIB=y
    CONFIG_NRF_MODEM_LIB_TRACE_ENABLED=y
    
    # Heap and stacks
    CONFIG_HEAP_MEM_POOL_SIZE=16384
    CONFIG_MAIN_STACK_SIZE=8192
    CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048
    CONFIG_HW_STACK_PROTECTION=y

    The modem firmware is the 1.3.0.

    The nRF9160 chip we are using comes from a kinda old board, and as the following lines written on it:

    nrf9160 SICA

    B0

    191104

    I'll try to see if I can redirect trace to SWD.

    Giuliano

  • I apologise for not remembering this earlier, but you have to send the list of AT commands for each test.

    The modem removes any urc subscriptions when it receives +CFUN=0.

  • Here is the newest log.

    Same thing, test stopped after 10 min without any more logs

    [00:00:00.222,534] <dbg> at_cmd.at_cmd_driver_init: Common AT socket created
    [00:00:00.222,961] <dbg> at_cmd.at_cmd_driver_init: Common AT socket processing thread created
    [00:00:00.223,419] <dbg> at_cmd.at_cmd_set_notification_handler: Setting notification handler to 0x156a5
    [00:00:00.223,937] <wrn> app: Starting test in 10 seconds
    [00:00:00.224,304] <dbg> at_cmd.socket_thread_fn: AT socket thread started
    [00:00:00.224,700] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:00.225,097] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.224,334] <inf> pwr_mngr: Pin 14 set to 0
    [00:00:10.224,700] <wrn> app: ====Calling lte_lc_init()====
    [00:00:10.225,067] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE?
    [00:00:10.231,750] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE?
    [00:00:10.234,649] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 28 bytes, %XSYSTEMMODE: 1,0,0,0
    OK
    
    [00:00:10.235,137] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.235,778] <dbg> lte_lc.init_and_config: System mode (1) and preference (0) are already configured
    [00:00:10.236,328] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XMODEMTRACE=1,2
    [00:00:10.236,785] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.237,213] <dbg> at_cmd.at_write: Sending command AT%XMODEMTRACE=1,2
    [00:00:10.240,844] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.243,957] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.244,384] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.244,842] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:00:10.245,269] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.251,312] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:00:10.257,995] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.260,131] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.260,559] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.261,016] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:00:10.261,474] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.261,871] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:00:10.266,357] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.268,524] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.279,510] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.279,968] <wrn> app: ====Using SIM 0====
    [00:00:10.280,303] <wrn> app: ====Starting test 0 in 3 seconds=====
    [00:00:10.280,700] <wrn> app: Mode: 1, edrx: 1, ltem: 0001, nbiot: 0001
    [00:00:10.281,127] <wrn> app: ====Registering %XSIM urc====
    [00:00:10.281,494] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSIM=1
    [00:00:10.281,951] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.282,348] <dbg> at_cmd.at_write: Sending command AT%XSIM=1
    [00:00:10.289,031] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.291,168] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.291,595] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.302,612] <wrn> app: ====Registering %CESQ urc====
    [00:00:10.303,009] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%CESQ=1
    [00:00:10.303,436] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.303,833] <dbg> at_cmd.at_write: Sending command AT%CESQ=1
    [00:00:10.310,516] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.312,652] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.313,079] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.313,507] <wrn> app: ====Registering %MDEV urc====
    [00:00:10.313,903] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%MDEV=1
    [00:00:10.314,331] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.314,758] <dbg> at_cmd.at_write: Sending command AT%MDEV=1
    [00:00:10.318,847] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.320,831] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 8 bytes, ERROR
    
    [00:00:10.331,848] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.332,275] <wrn> app: ====Registering +CMEE urc====
    [00:00:10.332,641] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CMEE=1
    [00:00:10.333,099] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.333,496] <dbg> at_cmd.at_write: Sending command AT+CMEE=1
    [00:00:10.340,148] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.342,285] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.342,712] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.343,170] <wrn> app: ====Registering +CNEC urc====
    [00:00:10.343,536] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CNEC=24
    [00:00:10.343,963] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.344,390] <dbg> at_cmd.at_write: Sending command AT+CNEC=24
    [00:00:10.366,577] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:10.368,713] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:10.369,140] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:10.369,628] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:10.370,025] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.369,689] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.370,239] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.376,953] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.382,385] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.382,812] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.383,270] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS=
    [00:00:13.383,697] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.384,124] <dbg> at_cmd.at_write: Sending command AT+CPSMS=
    [00:00:13.388,580] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.391,021] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.391,448] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.391,906] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for LTE-M
    [00:00:13.392,333] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for NB-IoT
    [00:00:13.392,822] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,4,"0001"
    [00:00:13.393,310] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.393,707] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,4,"0001"
    [00:00:13.397,247] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.399,810] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.400,238] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.400,756] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,5,"0001"
    [00:00:13.406,829] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.407,257] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,5,"0001"
    [00:00:13.413,940] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.416,198] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.416,625] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.417,114] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.417,663] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.418,121] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.434,143] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:00:13.440,826] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.446,228] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.446,655] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.447,113] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:00:13.447,540] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.447,967] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:00:13.452,423] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.454,589] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.455,017] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.455,474] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:00:13.455,902] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.461,944] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:00:13.468,627] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.470,794] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.471,191] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.471,679] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=1
    [00:00:13.472,137] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.472,534] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
    [00:00:13.476,989] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:13.535,522] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:13.535,949] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:13.536,407] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:13.536,834] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.555,664] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 11 bytes, %XSIM: 1
    
    [00:00:14.557,403] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.558,410] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.559,448] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, %CESQ: 64,3,9,1
    
    [00:00:14.561,401] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.561,828] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.562,286] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 2,"767C","07F0E208",7,0,0,"11100000","11100000"
    
    [00:00:14.562,866] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"767C","07F0E208",7,0,0,"11100000","11100000"
    
    [00:00:14.563,690] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    [00:00:14.564,147] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:14.564,636] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.593,017] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.593,475] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 19 bytes, %CESQ: 65,3,19,2
    
    [00:00:14.593,963] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.594,390] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:14.594,818] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 1
    
    [00:00:14.595,275] <dbg> lte_lc.at_handler: +CSCON notification
    [00:00:14.595,794] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:14.596,191] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:15.173,065] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 19 bytes, %CESQ: 65,3,24,3
    
    [00:00:15.173,553] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:15.173,980] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:16.501,312] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 18 bytes, +CNEC_ESM: 50,0
    
    [00:00:16.501,800] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:16.502,227] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:16.502,655] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 56 bytes, +CEREG: 5,"767C","07F0E208",7,,,"11100000","11100000"
    
    [00:00:16.503,265] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"767C","07F0E208",7,,,"11100000","11100000"
    
    [00:00:16.504,028] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 5
    [00:00:16.504,486] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:16.504,882] <dbg> lte_lc_helpers.parse_psm: TAU: -1 sec, active time: -1 sec
    
    [00:00:16.505,432] <wrn> app: Connected ! Checking eDRX value
    [00:00:16.505,828] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:16.506,256] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:16.521,575] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 16 bytes, +CNEC_EMM: 13
    
    [00:00:16.522,064] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:16.522,491] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:17.907,073] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 0
    
    [00:00:17.908,203] <dbg> lte_lc.at_handler: +CSCON notification
    [00:00:17.908,691] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:17.909,118] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:17.937,713] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 21 bytes, %CESQ: 255,0,255,0
    
    [00:00:17.968,414] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:17.968,841] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:17.969,299] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 59 bytes, +CEREG: 2,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:17.970,550] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:17.971,374] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    [00:00:17.971,832] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:17.972,290] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:17.972,717] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:18.506,835] <dbg> at_cmd.at_write: Sending command AT+CEDRXRDP
    [00:00:18.507,415] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXRDP
    [00:00:18.509,796] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEDRXRDP: 4,"0001","",""
    OK
    
    [00:00:18.510,620] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:18.511,108] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:18.511,535] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:20.511,138] <dbg> at_cmd.at_write: Sending command AT+CEDRXRDP
    [00:00:20.511,718] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXRDP
    [00:00:20.518,432] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEDRXRDP: 4,"0001","",""
    OK
    
    [00:00:20.518,920] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:20.519,378] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:20.519,805] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.519,439] <dbg> at_cmd.at_write: Sending command AT+CEDRXRDP
    [00:00:22.526,153] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXRDP
    [00:00:22.529,174] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 32 bytes, +CEDRXRDP: 4,"0001","",""
    OK
    
    [00:00:22.529,663] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:22.530,120] <wrn> app: ====Test 0 done. Starting next one in 10 seconds====
    [00:00:22.530,609] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=0
    [00:00:22.531,036] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.531,463] <dbg> at_cmd.at_write: Sending command AT+CFUN=0
    [00:00:22.535,369] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.564,544] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 59 bytes, +CEREG: 0,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:22.565,795] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0,"FFFE","FFFFFFFF",7,0,13,"11100000","11100000"
    
    [00:00:22.566,619] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 0
    [00:00:22.567,077] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:00:22.567,535] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.567,962] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.653,198] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 11 bytes, %XSIM: 0
    
    [00:00:22.653,656] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.654,083] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:22.716,918] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:22.717,346] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:22.717,834] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:22.718,231] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:32.717,834] <wrn> app: ====Starting test 1 in 3 seconds=====
    [00:00:32.718,261] <wrn> app: Mode: 2, edrx: 1, ltem: 0001, nbiot: 0001
    [00:00:32.718,688] <wrn> app: ====Registering %XSIM urc====
    [00:00:32.719,055] <dbg> at_cmd.at_write: Sending command AT%XSIM=1
    [00:00:32.725,738] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSIM=1
    [00:00:32.729,614] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:32.730,010] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:32.730,468] <wrn> app: ====Registering %CESQ urc====
    [00:00:32.730,834] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%CESQ=1
    [00:00:32.731,292] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:32.731,689] <dbg> at_cmd.at_write: Sending command AT%CESQ=1
    [00:00:32.735,809] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:32.737,976] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:32.738,372] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:32.738,830] <wrn> app: ====Registering %MDEV urc====
    [00:00:32.739,196] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%MDEV=1
    [00:00:32.739,654] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:32.750,671] <dbg> at_cmd.at_write: Sending command AT%MDEV=1
    [00:00:32.757,324] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:32.759,307] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 8 bytes, ERROR
    
    [00:00:32.759,735] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:32.760,192] <wrn> app: ====Registering +CMEE urc====
    [00:00:32.760,559] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CMEE=1
    [00:00:32.760,986] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:32.761,413] <dbg> at_cmd.at_write: Sending command AT+CMEE=1
    [00:00:32.765,502] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:32.767,669] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:32.768,066] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:32.768,524] <wrn> app: ====Registering +CNEC urc====
    [00:00:32.774,536] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CNEC=24
    [00:00:32.774,963] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:32.775,390] <dbg> at_cmd.at_write: Sending command AT+CNEC=24
    [00:00:32.782,073] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:32.784,240] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:32.784,667] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:32.785,125] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:32.785,552] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.785,186] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.785,736] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.792,419] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.797,851] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.798,248] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.798,736] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS=
    [00:00:35.799,163] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.799,560] <dbg> at_cmd.at_write: Sending command AT+CPSMS=
    [00:00:35.804,046] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.806,488] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.806,915] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.807,373] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for LTE-M
    [00:00:35.807,800] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for NB-IoT
    [00:00:35.808,288] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,4,"0001"
    [00:00:35.814,392] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.814,819] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,4,"0001"
    [00:00:35.821,502] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.823,760] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.824,188] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.824,707] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,5,"0001"
    [00:00:35.830,780] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.831,207] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,5,"0001"
    [00:00:35.837,890] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.840,454] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.840,881] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.841,369] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.841,918] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.842,376] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.842,803] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=0,1,0,0
    [00:00:35.846,649] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.852,081] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.852,508] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.852,966] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:00:35.853,393] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.859,436] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:00:35.866,119] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.868,286] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.868,682] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.869,171] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:00:35.869,598] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.870,025] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:00:35.874,481] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.876,647] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.887,664] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.888,153] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=1
    [00:00:35.888,580] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.889,007] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
    [00:00:35.895,660] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:35.955,535] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:00:35.955,963] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:00:35.956,420] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:35.956,848] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:00:36.895,690] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 11 bytes, %XSIM: 1
    
    [00:00:36.896,179] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:00:36.896,575] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:05.956,451] <inf> lte_lc: Network connection attempt timed out
    [00:02:05.956,848] <err> app: Test 1 fails: no connection
    [00:02:05.957,214] <wrn> app: ====Test 1 done. Starting next one in 10 seconds====
    [00:02:05.957,672] <dbg> at_cmd.at_write: Sending command AT+CFUN=0
    [00:02:05.958,251] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=0
    [00:02:06.020,172] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 0,"FFFE","FFFFFFFF",9,0,0,"11100000","11100000"
    
    [00:02:06.020,751] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0,"FFFE","FFFFFFFF",9,0,0,"11100000","11100000"
    
    [00:02:06.021,545] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 0
    [00:02:06.022,003] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    [00:02:06.022,491] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:06.022,918] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:06.023,345] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 11 bytes, %XSIM: 0
    
    [00:02:06.023,834] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:06.024,230] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:07.282,104] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:07.282,531] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:07.282,989] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:07.283,416] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:17.283,020] <wrn> app: ====Using SIM 1====
    [00:02:17.283,386] <wrn> app: ====Starting test 0 in 3 seconds=====
    [00:02:17.283,782] <wrn> app: Mode: 1, edrx: 1, ltem: 0001, nbiot: 0001
    [00:02:17.284,210] <wrn> app: ====Registering %XSIM urc====
    [00:02:17.284,576] <dbg> at_cmd.at_write: Sending command AT%XSIM=1
    [00:02:17.291,259] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSIM=1
    [00:02:17.293,853] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:17.294,281] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:17.294,708] <wrn> app: ====Registering %CESQ urc====
    [00:02:17.295,104] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%CESQ=1
    [00:02:17.295,532] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:17.295,959] <dbg> at_cmd.at_write: Sending command AT%CESQ=1
    [00:02:17.300,048] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:17.302,215] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:17.302,612] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:17.303,070] <wrn> app: ====Registering %MDEV urc====
    [00:02:17.303,466] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%MDEV=1
    [00:02:17.303,894] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:17.314,910] <dbg> at_cmd.at_write: Sending command AT%MDEV=1
    [00:02:17.321,563] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:17.323,547] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 8 bytes, ERROR
    
    [00:02:17.323,974] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:17.324,401] <wrn> app: ====Registering +CMEE urc====
    [00:02:17.324,798] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CMEE=1
    [00:02:17.325,225] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:17.325,653] <dbg> at_cmd.at_write: Sending command AT+CMEE=1
    [00:02:17.329,742] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:17.331,909] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:17.332,336] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:17.332,763] <wrn> app: ====Registering +CNEC urc====
    [00:02:17.343,750] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CNEC=24
    [00:02:17.344,177] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:17.344,604] <dbg> at_cmd.at_write: Sending command AT+CNEC=24
    [00:02:17.351,257] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:17.353,424] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:17.353,820] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:17.354,309] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:17.354,736] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.354,370] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:02:20.354,919] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:02:20.361,602] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:02:20.367,034] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.367,431] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.367,889] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CPSMS=
    [00:02:20.368,347] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.368,743] <dbg> at_cmd.at_write: Sending command AT+CPSMS=
    [00:02:20.373,229] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.375,671] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.376,098] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.376,556] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for LTE-M
    [00:02:20.376,983] <dbg> lte_lc.lte_lc_edrx_param_set: eDRX set to 0001 for NB-IoT
    [00:02:20.377,502] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,4,"0001"
    [00:02:20.377,960] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.378,387] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,4,"0001"
    [00:02:20.381,896] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.384,460] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.384,887] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.385,406] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEDRXS=2,5,"0001"
    [00:02:20.391,479] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.391,906] <dbg> at_cmd.at_write: Sending command AT+CEDRXS=2,5,"0001"
    [00:02:20.398,590] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.400,848] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.401,275] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.401,763] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    [00:02:20.402,313] <dbg> at_cmd.at_cmd_write: Awaiting response for AT%XSYSTEMMODE=1,0,0,0
    [00:02:20.402,801] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.408,843] <dbg> at_cmd.at_write: Sending command AT%XSYSTEMMODE=1,0,0,0
    [00:02:20.415,527] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.420,989] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.421,417] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.421,875] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CEREG=5
    [00:02:20.422,332] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.422,729] <dbg> at_cmd.at_write: Sending command AT+CEREG=5
    [00:02:20.427,215] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.429,382] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.429,809] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.430,267] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CSCON=1
    [00:02:20.430,694] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.431,121] <dbg> at_cmd.at_write: Sending command AT+CSCON=1
    [00:02:20.435,577] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.437,744] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.438,171] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.438,659] <dbg> at_cmd.at_cmd_write: Awaiting response for AT+CFUN=1
    [00:02:20.439,086] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.439,514] <dbg> at_cmd.at_write: Sending command AT+CFUN=1
    [00:02:20.443,939] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:20.502,044] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 5 bytes, OK
    
    [00:02:20.502,471] <dbg> at_cmd.socket_thread_fn: Enqueueing response for sync call
    [00:02:20.502,929] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:20.503,356] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:23.268,188] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 11 bytes, %XSIM: 1
    
    [00:02:23.268,676] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:23.269,104] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:52.697,113] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 19 bytes, %CESQ: 54,2,14,2
    
    [00:02:52.721,343] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:52.721,771] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:52.722,198] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 58 bytes, +CEREG: 2,"07A1","00A12301",7,0,0,"11100000","11100000"
    
    [00:02:52.722,808] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"07A1","00A12301",7,0,0,"11100000","11100000"
    
    [00:02:52.723,602] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    [00:02:52.724,090] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    [00:02:52.724,548] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:52.724,975] <dbg> at_cmd.socket_thread_fn: Listening on socket
    [00:02:52.905,639] <dbg> at_cmd.socket_thread_fn: at_cmd_rx 12 bytes, +CSCON: 1
    
    [00:02:52.906,097] <dbg> lte_lc.at_handler: +CSCON notification
    [00:02:52.906,585] <dbg> at_cmd.socket_thread_fn: Writing any pending command
    [00:02:52.907,012] <dbg> at_cmd.socket_thread_fn: Listening on socket
    

  • Hi Didrik,

    I've tried to add RTT as trace output. Here is the result of my test.

    Please tell me if the traces are correctly formatted and understandable.

    If so, I'll do a pull request on sdk-nrf to add that functionality to the tree

    Regards

    Giuliano

    nrf9160_modem.zip

  • I will look more at the trace tomorrow, but yes, it seems to be valid.

    The error rate was a bit higher than normal, but I don't know how much of a problem that really is. From my quick look, it seemed like most of the information was there.

    How long did you trace? Looking at the timestamps in the trace, there is ~2 minutes of traces in the file. Is that correct?

    On a different note, that trace is from mfw 1.2.3, not mfw 1.3.0.

Reply Children
Related