nRF9160 Date Time Desync Issue

[Jstone40649]

Hello, 

We're currently using the nRF9160 module in an iOT device meant to run for a long time continuously. As part of this operation we're tracking a date-time and using it to post to AWS. We're taking advantage of the date time library code described here: https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/include/date_time.html. 

The software has run well for several weeks, but suddenly we found our device had shifted forward about a month and is now reporting date-times in august. We call date_time_update_async periodically and so expected that any errors like this would be corrected on a new call, but that doesn't seem to be the case: our device is still shifted forward after several days and update calls don't seem to correct the error. Other devices deployed later seem to be getting proper date times, and devices that fell out of sync will correct with a software reset. 

Do you have any insight as to what could cause our clock to skip forward like that, or why the date_time_update_async calls would not correct the error?

[Sebastian Stein]

Hi,

sorry for jumping into the discussion. However, I am experiencing the same behavior with a nrf9160 DK, which I run in a continuous duty test.

Meta information:

• nrf9160 DK version: 0.9.0 | 2019.20
• nrf Connect SDK version: 1.5.1
• Modem firmware version: 1.2.3
• Date time library related prj.conf settings:
  

  CONFIG_DATE_TIME=y
  CONFIG_DATE_TIME_MODEM=y
  CONFIG_DATE_TIME_UPDATE_INTERVAL_SECONDS=3600

Issue description:

At the month boundary between July and August, the date time jumped to late September and is not corrected despite of the update period of 3600 s. This issue occurred after 36 days (5 hour precision) after the continuous duty test started. The time offset is around 4294959 s.

Every 10 minutes, the DK acquires sensor data and sends them into a cloud service. The cloud service received the last valid data set at 2021-07-30 05:31:26 UTC. The date time has an offset since then. In the following you find two examples of raw data sets, which the cloud service has received since then.

// Received at 2021-08-02 15:51:47 UTC
// The unix time stamps translate to 2021-09-21 08:54:26 UTC
{

   "ver":"0.01",

   "snd":[

      "1632214466,LmLrs21,t0,19.100,0",

      "1632214466,LmLrs21,t1,55.900,0",

      "1632214466,LmLrs21,t2,993.600,0"

   ]

}

// Received at 2021-08-02 16:01:47 UTC
// The unix time stamps translate to 2021-09-21 09:04:26 UTC
{

   "ver":"0.01",

   "snd":[

      "1632215066,LmLrs21,t0,19.300,0",

      "1632215066,LmLrs21,t1,55.500,0",

      "1632215066,LmLrs21,t2,993.600,0"

   ]

}

Furthermore, I gather logging information and send them to a server of mine. I  noticed two things in the log messages. Firstly, the time stamps of the log messages exhibit the same date time offset. Secondly, the modem seemed to had some issues with querying the time from a ntp server. However, this querying issue does not overlap with the first occurrence of the date time offset. Below you find a slightly censored log file. The time is given in UTC. Please note the jump in the time stamps between line 4 and 5 and please note the date time log messages beginning at line 12.

[2021-07-29 23:21:26] <dbg> lmSdi12.sdi12IssueCommandSequence: Sensor 4 - seq. retries: 1
[2021-07-30 02:01:26] <dbg> lmSdi12.sdi12IssueCommandSequence: Sensor 4 - seq. retries: 1
[2021-07-30 03:31:26] <dbg> lmSdi12.sdi12IssueCommandSequence: Sensor 4 - seq. retries: 1
[2021-07-30 04:01:26] <dbg> lmSdi12.sdi12IssueCommandSequence: Sensor 4 - seq. retries: 1
[2021-09-18 18:24:34] <wrn> cloudService: Could not send data, data buffered
[2021-09-18 18:24:34] <wrn> cloudUpdateTask: Sending failed
[2021-09-18 18:34:34] <inf> cloudService: Buffered data was send
[2021-09-19 13:04:26] <dbg> lmSdi12.sdi12IssueCommandSequence: Sensor 4 - seq. retries: 1
[2021-09-19 18:34:33] <wrn> cloudService: Could not send data, data buffered
[2021-09-19 18:34:33] <wrn> cloudUpdateTask: Sending failed
[2021-09-19 18:44:34] <inf> cloudService: Buffered data was send
[2021-09-20 00:43:30] <wrn> date_time: sntp_query, error: -116
[2021-09-20 00:44:00] <wrn> date_time: getaddrinfo, error: -11
[2021-09-20 00:44:30] <wrn> date_time: getaddrinfo, error: -11
[2021-09-20 00:44:30] <wrn> date_time: getaddrinfo, error: -11
[2021-09-20 00:44:30] <wrn> date_time: getaddrinfo, error: -11
[2021-09-20 00:44:30] <wrn> date_time: Not getting time from any NTP server
[2021-09-20 00:44:30] <err> at_cmd: Failed to send AT command (err:9)
[2021-09-20 00:44:33] <wrn> cloudService: Could not send data, data buffered
[2021-09-20 00:44:33] <wrn> cloudUpdateTask: Sending failed
[2021-09-20 00:54:34] <inf> cloudService: Buffered data was send
[2021-09-20 05:43:30] <wrn> date_time: sntp_query, error: -116
[2021-09-21 20:44:26] <dbg> lmSdi12.sdi12IssueCommandSequence: Sensor 4 - seq. retries: 1