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

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

Dear Nordic Support Team,

After I updated the nRF Connect SDK (1.4.0 to 1.5.1) and the Modem firmware (1.2.2 to 1.2.3) on my nrf9160 DK devices, the date time isn't synchronized anymore.

After the modem successfully connects to the LTE network (lte_lc_psm_req(.) and lte_lc_init_and_connect() return 0), I initiate the date time synchronization with date_time_update_async(). I wait until date_time_is_valid() returns true. This however never happens and printing the current system time obviously shows wrong results. Please note that I used the same application code before and after the SDK and Modem firmware update (except for the new date_time_is_valid() function). Before the update, the date time synchronization was not an issue.

I flashed the Asset Tracker v2 sample onto one of my devices to tackle the problem. The sample failed and issued a reboot on the first run. In the second run, the sample worked properly and the data sent to the nRF Connect Cloud had a correct time stamp. Thereafter I again flashed my application code to the very same device on which I had the Asset Tracker v2 running. Surprisingly, now the date time synchronization was working on that device. I have a second device on which the date time synchronization still fails. I never had the Asset Tracker v2 sample running on this second device.

I would like to understand what causes this behavior and how I can get my devices to synchronize their system time again without utilizing the Asset-Tracker-v2-workaround.

Thank you very much for you help!

PS: You find my prj.conf attached.

EDIT: updated prj.conf, added dateTimeError.log, added minimalExample.c

6560.prj.conf

*** Booting Zephyr OS build v2.4.99-ncs2  ***

I am running!

Init modem

        lte_lc_psm_req returned: 0

        lte_lc_init_and_connect returned: 0

Fetch date time

        d[00:00:13.057,067] <wrn> date_time: getaddrinfo, error: -11

a[00:00:13.063,476] <wrn> date_time: getaddrinfo, error: -11

te[00:00:13.070,037] <wrn> date_time: getaddrinfo, error: -11

_[00:00:13.076,477] <wrn> date_time: getaddrinfo, error: -11

tim[00:00:13.083,068] <wrn> date_time: getaddrinfo, error: -11

[00:00:13.089,294] <wrn> date_time: Not getting time from any NTP server

e_update_async returned: 0

*** Booting Zephyr OS build v2.4.99-ncs2  ***

I am running!

Init modem

        lte_lc_psm_req returned: 0

        lte_lc_init_and_connect returned: 0

Fetch date time

        d[00:00:11.937,042] <wrn> date_time: getaddrinfo, error: -11

a[00:00:11.943,481] <wrn> date_time: getaddrinfo, error: -11

te[00:00:11.950,042] <wrn> date_time: getaddrinfo, error: -11

_[00:00:11.956,451] <wrn> date_time: getaddrinfo, error: -11

tim[00:00:11.963,043] <wrn> date_time: getaddrinfo, error: -11

[00:00:11.969,299] <wrn> date_time: Not getting time from any NTP server

e_update_async returned: 0
// Zephyr
#include <zephyr.h>

// Nordic
#include <date_time.h>
#include <modem/lte_lc.h>

// Local
#include "Hardware/lmWatchdog.h"



// Macro
//=============================================================================
//=============================================================================



// Declaration
//=============================================================================
//=============================================================================



// Interface
//=============================================================================
/**
 * @brief Directly called in main.c
 */
void lmControlProtoApp_initialize(void) {
    int error = 0;

    printk("Init modem\n");

    error = lte_lc_psm_req(true);
    printk("\tlte_lc_psm_req returned: %d\n", error);

    error = lte_lc_init_and_connect();
    printk("\tlte_lc_init_and_connect returned: %d\n", error);


    printk("Fetch date time\n");

    error = date_time_update_async(NULL);
    printk("\tdate_time_update_async returned: %d\n", error);
    
    LmWatchdog watchdog;
    lmWatchdog_initialize(&watchdog, 1000*10);
    lmWatchdog_start(&watchdog);
    while (!date_time_is_valid()) {
        k_msleep(1000);
    }
    lmWatchdog_stop(&watchdog);

    printk("Init done\n");
}


/**
 * @brief Directly called in main.c after initialize is complete
 */
void lmControlProtoApp_run(void) {
    int64_t unixStamp;
    
    while (true)
    {
        date_time_now(&unixStamp);
        printk("unix time stamp: &lld\n", unixStamp);
        k_msleep(1000*5);
    }
}
//=============================================================================



// Definition
//=============================================================================
//=============================================================================

