Date time synchronization fails after nRF Connect SDK and modem firmware update - yet again

Dear Nordic Support Team,

After I updated the nRF Connect SDK (1.5.1 to 1.6.1) and the Modem firmware (1.2.3 to 1.3.0) on my nrf9160 DK device (v1.0.0, SiP revision 2), the date time isn't synchronized anymore. The date time library only issues the DATE_TIME_NOT_OPTAINED event. This issue might be related to this ticket.

I followed these instructions to update the modem firmware.

Here are the crucial code snippets I use:

// Modem initialization
int lmModem_initialize(const LmModemConfiguration config)
{
    int error;

    error = lte_lc_init();
    if (error) goto onError;

    error = lte_lc_psm_req(config.requestPsm);
    if (error) goto onError;

    error = lte_lc_connect();
    if (error) goto onError;

    k_sleep(K_SECONDS(5));

    return LMMODULSUCCESS;
onError:
    return LMMODULERROR;
}


int lmModem_initializeDefault(void) {
    LmModemConfiguration config;
    lmModem_getDefaultConfig(&config);
    return lmModem_initialize(config);
}


void lmModem_getDefaultConfig(LmModemConfiguration* config) {
    config->requestPsm = true;
}


// Date time initialization
// Please note that the semaphore is "given" by the eventHandler if date time is obtained
int lmDateTime_initialize(void)
{
    int error = LMMODULESUCCESS;

    // Synchronize time independed of usual update interval
    error = date_time_update_async(eventHandler);
    if (error)
    {
        printk("Data time update async request failed\n");
        goto onError;
    }

    // Wait for date time update to finish
    error = k_sem_take(&dateTimeInitialized, K_SECONDS(DATETIMEUPDATETIMEOUTS));
    if (error)
    {
        printk("Data time update time out\n");
        goto onError;
    }
    
    // Validate date time
    if (!date_time_is_valid())
    {
        printk("Data time is not valid\n");
        goto onError;
    }

    return LMMODULESUCCESS;
onError:
    return LMMODULEERROR;
}


// Try to initialize the modem and then the date time
void lmControlProtoApp_initialize(void) {
    int error;

    printk("Initialize modem\n");
    error = lmModem_initializeDefault();
    printk("Init of modem error: %d\n", error);

    printk("Initialize date time\n");
    error = lmDateTime_initialize();
    printk("Init of date time error: %d\n", error);
}

This is my prj.conf:

# Physical interface
#==============================================================================
CONFIG_GPIO=y
CONFIG_SERIAL=y



# UART (depends on SERIAL)
#==============================================================================
CONFIG_UART_ASYNC_API=y



# Include reboot functionality
#==============================================================================
CONFIG_REBOOT=y



# Logging
#==============================================================================
CONFIG_LOG=y
CONFIG_LOG_MODE_IMMEDIATE=n
CONFIG_LOG_MODE_OVERFLOW=y
CONFIG_LOG_PROCESS_THREAD=n
CONFIG_LOG_DEFAULT_LEVEL=2
CONFIG_LOG_BUFFER_SIZE=1024
CONFIG_LOG_STRDUP_BUF_COUNT=16



# nrf modem library
#==============================================================================
CONFIG_NRF_MODEM_LIB=y



# Nordics date time library (depends on NRF_MODEM_LIB)
#==============================================================================
CONFIG_DATE_TIME=y
CONFIG_DATE_TIME_UPDATE_INTERVAL_SECONDS=3600



# Nordics BSD socket api and dependencies
#==============================================================================
CONFIG_BSD_LIBRARY=y
CONFIG_BSD_LIBRARY_SYS_INIT=y
CONFIG_NETWORKING=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y



# Modem and lte configuration (depends on BSD_LIBRARY)
#==============================================================================
CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_NETWORK_MODE_LTE_M=y
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n

# PSM timer parameters requested from the network provider
# CONFIG_LTE_PSM_REQ_RPTAU="00000110"
# CONFIG_LTE_PSM_REQ_RAT="00000010"



# Memory size
#==============================================================================
CONFIG_MAIN_STACK_SIZE=16384
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=8192
CONFIG_HEAP_MEM_POOL_SIZE=16384



