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,

I've had a talk with the developer of the date_time library, and he suggested that it might be the last_date_time_update that overflows.

Could you try to change the type from int to int64_t for the last_date_time_update field in the time_aux struct (line 70 in date_time.c)?

[anicare-tero]

Hi,

I just found out yesterday after reading this discussion that I have this same problem.

• nRF Connect SDK version: 1.6.0
• Modem firmware version: 1.2.3

Our device search GPS once a week and after a GPS fix it sets the GPS datetime to Date-Time with date_time_set(). Then I'm calculating the delay for the next week's target time and getting the current UTC time with date_time_now().

I have also set CONFIG_DATE_TIME_UPDATE_INTERVAL_SECONDS=0 so the library won't update the Date-Time without commanding it to do it.

Here you can see from the logs that after 25 days it's not responding correctly anymore:

Jul 06 14:41:24 [00:02:06.592,620] <inf> application: Current UTC time from GPS has been set: 06.07.2021 11:41:24	// date_time_set()
Jul 06 14:41:24 [00:02:06.987,121] <inf> application: uptime_days: 0
Jul 06 14:41:27 [00:02:09.473,358] <inf> application: Current UTC time: 06.07.2021 11:41:26							// date_time_now()
Jul 06 14:41:27 [00:02:09.483,032] <inf> application: Calculated target UTC time: 11.07.2021 04:48:26

Jul 11 07:50:01 [03:57:16.162,139] <inf> application: Current UTC time from GPS has been set: 11.07.2021 04:50:00	// date_time_set()
Jul 11 07:50:01 [03:57:16.545,410] <inf> application: uptime_days: 4
Jul 11 07:50:03 [03:57:18.905,487] <inf> application: Current UTC time: 11.07.2021 04:50:02							// date_time_now()
Jul 11 07:50:03 [03:57:18.915,191] <inf> application: Calculated target UTC time: 18.07.2021 04:48:02

Jul 18 08:12:02 [26:41:23.327,484] <inf> application: Current UTC time from GPS has been set: 18.07.2021 05:12:02	// date_time_set()
Jul 18 08:12:03 [26:41:23.711,059] <inf> application: uptime_days: 11
Jul 18 08:12:05 [26:41:26.098,937] <inf> application: Current UTC time: 18.07.2021 05:12:04							// date_time_now()
Jul 18 08:12:05 [26:41:26.108,581] <inf> application: Calculated target UTC time: 25.07.2021 04:48:04

Jul 25 07:49:30 [12:16:26.470,001] <inf> application: Current UTC time from GPS has been set: 25.07.2021 04:49:30	// date_time_set()
Jul 25 07:49:31 [12:16:26.853,454] <inf> application: uptime_days: 18
Jul 25 07:49:33 [12:16:29.483,276] <inf> application: Current UTC time: 25.07.2021 04:49:33							// date_time_now()
Jul 25 07:49:33 [12:16:29.492,980] <inf> application: Calculated target UTC time: 01.08.2021 04:48:33

Aug 01 07:50:00 [34:39:01.667,724] <inf> application: Current UTC time from GPS has been set: 01.08.2021 04:50:00	// date_time_set()
Aug 01 07:50:01 [34:39:02.051,330] <inf> application: uptime_days: 25
######################################################################################################################################
Aug 01 07:50:03 [34:39:04.418,701] <inf> application: Current UTC time: 19.09.2021 21:52:50							// date_time_now()
Aug 01 07:50:03 [34:39:04.428,405] <inf> application: Calculated target UTC time: 26.09.2021 04:48:50
######################################################################################################################################

It's sad that testing this issue lasts for so long. Didrik Rokhaug do you think there could be any disadvantages or problems when changing that last_date_time_update from int to int64_t? I think we have to do a next firmware release in this month so we have not enough time to test this fix completely before that.

[Didrik Rokhaug]

Hi anicare-tero,

No, I don't think there should be any negative consequences of changing the type from int to tint64_t.

We have opened a PR with this update: https://github.com/nrfconnect/sdk-nrf/pull/5245

As Simen explains in the commit, k_uptime_get() returns an int64_t, so storing the value in an int will cause an overflow after approximately 25 days, as you are seeing.

[JLCIOT]

We are having this same issue on our boards.  Would someone provide an update on if the recommended fix solved this problem!!!!!

[Didrik Rokhaug]

Hi JLCIOT, and sorry for the late reply.

Unfortunately, replies to very old cases have a tendency to be missed.

The PR with the fix (which I linked to in my previous reply) was merged August 6th, 2021, and has been part of all NCS versions starting from v1.7.0.

Best regards,

Didrik