Parents
  • Hi @Sebastian Stein. I struggle to identify the exact issue at hand. Could you provide some log output to further support your case? The date time library supports registering a handler that provides callbacks when date time has been obtained (In asset tracker v1 main.c the handler name is date_time_event_handler. I recommend depending on that with a semaphore in stead of blocking on date_time_is_valid().

  • Hi ,

    thank you for your response.

    I edited the attached files of my first post. I added the log file dateTimeError.log and a minimal example with which I am able to reproduce the issue. To generate the log messages I have set CONFIG_LOG_DEFAULT_LEVEL=4 and CONFIG_LOG_IMMEDIATE=y.

  • /**
     * @brief Directly called in main.c after initialize is complete
     */
    void lmControlProtoApp_run(void) {
        int64_t unixStamp;
    
        while (true)
        {
            date_time_now(&unixStamp);
            printk("unix time stamp: %lld\n", unixStamp);
            k_msleep(1000*5);
        }
    }
    //=============================================================================
    
    // Interface
    //=============================================================================
    /**
     * @brief Directly called in main.c
     */
    void main(void) {
        int error = 0;
    
        printk("Init modem\n");
    
        error = lte_lc_psm_req(true);
        printk("\tlte_lc_psm_req returned: %d\n", error);
    
        error = lte_lc_init_and_connect();
        printk("\tlte_lc_init_and_connect returned: %d\n", error);
    
        printk("Fetch date time\n");
    
        error = date_time_update_async(NULL);
        printk("\tdate_time_update_async returned: %d\n", error);
    
        while (!date_time_is_valid()) {
            k_msleep(1000);
        }
    
        printk("Init done\n");
    
        lmControlProtoApp_run();
    }

    Made a few changes. This works at my end. I can provide an alternative if the code above does not work using the callback handler for the date time library in combination with a semaphore:

    static K_SEM_DEFINE(date_time_sem, 0, 1);
    
    static void date_time_event_handler(const struct date_time_evt *evt)
    {
    	switch (evt->type) {
    	case DATE_TIME_OBTAINED_MODEM:
    	case DATE_TIME_OBTAINED_NTP:
    	case DATE_TIME_OBTAINED_EXT:
    		printk("Date time is obtained\n");
    		k_sem_give(&date_time_sem);
    		break;
    	case DATE_TIME_NOT_OBTAINED:
    		break;
    	default:
    		break;
    	}
    }
    
    /**
     * @brief Directly called in main.c after initialize is complete
     */
    void lmControlProtoApp_run(void) {
        int64_t unixStamp;
    
        while (true)
        {
            date_time_now(&unixStamp);
            printk("unix time stamp: %lld\n", unixStamp);
            k_msleep(1000*5);
        }
    }
    //=============================================================================
    
    // Interface
    //=============================================================================
    /**
     * @brief Directly called in main.c
     */
    void main(void) {
        int error = 0;
    
        printk("Init modem\n");
    
        error = lte_lc_psm_req(true);
        printk("\tlte_lc_psm_req returned: %d\n", error);
    
        error = lte_lc_init_and_connect();
        printk("\tlte_lc_init_and_connect returned: %d\n", error);
    
        printk("Fetch date time\n");
    
        error = date_time_update_async(date_time_event_handler);
        printk("\tdate_time_update_async returned: %d\n", error);
    
        k_sem_take(&date_time_sem, K_FOREVER);
    
        printk("Init done\n");
    
        lmControlProtoApp_run();
    }

  • Hi,

    thank you for your examples. I had let them run on my device but at my end they have exactly the same issue in synchronizing the date time. I will attach both log files at the end of this post.

    Note that I edited the second example of yours by printing a message for the DATE_TIME_NOT_OBTAINED event:

    static void date_time_event_handler(const struct date_time_evt *evt)
    {
    	switch (evt->type) {
    	case DATE_TIME_OBTAINED_MODEM:
    	case DATE_TIME_OBTAINED_NTP:
    	case DATE_TIME_OBTAINED_EXT:
    		printk("Date time is obtained\n");
    		k_sem_give(&date_time_sem);
    		break;
    	case DATE_TIME_NOT_OBTAINED:
    		printk("Date time was NOT obtained");
    	default:
    		break;
    	}
    }

    As I mentioned in my initial post, I had the exactly same problem with another device and it was miraculously solved after I flashed the Asset Tracker v2 sample. But I am a little reluctant to do the same thing with this device because then, I will not be able to reproduce the error at hand anymore.

    The log messages seem to indicate that the url of the ntp server cannot be resolved. Does the Asset Tracker v2 sample change some persistent modem settings in this regard?

    Log of first example:

    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    Init modem
    
            lte_lc_psm_req returned: 0
    
            lte_lc_init_and_connect returned: 0
    
    Fetch date time
    
            [00:00:12.649,749] <wrn> date_time: getaddrinfo, error: -11
    
    d[00:00:12.656,188] <wrn> date_time: getaddrinfo, error: -11
    
    at[00:00:12.662,719] <wrn> date_time: getaddrinfo, error: -11
    
    e[00:00:12.669,189] <wrn> date_time: getaddrinfo, error: -11
    
    _t[00:00:12.675,750] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:12.682,006] <wrn> date_time: Not getting time from any NTP server
    
    ime_update_async returned: 0
    

    Log of second example (with semaphore):

    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    Init modem
    
            lte_lc_psm_req returned: 0
    
            lte_lc_init_and_connect returned: 0
    
    Fetch date time
    
            [00:00:13.105,163] <wrn> date_time: getaddrinfo, error: -11
    
    d[00:00:13.111,572] <wrn> date_time: getaddrinfo, error: -11
    
    at[00:00:13.118,133] <wrn> date_time: getaddrinfo, error: -11
    
    e[00:00:13.124,572] <wrn> date_time: getaddrinfo, error: -11
    
    _ti[00:00:13.131,164] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:13.137,390] <wrn> date_time: Not getting time from any NTP server
    
    me_update_async returned: 0
    
    Date time was NOT obtained
    

  • Hello, I'll be taking care of this case as Simen has other issues to attend to. I tried to reproduce the issue as well, but it doesn't run in to any errors. Have you made sure your SIM card is activated on your device?

  • Hi Hakon,

    thanks for taken over.

    Yes, my SIM card is registered and has plenty of data volume left. The date time synchronization did also worked in the past. Only since the two updates, I mentioned in my initial post, seems something  to be amiss.

    Since I needed to proceed with my project, I flashed the Asset Tracker v2 sample to the last device which had the issue. As with my other device, the date time synchronization seems to work again since then. The consequence is that now, I too don't have a device any more with which I can reproduce the mentioned behavior.

    However, I logged the output of the Asset Tracker v2 sample. Like I mentioned in my first post, the first run failed and the second run (after a cold reboot) succeeded. Unfortunately the log file of the second run isn't compete since I wasn't fast enough to reconnect my terminal to the device after the reboot.

    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    I: Starting bootloader
    
    I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
    
    I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
    
    I: Boot source: none
    
    I: Swap type: none
    
    I: Bootloader chainload address offset: 0x10000
    
    I: Jumping to the first image slot
    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    Flash regions           Domain          Permissions
    
    00 02 0x00000 0x18000   Secure          rwxl
    
    03 31 0x18000 0x100000  Non-Secure      rwxl
    
    
    
    Non-secure callable region 0 placed in flash region 2 with size 32.
    
    
    
    SRAM region             Domain          Permissions
    
    00 07 0x00000 0x10000   Secure          rwxl
    
    08 31 0x10000 0x40000   Non-Secure      rwxl
    
    
    
    Peripheral              Domain          Status
    
    00 NRF_P0               Non-Secure      OK
    
    01 NRF_CLOCK            Non-Secure      OK
    
    02 NRF_RTC0             Non-Secure      OK
    
    03 NRF_RTC1             Non-Secure      OK
    
    04 NRF_NVMC             Non-Secure      OK
    
    05 NRF_UARTE1           Non-Secure      OK
    
    06 NRF_UARTE2           Secure          SKIP
    
    07 NRF_TWIM2            Non-Secure      OK
    
    08 NRF_SPIM3            Non-Secure      OK
    
    09 NRF_TIMER0           Non-Secure      OK
    
    10 NRF_TIMER1           Non-Secure      OK
    
    11 NRF_TIMER2           Non-Secure      OK
    
    12 NRF_SAADC            Non-Secure      OK
    
    13 NRF_PWM0             Non-Secure      OK
    
    14 NRF_PWM1             Non-Secure      OK
    
    15 NRF_PWM2             Non-Secure      OK
    
    16 NRF_PWM3             Non-Secure      OK
    
    17 NRF_WDT              Non-Secure      OK
    
    18 NRF_IPC              Non-Secure      OK
    
    19 NRF_VMC              Non-Secure      OK
    
    20 NRF_FPU              Non-Secure      OK
    
    21 NRF_EGU1             Non-Secure      OK
    
    22 NRF_EGU2             Non-Secure      OK
    
    23 NRF_DPPIC            Non-Secure      OK
    
    24 NRF_REGULATORS       Non-Secure      OK
    
    25 NRF_GPIOTE1          Non-Secure      OK
    
    
    
    SPM: NS image at 0x1c200
    
    SPM: NS MSP at 0x200255a0
    
    SPM: NS reset vector at 0x26815
    
    SPM: prepare to jump to Non-Secure image.
    
    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    [00:00:00.206,146] <inf> asset_tracker: Asset tracker started
    
    [00:00:00.212,249] <inf> watchdog: Watchdog timeout installed. Timeout: 60000
    
    [00:00:00.219,757] <inf> watchdog: Watchdog started
    
    [00:00:00.225,067] <inf> watchdog: Watchdog feed enabled. Timeout: 30000
    
    [00:00:00.239,562] <dbg> nrf_cloud_transport.nct_client_id_get: client_id = nrf-352656106105102
    
    [00:00:00.248,626] <dbg> nrf_cloud_transport.nct_topics_populate: shadow_base_topic: $aws/things/nrf-352656106105102/shadow
    
    [00:00:00.260,162] <dbg> nrf_cloud_transport.nct_topics_populate: accepted_topic: nrf-352656106105102/shadow/get/accepted
    
    [00:00:00.271,514] <dbg> nrf_cloud_transport.nct_topics_populate: rejected_topic: $aws/things/nrf-352656106105102/shadow/get/rejected
    
    [00:00:00.283,935] <dbg> nrf_cloud_transport.nct_topics_populate: update_delta_topic: $aws/things/nrf-352656106105102/shadow/update/delta
    
    [00:00:00.296,661] <dbg> nrf_cloud_transport.nct_topics_populate: update_topic: $aws/things/nrf-352656106105102/shadow/update
    
    [00:00:00.308,380] <dbg> nrf_cloud_transport.nct_topics_populate: shadow_get_topic: $aws/things/nrf-352656106105102/shadow/get
    
    [00:00:00.320,159] <inf> asset_tracker: Connecting to LTE network.
    
    [00:00:00.326,721] <inf> asset_tracker: This may take several minutes.
    
    +CEREG: 2,"B293","00C4D302",7,0,0,"11100000","11100000"
    
    [00:00:09.245,910] <inf> asset_tracker: LTE cell changed: Cell ID: 12899074, Tracking area: 45715
    
    +CSCON: 1
    
    [00:00:09.292,785] <inf> asset_tracker: RRC mode: Connected
    
    +CEREG: 5,"B293","00C4D302",7,,,"00011110","11100000"
    
    [00:00:11.939,758] <inf> asset_tracker: Connected to LTE network.
    
    [00:00:11.946,411] <inf> asset_tracker: Connecting to cloud, attempt 1 of 8
    
    [00:00:11.953,735] <inf> asset_tracker: Cloud connection request sent.
    
    [00:00:11.960,632] <inf> asset_tracker: Connection response timeout is set to 30 seconds.
    
    [00:00:11.969,238] <wrn> date_time: getaddrinfo, error: -11
    
    [00[00:00:11.975,891] <wrn> date_time: getaddrinfo, error: -11
    
    :[00:00:11.982,269] <wrn> date_time: getaddrinfo, error: -11
    
    00:[00:00:11.988,861] <wrn> date_time: getaddrinfo, error: -11
    
    11.[00:00:11.995,391] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:12.001,556] <wrn> date_time: Not getting time from any NTP server
    
    975,555] <inf> asset_tracker: Network registration status: Connected - roaming
    
    [00:00:12.016,693] <inf> asset_tracker: PSM parameter update: TAU: -1, Active time: 60
    
    [00:00:12.025,146] <inf> asset_tracker: DATE_TIME_NOT_OBTAINED
    
    [00:00:12.031,402] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTING
    
    [00:00:12.039,825] <inf> asset_tracker: CLOUD_EVT_CONNECTING
    
    [00:00:12.046,173] <dbg> nrf_cloud_transport.nct_connect: getaddrinfo failed -11
    
    [00:00:12.053,894] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTING
    
    [00:00:12.062,377] <inf> asset_tracker: CLOUD_EVT_CONNECTING
    
    [00:00:12.068,450] <err> asset_tracker: Failed to connect to cloud, error -3
    
    [00:00:12.076,171] <err> asset_tracker: Network error, check cloud configuration
    
    [00:00:12.084,228] <err> asset_tracker: Device will reboot in 300 seconds
    
    [00:00:12.091,674] <err> asset_tracker: LTE link disconnect
    
    +CSCON: 0
    
    [00:00:13.343,078] <inf> asset_tracker: RRC mode: Idle
    
    +CEREG: 0,"B293","00C4D302",7,0,11,"11100000","11100000"
    
    [00:00:13.685,211] <err> asset_tracker: Shutdown modem
    
    +CEREG: 2,"0BF4","01914E01",7,0,0,"11100000","11100000"
    
    [00:00:32.015,319] <inf> asset_tracker: LTE cell changed: Cell ID: 26299905, Tracking area: 3060
    
    +CSCON: 1
    
    [00:00:32.064,392] <inf> asset_tracker: RRC mode: Connected
    
    +CEREG: 5,"0BF4","01914E01",7,,,"00100001","00000110"
    
    [00:00:34.946,807] <inf> asset_tracker: Connected to LTE network.
    
    [00:00:34.953,369] <inf> asset_tracker: Connecting to cloud, attempt 1 of 8
    
    [00:00:34.960,754] <inf> asset_tracker: Cloud connection request sent.
    
    [00:00:34.967,651] <inf> asset_tracker: Connection response timeout is set to 30 seconds.
    
    [00:00:34.976,318] <inf> asset_tracker: Network registration status: Connected - roaming
    
    [00:00:34.984,741] <inf> asset_tracker: PSM parameter update: TAU: 3600, Active time: 60
    
    [00:00:34.993,286] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTING
    
    [00:00:35.001,708] <inf> asset_tracker: CLOUD_EVT_CONNECTING
    
    [00:00:3[00:00:35.146,057] <inf> asset_tracker: DATE_TIME_OBTAINED_NTP
    
    5.145,019] <dbg> nrf_cloud_transport.nct_connect: IPv4 address: 3.223.156.194
    
    [00:00:35.159,759] <dbg> nrf_cloud_transport.nct_mqtt_connect: MQTT clean session flag: 1
    
    [00:00:39.483,612] <inf> nrf_cloud_transport: Using socket send timeout of 60 seconds
    
    [00:00:39.491,821] <dbg> nrf_cloud.nrf_cloud_run: Cloud connection request sent.
    
    [00:00:39.802,429] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_CONNACK: result 0
    
    [00:00:39.811,309] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 2
    
    [00:00:39.818,908] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTED
    
    [00:00:39.827,331] <inf> asset_tracker: CLOUD_EVT_CONNECTED
    
    [00:00:39.833,312] <inf> asset_tracker: Persistent Sessions = 0
    
    [00:00:39.839,630] <dbg> nrf_cloud_transport.nct_cc_connect: nct_cc_connect
    
    [00:00:39.848,175] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 3
    
    [00:00:40.068,389] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_SUBACK: id = 1234 result = 0
    
    [00:00:40.078,186] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 4
    
    [00:00:40.085,815] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 5678 opcode = 0 len = 0
    
    [00:00:40.096,374] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
    
    [00:00:40.441,467] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 5678 result = 0
    
    [00:00:40.451,293] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
    
    [00:00:40.484,008] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBLISH: id = 37220 len = 317
    
    [00:00:40.495,239] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
    
    [00:00:40.502,807] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_RX_DATA
    
    [00:00:40.510,162] <inf> asset_tracker: CLOUD_EVT_DATA_RECEIVED
    
    [00:00:40.517,364] <inf> cloud_codec: [cloud_search_config:941] Found cfg item GPS, enable
    
    
    [00:00:40.528,961] <dbg> nrf_cloud_transport.nct_dc_endpoint_set: nct_dc_endpoint_set
    
    [00:00:40.537,567] <dbg> nrf_cloud_transport.nct_dc_endpoint_get: nct_dc_endpoint_get
    
    [00:00:40.548,004] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 7890 opcode = 1 len = 360
    
    [00:00:40.559,417] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 7
    
    [00:00:40.566,986] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_USER_ASSOCIATED
    
    [00:00:40.575,042] <inf> asset_tracker: CLOUD_EVT_PAIR_DONE
    
    [00:00:40.580,993] <inf> asset_tracker: CLOUD_EVT_FOTA_ERROR
    
    [00:00:41.081,512] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 7890 result = 0
    
    [00:00:41.091,308] <dbg> nrf_cloud_transport.nct_dc_connect: nct_dc_connect
    
    [00:00:41.099,731] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 8
    
    [00:00:41.401,428] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_SUBACK: id = 8765 result = 0
    
    [00:00:41.411,254] <dbg> nrf_cloud_transport.save_session_state: Setting session state: 1
    
    [00:00:41.420,379] <dbg> nrf_cloud_fota.nrf_cloud_fota_subscribe: Subscribing to topic: prod/f09a7a09-25a9-4888-94a8-694361ad2d4c/nrf-352656106105102/jobs/rcv
    
    [00:00:41.435,913] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 9
    
    [00:00:41.443,481] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_READY
    
    [00:00:41.450,683] <inf> asset_tracker: CLOUD_EVT_READY
    
    [00:00:41.457,824] <dbg> nrf9160_gps.configure_antenna: MAGPIO set: AT%XMAGPIO=1,0,0,1,1,1565,1586
    
    [00:00:41.467,895] <dbg> nrf9160_gps.configure_antenna: COEX0 set: AT%XCOEX0=1,1,1565,1586
    
    [00:00:41.476,531] <dbg> nrf9160_gps.open_socket: GPS socket created, fd: 1232491587
    
    [00:00:41.484,680] <inf> gps_control: GPS initialized
    
    [00:00:41.531,402] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 1 opcode = 1 len = 625
    
    %CESQ: 36,1,18,2
    
    [00:00:41.662,475] <dbg> nrf_cloud_fota.nrf_cloud_fota_mqtt_evt_handler: MQTT_EVT_SUBACK
    
    [00:00:41.670,898] <dbg> nrf_cloud_fota.publish: Topic: prod/f09a7a09-25a9-4888-94a8-694361ad2d4c/nrf-352656106105102/jobs/req
    
    [00:00:41.682,678] <dbg> nrf_cloud_fota.publish: Payload (4 bytes): [""]
    
    [00:00:41.883,483] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 1 result = 0
    
    [00:00:42.025,482] <dbg> nrf_cloud_fota.nrf_cloud_fota_mqtt_evt_handler: MQTT_EVT_PUBACK: msg id 8767
    
    +CSCON: 0
    
    [00:00:59.613,372] <inf> asset_tracker: RRC mode: Idle
    
    %CESQ: 36,1,13,1
    
    +CSCON: 1
    
    [00:01:16.566,558] <inf> asset_tracker: RRC mode: Connected
    
    %CESQ: 35,1,18,2
    
    +CSCON: 0
    
    [00:01:31.071,807] <inf> asset_tracker: RRC mode: Idle
    
    %CESQ: 36,1,13,1
    
    +CSCON: 1
    
    [00:01:46.587,982] <inf> asset_tracker: RRC mode: Connected
    
    %CESQ: 35,1,18,2

