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?

[Didrik Rokhaug]

Hi,

What time sources are you getting your time from?

What date_time related Kconfig options have you set, and how do you use the library in your code?

 

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?

 In general, memory leaks, or other memory related errors could cause all kind of weird behavior. Could it be possible that there is something else than the date_time library that writes to the date_time library's internal variable?

Best regards,

Didrik

[Jstone40649]

Config wise we have: the date time interval at 3600, Date time modem and ntp are both set, the stack size for the date time thread is 1024, and the ntp query time is 5 seconds.

The snippet covers most of the code related to getting date-times, and works as expected in testing.

static void date_time_event_handler(const struct date_time_evt *evt)
{
	switch (evt->type) {
	case DATE_TIME_OBTAINED_MODEM:
		printk("DATE_TIME_OBTAINED_MODEM\n");
		break;
	case DATE_TIME_OBTAINED_NTP:
		printk("DATE_TIME_OBTAINED_NTP\n");
		break;
	case DATE_TIME_OBTAINED_EXT:
		printk("DATE_TIME_OBTAINED_EXT\n");
		break;
	case DATE_TIME_NOT_OBTAINED:
		printk("DATE_TIME_NOT_OBTAINED\n");
		break;
	default:
		break;
	}

	/** Do not depend on obtained time, continue upon any event from the
	 *  date time library.
	 */
	k_sem_give(&date_time_obtained);
}

int dateTimeErrs = 0;

static void date_time_update(void)
{
    int err;

    // Start datetime update
    date_time_update_async(date_time_event_handler);

    // wait, DATE_TIME_TIMEOUT_S seconds for the datetime update to return
    err = k_sem_take(&date_time_obtained, K_SECONDS(DATE_TIME_TIMEOUT_S));
    if (err) {
            printk("Date time, no callback event within %d seconds\n",
                    DATE_TIME_TIMEOUT_S);
    }
    else
    {
        int64_t unixTime;   
        err = date_time_now(&unixTime);
        if (err)
        {
			dateTimeErrs++;
        }
        else
        {
			// We're deviding by 1000 to get unix time in seconds instead of milliseconds.
			// TODO Consider finding an alternative method.
			ClockService_SetTimeUnix(unixTime/1000);
        }
		LOG_ERR("DateTimeErrors: %d", dateTimeErrs);
    }
}

And then a little down the line we have this code, to convert from the unix timestamp to our structure

bool DateTime_FromUnix(DateTime* value, int64_t unixTime)
{
    time_t epoch = unixTime;
    struct tm timestamp = *localtime(&epoch);  
    return DateTime_Initialize(value, 1900 + timestamp.tm_year, 1 + timestamp.tm_mon, timestamp.tm_mday, timestamp.tm_hour, timestamp.tm_min, timestamp.tm_sec, 0);
}

I don't think we have any place where the internal variable could be comprimised. Memory leaks or problems like it could make sense, but we've got multiple devices reporting the same behaviour, and the datetime, while now a month off, is still consistent with the passing of time, but with an offset. I'd expect that memory issues would be lead to more random outcomes.

[Didrik Rokhaug]

Hi, and sorry for the late reply.

have you had any progress on this issue?

I would like to have the developer behind the date_time library look at this ticket, but unfortunately, he is on vacation for another week.

In the meantime, I have some more questions:

1. How big is the time offset? What time values do you get?

2. Is the time offset the same on all the failing devices?

3. What source do you get the time from? Does the source change when the error appears?

4. When did the error appear? E.g. was it at a month boundary?

5. How are the timestamps handled on the cloud side?

6. Could you add printks/log statements in the date_time library that prints the time received from the source?

7. Does the error appear at the same time, or after the same runtime in different devices?

Best regards,

Didrik

[Jstone40649]

Unfortunately no progress yet, since it takes so long to reproduce were finding it difficult to debug. 

1. It's about 8 weeks, so for example on July 5th (7-5) the time reported as august 24th (8-24)

2. Yes, it appears to be consistent between devices.

3. It's my understand that the date_time library can pull from several sources, I think we have modem time and NTP enabled. We have not been tracking the source of each individual update, I'll add that to our testing considerations going forward. 
4. The error seems to appear 30 days after initial power-up, but there's no other specific boundary. 

5. Before uploading we format the date-time to a JSON string, the cloud stores that string directly along side the date-time as the server sees it. 

6. We're working on something like this, but we don't have long-term serial access generally so we're working to get that info pushed up through the cloud. 

7. We don't have a huge sample size for this, but it seems to trigger around 30 days after powerup. 

Thanks for your help looking into this, I'll keep looking into it on our end and I'll try to add in those extra considerations you mentioned.

[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