Strange time behaviour after restart (IDFGH-11996)

damian-kurek-wizzdev commented 7 months ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

I have a fleet of around 250k devices (esp32/esp32s3) connected to the internet and synchronized via NTP. Last week I made an update that updated around 40k of them. In this update, I changed esp-idf from 4.4.3 and added a check to assume that the device is synchronized after restart if it stores the time on the device is larger than 01.01.2024. After some time I noticed that for around 20% of the devices(around 8k), timestamps are messed up by up to +/- 8 hours. When I tested it with a few dev boards + and a few devices I never observed this issue. What is the expected behaviour of the system clock when you restart the esp. When restarting esp it is powered on all the time.

I get time using this code:

int64_t getCurrentSystemClockTimestampMs()
{
    struct timeval currentTime = {};
    gettimeofday(&currentTime, nullptr);
    int64_t millis = static_cast<int64_t>(currentTime.tv_sec) * 1000 + (currentTime.tv_usec / 1000);
    return millis;
}

AxelLin commented 6 months ago

@damian-kurek-wizzdev Do you mean it works with esp-idf-4.3.3 but has issue with newer esp-idf version? Which version (git describe --tags output) is used when the issue happened? @KonstantinKondrashov Any update?

damian-kurek-wizzdev commented 6 months ago

@AxelLin I forget to add this 4.4.3 to 5.1.1. I am not sure if it happened on the earlier idf version.

KonstantinKondrashov commented 6 months ago

Hi @damian-kurek-wizzdev! Sorry for the delay. Yes, before a restart, ESP preserves the system time in RTC memory. It will not be reset. Based on your description you do not get it reset, the time is not correct up to +/- 8 hours. There is a function that is called before restart to sync time (RTC timer and esp_timer) - https://github.com/espressif/esp-idf/blob/master/components/newlib/port/esp_time_impl.c#L131. Maybe this function is not called for some reason:

At startup, a callback function that uses esp_register_shutdown_handler() was not ok - then I should see this error at startup esp - "Register shutdown handler failed, err = 0x"
The restart was not finished correctly and the esp_sync_timekeeping_timers() was not called.

Additionally, the character of the issue might say that there is a timezone involved (if you use these functions to calc time diff). We do not save the timezone anywhere.

    setenv("TZ", "CST-8", 1);
    tzset();
    time(&now);

AxelLin commented 6 months ago

@damian-kurek-wizzdev

Just want to clarify if the +/- 8 hours is related to timezone. What is your current timezone setting?

damian-kurek-wizzdev commented 6 months ago

@AxelLin sorry I did not have time to look into it again, but It wasn't 8 hours flat it was something like 8:23. I asked my devops to get it from the database. Additionally, sometimes it was 8:xx and sometimes 4:yz

damian-kurek-wizzdev commented 6 months ago

-54 years was lack of synchronization for some reason (I did a bit later). But there you can see the time difference. The difference shows time difference between device and server time "0f026bbc-958c-4eb7-afb3-3901ad527483" "-01:11:47.875" "16c199b2-f9e7-40e4-99d5-f96ea9983eac" "02:23:47.6" "17b5e75d-6c56-43ce-bb93-808746163e81" "-54 years -15 days -05:43:08.2" "22fe0009-22d3-4338-a387-60424421eab8" "-01:02:57.9375" "281bf913-a910-4a5f-81a2-0ec3ab6b3a7c" "-02:10:41.75" "39fe62d2-836b-4de7-a5d4-a80cd8db771c" "-01:07:19.483333" "42a5cc04-abfe-448c-b7f7-cbcbe25ae3b7" "-54 years -15 days -04:37:37.863014" "6f81463e-0f9d-41c4-bce4-6c5e0afeff02" "-01:08:02.05814" "a36c32d5-13a6-45e1-a2fb-caf1b4cd97d6" "-01:44:36.837209" "b4198da8-8eb1-418d-b153-e48da429eca1" "-01:04:21.074074" "ba514624-bf60-4a24-a9ee-63059e93a9b9" "-54 years -15 days -07:24:28" "ba55394d-66c6-4cf1-933a-6397caba9a2f" "-54 years -15 days -04:16:59" "ccfb39ae-e9bb-42cb-a5aa-94194156fe79" "03:16:32.678571" "ce06f6ce-40fc-4eb7-bf64-6ba81af6d980" "-54 years -15 days -05:49:07.892857" "038fc4a2-3423-47a0-b78d-5153de6a1a8c" "-01:02:22" "1ea2cef6-da80-44f2-8165-609b2094209c" "-01:01:43" "3b3d63e4-f303-4891-a8cd-efc276b1c14d" "-02:07:41.363636" "53908f70-5b7d-4f2b-bfe4-a7990594b5c7" "-01:59:55.571429" "72667764-5a20-4296-b072-e250affc8fde" "-01:11:02.2" "7a7da80c-4123-4195-b6b0-c3f8d20951cf" "-01:37:25" "7e74a903-f5c0-4bbd-b878-2aec361e1ba9" "-02:03:40.625" "81c32457-23a7-47f1-85eb-47e6d069eef5" "-02:04:14.26087" "8a4762e1-0928-4cd5-a803-09c0c9c0c87d" "-01:57:17.285714" "9255a54d-59f0-4c4e-9397-5e00b075b3f7" "-02:05:54.444444" "a21dc431-c7b6-45ea-8b85-6a8f4bfce5f2" "-02:21:44.8" "a45f64ea-8c92-45b9-a365-07d93956c8a6" "-01:43:18.789474" "b40d1fa4-a39c-4363-b389-712707b8e1b3" "-01:58:41.5" "baa8ee16-7fb7-405b-a664-9afabeb704fb" "-02:07:01.545455" "d57dfda3-0d16-4132-8043-dede80ad56ed" "-01:00:19" "da432b29-90d0-4f84-9948-f1241f58b72e" "-02:14:14.333333" "e6ccc88b-e38b-46bc-bcee-32d19e602fc3" "-02:15:16.214286" "eabef1ae-4f0c-476e-94ff-2bd51a33315a" "-02:07:53.833333"

AxelLin commented 3 months ago

@KonstantinKondrashov Any feedback about the symptom reported by https://github.com/espressif/esp-idf/issues/13066#issuecomment-1985258949 ?

espressif / esp-idf

Strange time behaviour after restart (IDFGH-11996) #13066

Answers checklist.

General issue report