Reply
  • Hi Hakon,

    thanks for taken over.

    Yes, my SIM card is registered and has plenty of data volume left. The date time synchronization did also worked in the past. Only since the two updates, I mentioned in my initial post, seems something  to be amiss.

    Since I needed to proceed with my project, I flashed the Asset Tracker v2 sample to the last device which had the issue. As with my other device, the date time synchronization seems to work again since then. The consequence is that now, I too don't have a device any more with which I can reproduce the mentioned behavior.

    However, I logged the output of the Asset Tracker v2 sample. Like I mentioned in my first post, the first run failed and the second run (after a cold reboot) succeeded. Unfortunately the log file of the second run isn't compete since I wasn't fast enough to reconnect my terminal to the device after the reboot.

    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    I: Starting bootloader
    
    I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
    
    I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
    
    I: Boot source: none
    
    I: Swap type: none
    
    I: Bootloader chainload address offset: 0x10000
    
    I: Jumping to the first image slot
    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    Flash regions           Domain          Permissions
    
    00 02 0x00000 0x18000   Secure          rwxl
    
    03 31 0x18000 0x100000  Non-Secure      rwxl
    
    
    
    Non-secure callable region 0 placed in flash region 2 with size 32.
    
    
    
    SRAM region             Domain          Permissions
    
    00 07 0x00000 0x10000   Secure          rwxl
    
    08 31 0x10000 0x40000   Non-Secure      rwxl
    
    
    
    Peripheral              Domain          Status
    
    00 NRF_P0               Non-Secure      OK
    
    01 NRF_CLOCK            Non-Secure      OK
    
    02 NRF_RTC0             Non-Secure      OK
    
    03 NRF_RTC1             Non-Secure      OK
    
    04 NRF_NVMC             Non-Secure      OK
    
    05 NRF_UARTE1           Non-Secure      OK
    
    06 NRF_UARTE2           Secure          SKIP
    
    07 NRF_TWIM2            Non-Secure      OK
    
    08 NRF_SPIM3            Non-Secure      OK
    
    09 NRF_TIMER0           Non-Secure      OK
    
    10 NRF_TIMER1           Non-Secure      OK
    
    11 NRF_TIMER2           Non-Secure      OK
    
    12 NRF_SAADC            Non-Secure      OK
    
    13 NRF_PWM0             Non-Secure      OK
    
    14 NRF_PWM1             Non-Secure      OK
    
    15 NRF_PWM2             Non-Secure      OK
    
    16 NRF_PWM3             Non-Secure      OK
    
    17 NRF_WDT              Non-Secure      OK
    
    18 NRF_IPC              Non-Secure      OK
    
    19 NRF_VMC              Non-Secure      OK
    
    20 NRF_FPU              Non-Secure      OK
    
    21 NRF_EGU1             Non-Secure      OK
    
    22 NRF_EGU2             Non-Secure      OK
    
    23 NRF_DPPIC            Non-Secure      OK
    
    24 NRF_REGULATORS       Non-Secure      OK
    
    25 NRF_GPIOTE1          Non-Secure      OK
    
    
    
    SPM: NS image at 0x1c200
    
    SPM: NS MSP at 0x200255a0
    
    SPM: NS reset vector at 0x26815
    
    SPM: prepare to jump to Non-Secure image.
    
    *** Booting Zephyr OS build v2.4.99-ncs2  ***
    
    [00:00:00.206,146] <inf> asset_tracker: Asset tracker started
    
    [00:00:00.212,249] <inf> watchdog: Watchdog timeout installed. Timeout: 60000
    
    [00:00:00.219,757] <inf> watchdog: Watchdog started
    
    [00:00:00.225,067] <inf> watchdog: Watchdog feed enabled. Timeout: 30000
    
    [00:00:00.239,562] <dbg> nrf_cloud_transport.nct_client_id_get: client_id = nrf-352656106105102
    
    [00:00:00.248,626] <dbg> nrf_cloud_transport.nct_topics_populate: shadow_base_topic: $aws/things/nrf-352656106105102/shadow
    
    [00:00:00.260,162] <dbg> nrf_cloud_transport.nct_topics_populate: accepted_topic: nrf-352656106105102/shadow/get/accepted
    
    [00:00:00.271,514] <dbg> nrf_cloud_transport.nct_topics_populate: rejected_topic: $aws/things/nrf-352656106105102/shadow/get/rejected
    
    [00:00:00.283,935] <dbg> nrf_cloud_transport.nct_topics_populate: update_delta_topic: $aws/things/nrf-352656106105102/shadow/update/delta
    
    [00:00:00.296,661] <dbg> nrf_cloud_transport.nct_topics_populate: update_topic: $aws/things/nrf-352656106105102/shadow/update
    
    [00:00:00.308,380] <dbg> nrf_cloud_transport.nct_topics_populate: shadow_get_topic: $aws/things/nrf-352656106105102/shadow/get
    
    [00:00:00.320,159] <inf> asset_tracker: Connecting to LTE network.
    
    [00:00:00.326,721] <inf> asset_tracker: This may take several minutes.
    
    +CEREG: 2,"B293","00C4D302",7,0,0,"11100000","11100000"
    
    [00:00:09.245,910] <inf> asset_tracker: LTE cell changed: Cell ID: 12899074, Tracking area: 45715
    
    +CSCON: 1
    
    [00:00:09.292,785] <inf> asset_tracker: RRC mode: Connected
    
    +CEREG: 5,"B293","00C4D302",7,,,"00011110","11100000"
    
    [00:00:11.939,758] <inf> asset_tracker: Connected to LTE network.
    
    [00:00:11.946,411] <inf> asset_tracker: Connecting to cloud, attempt 1 of 8
    
    [00:00:11.953,735] <inf> asset_tracker: Cloud connection request sent.
    
    [00:00:11.960,632] <inf> asset_tracker: Connection response timeout is set to 30 seconds.
    
    [00:00:11.969,238] <wrn> date_time: getaddrinfo, error: -11
    
    [00[00:00:11.975,891] <wrn> date_time: getaddrinfo, error: -11
    
    :[00:00:11.982,269] <wrn> date_time: getaddrinfo, error: -11
    
    00:[00:00:11.988,861] <wrn> date_time: getaddrinfo, error: -11
    
    11.[00:00:11.995,391] <wrn> date_time: getaddrinfo, error: -11
    
    [00:00:12.001,556] <wrn> date_time: Not getting time from any NTP server
    
    975,555] <inf> asset_tracker: Network registration status: Connected - roaming
    
    [00:00:12.016,693] <inf> asset_tracker: PSM parameter update: TAU: -1, Active time: 60
    
    [00:00:12.025,146] <inf> asset_tracker: DATE_TIME_NOT_OBTAINED
    
    [00:00:12.031,402] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTING
    
    [00:00:12.039,825] <inf> asset_tracker: CLOUD_EVT_CONNECTING
    
    [00:00:12.046,173] <dbg> nrf_cloud_transport.nct_connect: getaddrinfo failed -11
    
    [00:00:12.053,894] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTING
    
    [00:00:12.062,377] <inf> asset_tracker: CLOUD_EVT_CONNECTING
    
    [00:00:12.068,450] <err> asset_tracker: Failed to connect to cloud, error -3
    
    [00:00:12.076,171] <err> asset_tracker: Network error, check cloud configuration
    
    [00:00:12.084,228] <err> asset_tracker: Device will reboot in 300 seconds
    
    [00:00:12.091,674] <err> asset_tracker: LTE link disconnect
    
    +CSCON: 0
    
    [00:00:13.343,078] <inf> asset_tracker: RRC mode: Idle
    
    +CEREG: 0,"B293","00C4D302",7,0,11,"11100000","11100000"
    
    [00:00:13.685,211] <err> asset_tracker: Shutdown modem
    
    +CEREG: 2,"0BF4","01914E01",7,0,0,"11100000","11100000"
    
    [00:00:32.015,319] <inf> asset_tracker: LTE cell changed: Cell ID: 26299905, Tracking area: 3060
    
    +CSCON: 1
    
    [00:00:32.064,392] <inf> asset_tracker: RRC mode: Connected
    
    +CEREG: 5,"0BF4","01914E01",7,,,"00100001","00000110"
    
    [00:00:34.946,807] <inf> asset_tracker: Connected to LTE network.
    
    [00:00:34.953,369] <inf> asset_tracker: Connecting to cloud, attempt 1 of 8
    
    [00:00:34.960,754] <inf> asset_tracker: Cloud connection request sent.
    
    [00:00:34.967,651] <inf> asset_tracker: Connection response timeout is set to 30 seconds.
    
    [00:00:34.976,318] <inf> asset_tracker: Network registration status: Connected - roaming
    
    [00:00:34.984,741] <inf> asset_tracker: PSM parameter update: TAU: 3600, Active time: 60
    
    [00:00:34.993,286] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTING
    
    [00:00:35.001,708] <inf> asset_tracker: CLOUD_EVT_CONNECTING
    
    [00:00:3[00:00:35.146,057] <inf> asset_tracker: DATE_TIME_OBTAINED_NTP
    
    5.145,019] <dbg> nrf_cloud_transport.nct_connect: IPv4 address: 3.223.156.194
    
    [00:00:35.159,759] <dbg> nrf_cloud_transport.nct_mqtt_connect: MQTT clean session flag: 1
    
    [00:00:39.483,612] <inf> nrf_cloud_transport: Using socket send timeout of 60 seconds
    
    [00:00:39.491,821] <dbg> nrf_cloud.nrf_cloud_run: Cloud connection request sent.
    
    [00:00:39.802,429] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_CONNACK: result 0
    
    [00:00:39.811,309] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 2
    
    [00:00:39.818,908] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_TRANSPORT_CONNECTED
    
    [00:00:39.827,331] <inf> asset_tracker: CLOUD_EVT_CONNECTED
    
    [00:00:39.833,312] <inf> asset_tracker: Persistent Sessions = 0
    
    [00:00:39.839,630] <dbg> nrf_cloud_transport.nct_cc_connect: nct_cc_connect
    
    [00:00:39.848,175] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 3
    
    [00:00:40.068,389] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_SUBACK: id = 1234 result = 0
    
    [00:00:40.078,186] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 4
    
    [00:00:40.085,815] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 5678 opcode = 0 len = 0
    
    [00:00:40.096,374] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
    
    [00:00:40.441,467] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 5678 result = 0
    
    [00:00:40.451,293] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
    
    [00:00:40.484,008] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBLISH: id = 37220 len = 317
    
    [00:00:40.495,239] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 5
    
    [00:00:40.502,807] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_RX_DATA
    
    [00:00:40.510,162] <inf> asset_tracker: CLOUD_EVT_DATA_RECEIVED
    
    [00:00:40.517,364] <inf> cloud_codec: [cloud_search_config:941] Found cfg item GPS, enable
    
    
    [00:00:40.528,961] <dbg> nrf_cloud_transport.nct_dc_endpoint_set: nct_dc_endpoint_set
    
    [00:00:40.537,567] <dbg> nrf_cloud_transport.nct_dc_endpoint_get: nct_dc_endpoint_get
    
    [00:00:40.548,004] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 7890 opcode = 1 len = 360
    
    [00:00:40.559,417] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 7
    
    [00:00:40.566,986] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_USER_ASSOCIATED
    
    [00:00:40.575,042] <inf> asset_tracker: CLOUD_EVT_PAIR_DONE
    
    [00:00:40.580,993] <inf> asset_tracker: CLOUD_EVT_FOTA_ERROR
    
    [00:00:41.081,512] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 7890 result = 0
    
    [00:00:41.091,308] <dbg> nrf_cloud_transport.nct_dc_connect: nct_dc_connect
    
    [00:00:41.099,731] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 8
    
    [00:00:41.401,428] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_SUBACK: id = 8765 result = 0
    
    [00:00:41.411,254] <dbg> nrf_cloud_transport.save_session_state: Setting session state: 1
    
    [00:00:41.420,379] <dbg> nrf_cloud_fota.nrf_cloud_fota_subscribe: Subscribing to topic: prod/f09a7a09-25a9-4888-94a8-694361ad2d4c/nrf-352656106105102/jobs/rcv
    
    [00:00:41.435,913] <dbg> nrf_cloud.nfsm_set_current_state_and_notify: state: 9
    
    [00:00:41.443,481] <dbg> nrf_cloud.api_event_handler: NRF_CLOUD_EVT_READY
    
    [00:00:41.450,683] <inf> asset_tracker: CLOUD_EVT_READY
    
    [00:00:41.457,824] <dbg> nrf9160_gps.configure_antenna: MAGPIO set: AT%XMAGPIO=1,0,0,1,1,1565,1586
    
    [00:00:41.467,895] <dbg> nrf9160_gps.configure_antenna: COEX0 set: AT%XCOEX0=1,1,1565,1586
    
    [00:00:41.476,531] <dbg> nrf9160_gps.open_socket: GPS socket created, fd: 1232491587
    
    [00:00:41.484,680] <inf> gps_control: GPS initialized
    
    [00:00:41.531,402] <dbg> nrf_cloud_transport.nct_cc_send: mqtt_publish: id = 1 opcode = 1 len = 625
    
    %CESQ: 36,1,18,2
    
    [00:00:41.662,475] <dbg> nrf_cloud_fota.nrf_cloud_fota_mqtt_evt_handler: MQTT_EVT_SUBACK
    
    [00:00:41.670,898] <dbg> nrf_cloud_fota.publish: Topic: prod/f09a7a09-25a9-4888-94a8-694361ad2d4c/nrf-352656106105102/jobs/req
    
    [00:00:41.682,678] <dbg> nrf_cloud_fota.publish: Payload (4 bytes): [""]
    
    [00:00:41.883,483] <dbg> nrf_cloud_transport.nct_mqtt_evt_handler: MQTT_EVT_PUBACK: id = 1 result = 0
    
    [00:00:42.025,482] <dbg> nrf_cloud_fota.nrf_cloud_fota_mqtt_evt_handler: MQTT_EVT_PUBACK: msg id 8767
    
    +CSCON: 0
    
    [00:00:59.613,372] <inf> asset_tracker: RRC mode: Idle
    
    %CESQ: 36,1,13,1
    
    +CSCON: 1
    
    [00:01:16.566,558] <inf> asset_tracker: RRC mode: Connected
    
    %CESQ: 35,1,18,2
    
    +CSCON: 0
    
    [00:01:31.071,807] <inf> asset_tracker: RRC mode: Idle
    
    %CESQ: 36,1,13,1
    
    +CSCON: 1
    
    [00:01:46.587,982] <inf> asset_tracker: RRC mode: Connected
    
    %CESQ: 35,1,18,2

Children
Related