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
//=============================================================================
//=============================================================================

  • 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

  • Sebastian Stein said:
    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.

     So is there still an issue, if you can't reproduce it? Do we need more investigation if the issue is gone?

  • Hi Hakon,

    So is there still an issue, if you can't reproduce it?

    In a purely practical sense, there isn't an issue for me which is stopping me from proceeding with my project.

    Do we need more investigation if the issue is gone?

    The answer to this question is twofold.

    As I mentioned in my original post, I did know the workaround for the issue since the beginning but I was curious about the cause. Furthermore I figured that my observations could be interesting for Nordic's developers. I am still curious but you don't have to investigate further just for me. However, if Nordic's devs are curious, I am still willing to help if I can.

    Long story short, I am fine with closing this ticket.

  • Sebastian Stein said:
    However, if Nordic's devs are curious, I am still willing to help if I can.

     That's great, we appreciate the feedback. I'm not sure if there is anything that can be done at this point since neither me or Simen are able to reproduce it, but if you want you can leave the ticket open in case someone else runs into the issue or we are able to reproduce it on our side.

  • It seems likely that the error picture I described was a red herring and that the issue was caused by an unfortunately correlated but not causally connected problem with the network, or my SIM card/subscription. See this Ticket.

Related