Time() irregularities

[0xffff]

For testing I have a simple application that generates sequential pings every few seconds and posts them via mqtt to a server. I disconnect the system from the internet every 2 minutes for 2 minutes to test how the system handles it. Note the following from the log entries:

Code: Select all

[2018-07-25T03:08:47.110] [ALL] USB - I (10859206) publish: time: 1532488169, type: ping.mqtt, value: 1825.000000
[2018-07-25T03:08:50.691] [ALL] USB - I (10862790) publish: time: 1532488173, type: ping.mqtt, value: 1826.000000
[2018-07-25T03:08:54.278] [ALL] USB - I (10866374) publish: time: 1532488177, type: ping.mqtt, value: 1827.000000
[2018-07-25T03:08:57.763] [ALL] USB - I (10869855) publish: time: 1532488180, type: ping.mqtt, value: 1828.000000
[2018-07-25T03:09:01.239] [ALL] USB - I (10873337) publish: time: 1532488184, type: ping.mqtt, value: 1829.000000
[2018-07-25T03:09:04.825] [ALL] USB - I (10876921) publish: time: 1532488187, type: ping.mqtt, value: 1830.000000
[2018-07-25T03:09:08.313] [ALL] USB - I (10880402) publish: time: 1532488147, type: ping.mqtt, value: 1831.000000
[2018-07-25T03:09:11.890] [ALL] USB - I (10883987) publish: time: 1532488151, type: ping.mqtt, value: 1832.000000
[2018-07-25T03:09:15.477] [ALL] USB - I (10887570) publish: time: 1532488154, type: ping.mqtt, value: 1833.000000
[2018-07-25T03:09:19.163] [ALL] USB - I (10891257) publish: time: 1532488158, type: ping.mqtt, value: 1834.000000
[2018-07-25T03:09:22.747] [ALL] USB - I (10894841) publish: time: 1532488162, type: ping.mqtt, value: 1835.000000
[2018-07-25T03:09:26.334] [ALL] USB - I (10898425) publish: time: 1532488165, type: ping.mqtt, value: 1836.000000
[2018-07-25T03:09:29.813] [ALL] USB - I (10901906) publish: time: 1532488169, type: ping.mqtt, value: 1837.000000

Specifically, time is advancing normally until ping.mqtt value 1830, after which it goes back by about 40 seconds. I suspect it may have to do with the timer re-syncing with NTP servers, but not sure how to get that information definitively. On startup, I do the following:

Code: Select all

bool init_time()
{
	struct tm timeinfo;
	long int gmt_offset_sec = 25200;
	int dst_offset_sec = 0;

	configTime( gmt_offset_sec, dst_offset_sec , "pool.ntp.org" );

	xEventGroupWaitBits(relevant_events,BIT_WIFI_READY,pdFALSE,pdFALSE,portMAX_DELAY);
	if( !getLocalTime( &timeinfo, 5000 ) ) {
		ESP_LOGW( __func__, "time acquisition failed, try again..." );
		return false;
	} else {
		ESP_LOGW( __func__, "...got time" );
		xEventGroupSetBits(relevant_events,BIT_HAVE_TIME);
		return true;
	}
}

I have configured timer in sdkconfig with:

Code: Select all

CONFIG_ESP32_TIME_SYSCALL_USE_RTC=y
CONFIG_ESP32_RTC_CLOCK_SOURCE_INTERNAL_RC

Note that previously I was using CONFIG_ESP32_TIME_SYSCALL_USE_RTC_FRC1 but after reboot time would go backwards so I changed it to use only RTC based upon advice in this forum, although I was using an older esp-idf version, and I did not notice this problem. It's possible that it may have surfaced after I updated to the latest esp-idf. I can regress to double-check - but mainly looking for clues as to what's going on and how to prevent it.

[0xffff]

BTW, this problem only manifested in master - after regressing to version 3.0.1 it no longer appeared