# Newlib support (provides some std c library functions)
#==============================================================================
CONFIG_NEWLIB_LIBC=y
CONFIG_NEWLIB_LIBC_NANO=n
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y
CONFIG_NEWLIB_LIBC_FLOAT_SCANF=y



# Use external cJson library (depends on NEWLIB_LIBC, NEWLIB_LIBC_FLOAT_PRINTF)
#==============================================================================
CONFIG_CJSON_LIB=y

Please note that I have a second, older device (v0.9.0, SiP revision 1) which still holds the old modem firmware version 1.2.3. The very same code (compiled with the 1.6.1 SDK as well) runs flawless on this device.

Can you please tell me what causes the issue? Since this is the second time my v1.0.0 device shows issue with the date time synchronization after a modem firmware update and no one else seems to have reported similar issues, do you think my hardware might be broken?

Thank you for you help!

Sebastian

  • Hello,

    can you try adding

    CONFIG_LOG=y

    CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=y

    CONFIG_DATE_TIME_LOG_LEVEL_DBG=y

    to get more information from the logging? Then you can reproduce the issue and post the full log.

  • Hi Hakon,

    thank you for the reply. Out of curiosity I have reproduced the issue several times to see if the error picture changes. It does slightly. I have attached two files: failedDateTime1.log and failedDateTime2.log.

    Please not the lines around the string: "Init of modem error:"  in both files. In both scenarios it looks to me like the modem seems to be the problem. However in the try of failedDateTime1.log the function lte_lc_connect() returns an error code but it does not in the try of failedDateTime2.log.

    *** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
    
    I am running!
    
    Initialize modem
    
    [00:00:00.221,740] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode                                                                                                                                                : AT%XSYSTEMMODE=1,0,0,0
    
    [00:00:00.229,644] <dbg> lte_lc.init_and_config: System mode (1) and preference (0) configure                                                                                                                                                d
    
    [00:00:00.231,323] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode                                                                                                                                                : AT%XSYSTEMMODE=1,0,0,0
    
    [00:00:07.512,359] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0BF4","01914E01",                                                                                                                                                7
    
    
    
    [00:00:07.512,542] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:07.512,573] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:07.555,694] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:07.816,497] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0BF4","01914E01",                                                                                                                                                7,0,15
    
    
    
    [00:00:07.816,680] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:07.816,711] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:09.065,155] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:09.083,679] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:00:09.083,801] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:09.083,801] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:00:09.122,375] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",                                                                                                                                                7
    
    
    
    [00:00:09.122,558] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:09.122,558] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:09.502,471] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:12.915,985] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",                                                                                                                                                7,0,17
    
    
    
    [00:00:12.916,168] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:12.916,198] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:14.167,938] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:23.003,112] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:26.511,016] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",                                                                                                                                                7,0,15
    
    
    
    [00:00:26.511,199] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:26.511,230] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:27.759,613] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:27.777,160] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:00:27.777,252] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:27.777,252] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:00:37.034,851] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0FAC","01C69C01",                                                                                                                                                7
    
    
    
    [00:00:37.035,034] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:37.035,064] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:37.194,061] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:37.543,029] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0FAC","01C69C01",                                                                                                                                                7,0,17
    
    
    
    [00:00:37.543,212] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:37.543,243] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:38.795,318] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:47.627,593] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:52.062,957] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:01:00.898,223] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:01:04.095,092] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0FAC","01C69C01",                                                                                                                                                7,0,15
    
    
    
    [00:01:04.095,306] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:01:04.095,306] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:01:05.344,604] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:01:05.446,411] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:01:05.446,533] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:01:05.446,533] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:03:04.381,042] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7
    
    
    
    [00:03:04.381,225] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:03:04.381,256] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:03:04.614,990] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:03:04.915,802] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7,0,17
    
    
    
    [00:03:04.915,985] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:03:04.916,015] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:03:06.167,236] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:03:33.841,369] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:03:35.379,150] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:03:44.231,903] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:03:45.782,135] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:03:54.616,394] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:03:56.157,623] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:04.986,877] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:09.397,277] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:09.446,838] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7
    
    
    
    [00:04:09.447,021] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:04:09.447,021] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:04:09.477,081] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:12.975,982] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7,0,17
    
    
    
    [00:04:12.976,196] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:04:12.976,196] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:04:14.227,478] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:23.057,739] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:27.882,141] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:36.718,383] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:47.247,070] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:04:56.079,315] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:05:00.863,250] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:05:09.699,981] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:05:14.574,401] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:05:14.725,097] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:05:14.725,189] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:05:14.725,189] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:06:50.392,486] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7
    
    
    
    [00:06:50.392,669] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:06:50.392,669] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:06:50.552,764] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:06:50.818,725] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7,0,17
    
    
    
    [00:06:50.818,908] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:06:50.818,939] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:06:52.071,014] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:00.905,273] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:05.377,685] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:14.205,932] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:15.713,165] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:24.546,417] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:27.744,262] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7,0,15
    
    
    
    [00:07:27.744,476] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:07:27.744,506] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:07:28.993,804] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:29.104,461] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:07:29.104,553] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:07:29.104,553] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:07:29.166,290] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7
    
    
    
    [00:07:29.166,473] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:07:29.166,473] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:07:29.216,613] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:29.815,368] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7,0,17
    
    
    
    [00:07:29.815,551] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:07:29.815,582] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:07:31.066,894] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:39.915,130] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:43.495,971] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",                                                                                                                                                7,0,15
    
    
    
    [00:07:43.496,185] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:07:43.496,215] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:07:44.745,574] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:07:44.798,156] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:07:44.798,248] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:07:44.798,248] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:10:00.263,275] <inf> lte_lc: Network connection attempt timed out
    
    [00:10:00.297,393] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 0
    
    
    
    [00:10:00.297,485] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 0
    
    [00:10:00.297,485] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:10:00.324,249] <inf> lte_lc: Using fallback network mode
    
    [00:10:00.324,279] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode                                                                                                                                                : AT%XSYSTEMMODE=0,1,0,0
    
    [00:10:36.203,277] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"05B1","009CFA65",                                                                                                                                                9
    
    
    
    [00:10:36.203,460] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:10:36.203,491] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:10:37.217,864] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:10:38.394,775] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"05B1","009CFA65",                                                                                                                                                9,0,111
    
    
    
    [00:10:38.394,989] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:10:38.395,019] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:10:39.998,901] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:10:42.438,232] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"05B1","009DC865",                                                                                                                                                9
    
    
    
    [00:10:42.438,415] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:10:42.438,446] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:10:42.772,979] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"DB1A","01B2FE07",                                                                                                                                                9
    
    
    
    [00:10:42.773,162] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:10:42.773,162] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:10:59.133,758] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:10:59.617,431] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"DB1A","01B2FE07",                                                                                                                                                9,0,15
    
    
    
    [00:10:59.617,614] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:10:59.617,645] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:10:59.679,748] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:11:00.006,805] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:11:00.006,896] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:11:00.006,927] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:11:02.917,755] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B3AB","00C4D366",                                                                                                                                                9
    
    
    
    [00:11:02.917,938] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:11:02.917,938] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:11:03.436,370] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:11:03.599,395] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B3AB","00C4D366",                                                                                                                                                9,0,15
    
    
    
    [00:11:03.599,578] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:11:03.599,609] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:11:03.657,775] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:11:04.009,094] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:11:04.009,185] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:11:04.009,216] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    [00:15:01.006,408] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"05B1","009DC865",                                                                                                                                                9
    
    
    
    [00:15:01.006,591] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:15:01.006,622] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:15:01.763,061] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:15:03.021,850] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"05B1","009DC865",                                                                                                                                                9,0,111
    
    
    
    [00:15:03.022,033] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:15:03.022,064] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 9
    
    [00:15:04.621,948] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:15:05.297,424] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:15:05.297,515] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:15:05.297,546] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    Init of modem error: 1
    
    Initialize date time
    
    [00:20:00.349,853] <inf> lte_lc: Network connection attempt timed out
    
    [00:20:00.353,759] <dbg> date_time.new_date_time_get: Updating date time UTC...
    
    [00:20:00.353,759] <dbg> date_time.current_time_check: Date time never set
    
    [00:20:00.353,790] <dbg> date_time.new_date_time_get: Current time not valid
    
    [00:20:00.353,790] <dbg> date_time.new_date_time_get: Fallback on NTP server
    
    [00:20:00.362,426] <wrn> date_time: getaddrinfo, error: -11
    
    [00:20:00.362,426] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server ntp.                                                                                                                                                uio.no, error -11
    
    [00:20:00.362,426] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:20:00.362,731] <wrn> date_time: getaddrinfo, error: -11
    
    [00:20:00.362,731] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time                                                                                                                                                1.google.com, error -11
    
    [00:20:00.362,762] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:20:00.450,744] <wrn> date_time: getaddrinfo, error: -11
    
    [00:20:00.450,744] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time                                                                                                                                                2.google.com, error -11
    
    [00:20:00.450,775] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:20:00.451,171] <wrn> date_time: getaddrinfo, error: -11
    
    [00:20:00.451,171] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time                                                                                                                                                3.google.com, error -11
    
    [00:20:00.451,171] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:20:00.451,385] <wrn> date_time: getaddrinfo, error: -11
    
    [00:20:00.451,385] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time                                                                                                                                                4.google.com, error -11
    
    [00:20:00.451,385] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:20:00.451,385] <wrn> date_time: Not getting time from any NTP server
    
    [00:20:00.451,416] <dbg> date_time.new_date_time_get: Not getting time from NTP server
    
    [00:20:00.451,416] <dbg> date_time.new_date_time_get: Fallback on cellular network time
    
    DATE_TIME_NOT_OBTAINED
    
    [00:20:00.552,825] <dbg> date_time.time_modem_get: Could not get cellular network time, error                                                                                                                                                : -8
    
    [00:20:00.552,856] <dbg> date_time.new_date_time_get: Not getting cellular network time
    
    [00:20:00.552,856] <dbg> date_time.new_date_time_get: Not getting time from any time source
    
    Data time update time out
    
    Init of date time error: 1
    
    Init uart with label UART_1 success
    
    Init uart with label UART_2 success
    
    I am returning!

    *** Booting Zephyr OS build v2.6.0-rc1-ncs1  ***
    
    I am running!
    
    Initialize modem
    
    [00:00:00.215,606] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    
    [00:00:00.223,510] <dbg> lte_lc.init_and_config: System mode (1) and preference (0) configured
    
    [00:00:00.225,189] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=1,0,0,0
    
    [00:00:06.009,033] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",7
    
    
    
    [00:00:06.009,216] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:06.009,216] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:06.156,188] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:09.865,173] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"B293","00C4D302",7,,,"00011110","1~
    
    [00:00:09.865,417] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 5
    
    [00:00:09.865,447] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:09.865,478] <dbg> lte_lc_helpers.parse_psm: TAU: -1 sec, active time: 60 sec
    
    
    [00:00:09.940,856] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",7
    
    
    
    [00:00:09.941,040] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:09.941,040] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:11.278,472] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:11.349,273] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2
    
    
    
    [00:00:11.349,365] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:11.349,395] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22
    
    Init of modem error: 0
    
    Initialize date time
    
    [00:00:13.986,389] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",7
    
    
    
    [00:00:13.986,541] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 2
    
    [00:00:13.986,572] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:14.039,703] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:14.869,537] <dbg> date_time.new_date_time_get: Updating date time UTC...
    
    [00:00:14.869,537] <dbg> date_time.current_time_check: Date time never set
    
    [00:00:14.869,537] <dbg> date_time.new_date_time_get: Current time not valid
    
    [00:00:14.869,537] <dbg> date_time.new_date_time_get: Fallback on NTP server
    
    [00:00:14.869,781] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:14.869,781] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server ntp.uio.no, error -11
    
    [00:00:14.869,781] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:00:14.955,718] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:14.955,718] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time1.google.com, error -11
    
    [00:00:14.955,749] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:00:14.955,932] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:14.955,963] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time2.google.com, error -11
    
    [00:00:14.955,963] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:00:14.956,176] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:14.956,176] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time3.google.com, error -11
    
    [00:00:14.956,176] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:00:14.956,481] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:14.956,512] <dbg> date_time.time_NTP_server_get: Not getting time from NTP server time4.google.com, error -11
    
    [00:00:14.956,512] <dbg> date_time.time_NTP_server_get: Trying another address...
    
    [00:00:14.956,512] <wrn> date_time: Not getting time from any NTP server
    
    [00:00:14.956,512] <dbg> date_time.new_date_time_get: Not getting time from NTP server
    
    [00:00:14.956,512] <dbg> date_time.new_date_time_get: Fallback on cellular network time
    
    DATE_TIME_NOT_OBTAINED
    
    [00:00:15.083,221] <dbg> date_time.time_modem_get: Could not get cellular network time, error: -8
    
    [00:00:15.083,251] <dbg> date_time.new_date_time_get: Not getting cellular network time
    
    [00:00:15.083,251] <dbg> date_time.new_date_time_get: Not getting time from any time source
    
    [00:00:17.506,225] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"94B4","0190CE00",7,,,"00100001","0~
    
    [00:00:17.506,439] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 5
    
    [00:00:17.506,469] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:17.506,500] <dbg> lte_lc_helpers.parse_psm: TAU: 3600 sec, active time: 60 sec
    
    
    Data time update time out
    
    Init of date time error: 1
    
    Init uart with label UART_1 success
    
    Init uart with label UART_2 success
    
    I am returning!
    
    
    [00:00:28.356,475] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:30.406,555] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"0BF4","01914E01",7,,,"00100001","0~
    
    [00:00:30.406,799] <dbg> lte_lc_helpers.parse_cereg: Network registration status: 5
    
    [00:00:30.406,829] <dbg> lte_lc_helpers.parse_cereg: LTE mode: 7
    
    [00:00:30.406,860] <dbg> lte_lc_helpers.parse_psm: TAU: 3600 sec, active time: 60 sec
    
    
    [00:00:30.450,653] <dbg> lte_lc.at_handler: +CSCON notification
    
    [00:00:31.844,024] <dbg> lte_lc.at_handler: +CSCON notification

  • Hi,

    Håkon is currently on vacation, so I have taken over this ticket.

    Based on your logs, it doesn't look like the problem is in the date_time library, but in your network connection.

    In both logs, you are not connected to a network when the date_time library tries to get the time.

    In the first log, you never get connected to the network, but get reject causes 17 and 15. These point to a problem in the network, or your SIM card/subscription. I recommend you contact your SIM card provider, and ask them for help.

    In the second log, you do get connected, but then the modem is reporting that it is searching for a network again right after. The log shows that you do get connected again after date_time has failed, but that is of course too late.

    I would expect that the two behaviours are related, so contacting your SIM card provider is probably the best first step.

    Best regards,

    Didrik

  • Hi Didrik,

    thank you for taking over.

    As I have mentioned, I have two nrf9160 DKs one of v1.0.0 and and one of v0.9.0. So far only the v1.0.0 device showed the mentioned issue. However, after I read your post, I swapped the SIM cards. Now, the v1.0.0 works like a charm and the v0.9.0 device has issues connecting to the network. Thus, your suspicions that the issue at hand is neither related to the version of the DK nor to the new modem firmware but to the SIM card seems to be correct indeed.

    If its ok with you, I would like to ask a few more questions.

    In the field I would like the device to ensure a stable network connection, to recover from a connection loss, or at least to write some debug information into a log file.

    • In the light of the current issue, how would you suggest to establish and validate a network connection? Since lte_lc_connect() returns without an error in the second scenario, I cannot solely rely on this return value to ensure a stable connection.
    • Is it possible to query some meta information from the modem which might tell me things like the current connection status, signal strength, the number of failed connection attempts after the last successful connection, the frequency of connection losses etc?
    • How would I recover from a connection loss? Do I just call lte_lc_connect() over and over again until a connection is established?

    Can you please help me to understand the logs in the log files I have provided (or point at the documentation) so that I can debug such issues myself in the future?

    Thank you allot for your effort!

  • Sebastian Stein said:
    Can you please help me to understand the logs in the log files I have provided (or point at the documentation) so that I can debug such issues myself in the future?

    Here is a very quick run through of the log files as I see them. Moste of the lines are not really that :

    1:

    It starts standard stuff, the first really interresting line is

    [00:00:07.512,359] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0BF4","01914E01",7

    Here, we see that the modem is trying to connect to a cell.

    [00:00:07.816,497] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"0BF4","01914E01",7,0,15

    Here we see the result of the connection attempt, rejected with EMM reject cause 15.

    [00:00:09.083,679] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2

    This line is a bit weird. I would expect the TAC, CID, and AcT be listed here as well.

    [00:00:09.083,801] <dbg> lte_lc_helpers.parse_cereg: LTE mode not found, error code: -22

    And, it is the cause of this error.

    [00:00:09.122,375] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",7

    Here it finds a new cell.

    [00:00:12.915,985] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",7,0,17

    And gets rejected with cause 17.

    The log is then more of the same, until

    [00:10:00.324,249] <inf> lte_lc: Using fallback network mode

    At this point, the LTE link control library has given up finding a network on LTE-M, and tries NB-IoT instead. It is not able to connect to any NB-IoT networks either, so it returns an error:

    Init of modem error: 1

    [00:20:00.349,853] <inf> lte_lc: Network connection attempt timed out

    (these two lines should be in the opposite order, but the logging is deferred, while printk is done in-place)

    Then it starts to fetch the time:

    [00:20:00.353,759] <dbg> date_time.new_date_time_get: Updating date time UTC...

    [00:20:00.353,759] <dbg> date_time.current_time_check: Date time never set

    It doesn't have one already.

    [00:20:00.362,426] <wrn> date_time: getaddrinfo, error: -11

    The DNS lookup on the NTP server fails, because we are not connected to the network (-11 from getaddrinfo is EAI_SYSTEM, which tells us that the actual error code is in errno. So there can be many causes, and it is not the most helpful)

    [00:20:00.362,426] <dbg> date_time.time_NTP_server_get: Trying another address...

    The date_time library knows of several NTP servers, so it tries the other ones. As expected, they all fail in the same way.

    [00:20:00.451,416] <dbg> date_time.new_date_time_get: Fallback on cellular network time

    A final attempt to get the time.
    [00:20:00.552,825] <dbg> date_time.time_modem_get: Could not get cellular network time, error: -8

    As we are not connected to a network, this also fails.

    2:

    A lot will be similar, so this will be a bit shorter.

    [00:00:09.865,173] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"B293","00C4D302",7,,,"00011110","1~

    Again, the output is a bit weird, but here we are connected to the network.

    [00:00:09.940,856] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"B293","00C4D302",7

    And here, we have lost the connection, and are trying to get it back.

    Init of modem error: 0

    Because we were connected, lte_lc_connect returns successfully.

    Initialize date time

    [00:00:13.986,389] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"94B4","0190CE00",7

    We still haven't regained the connection

    DATE_TIME_NOT_OBTAINED

    So we are not able to get the time.

    [00:00:17.506,225] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"94B4","0190CE00",7,,,"00100001","0~

    Here, the connection is regained.

    Sebastian Stein said:
    In the light of the current issue, how would you suggest to establish and validate a network connection? Since lte_lc_connect() returns without an error in the second scenario, I cannot solely rely on this return value to ensure a stable connection.

    The lte_lc library lets you register an event handler, which will be called whenever the modem sends a +CEREG update (amongst other things). You can use those events to track the status of your network connection.

    Sebastian Stein said:
    Is it possible to query some meta information from the modem which might tell me things like the current connection status, signal strength, the number of failed connection attempts after the last successful connection, the frequency of connection losses etc?

    There are many AT commands that give you useful information. You can see the current list here.

    But most of the useful parameters has been gathered in the %XMONITOR command.

    Sebastian Stein said:
    How would I recover from a connection loss? Do I just call lte_lc_connect() over and over again until a connection is established?

    The modem will automatically try to reconnect, so you shouldn't need to do anything.

Related