Timestamp rounding bug?

[Grumium]

Hi,
I am simply using the "Time 4" command to obtain a timestamp with millisecond resolution.
tasmota.cmd("Time 4",true)["Time"]
I take this string and I am publishing it via MQTT. Below, I posted a snippet of the output in the web console to showcase my problem. Please take a look at the timestamps printed in bold. I am running Tasmota 14.2.0 on an ESP32.
I doubt this is intentional, but I wanted to discuss with you first, before opening an issue.
Thank you for your support!

16:05:45.041 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:05:45.027"}
16:05:46.017 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:05:46.004"}
16:05:47.018 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:05:47.003"}
16:05:48.013 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:05:47.000"}
16:05:49.009 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:05:48.996"}
16:05:50.007 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:05:49.993"}
(...)
16:06:00.015 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:00.002"}
16:06:01.010 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:00.996"}
16:06:02.019 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:02.006"}
16:06:03.025 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:03.012"}
16:06:04.272 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:04.258"}
16:06:05.021 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:05.009"}
16:06:06.022 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:06.009"}
16:06:07.014 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:06.000"}
16:06:08.020 MQT: test/nrt_tele/SENSOR = {"Time":"2024-10-23T16:06:08.008"}

[s-hadinger]

Nice one. I'm surprised it happens so often. Are you doing the command at specific time? Using cron?

[Grumium]

I am triggering it in a berry driver with every_second().
I do not trigger it at specific times. It's just coincidence that it sometimes hits the exact millisecond.

[arendst]

It's a simple "bug/feature". As time is is second based I had to add a seperate milisecond counter. This one is hard to sync with the second interrupt without forced missed milliseconds. If you find a beter way, pls provide one. The code is in support_rtc.ino

[Grumium]

The following code solves the problem for ~90% of the cases

String GetDateAndTime(uint8_t time_type) {
  // "2017-03-07T11:08:02-07:00" - ISO8601:2004
  uint32_t time_millis = RtcMillis();
  uint32_t time = Rtc.local_time;
  switch (time_type) {
    case DT_UTC:
      time = Rtc.utc_time;
      break;
//    case DT_LOCALNOTZ:  // Is default anyway but allows for not appendig timezone
//      time = Rtc.local_time;
//      break;
    case DT_DST:
      time = Rtc.daylight_saving_time;
      break;
    case DT_STD:
      time = Rtc.standard_time;
      break;
    case DT_RESTART:
      if (Rtc.restart_time == 0) {
        return "";
      }
      time = Rtc.restart_time;
      break;
    case DT_BOOTCOUNT:
      time = Settings->bootcount_reset_time;
      break;
  }
  String dt = GetDT(time);  // 2017-03-07T11:08:02

  if (DT_LOCAL_MILLIS == time_type) {
    char ms[10];
    if (time_millis == 0) {
      dt = GetDT(time+1);
    }
    snprintf_P(ms, sizeof(ms), PSTR(".%03d"), time_millis);
    dt += ms;               // 2017-03-07T11:08:02.123
    time_type = DT_LOCAL;
  } 

However, at the position of the red arrow, it still didn't work,

and the system timestamps are also not correct, but this handled elsewhere, I think:

Tasmota/tasmota/tasmota_support/support.ino

Lines 2603 to 2604 in 0f2b3b1

	snprintf_P(mxtime, sizeof(mxtime), PSTR("%02d" D_HOUR_MINUTE_SEPARATOR "%02d" D_MINUTE_SECOND_SEPARATOR "%02d.%03d"),
	RtcTime.hour, RtcTime.minute, RtcTime.second, RtcMillis());

[Jason2866]

The code size increase should kept small. It is just an information time stamp.

[Grumium]

The code size increase should kept small. It is just an information time stamp.

For the log, I agree, but for sensor data, timestamp duplicates and not monotonically increasing timestamps are not just a cosmetic flaw. And so far it is just one additional variable. There is no major increase in code size.

As a workaround to all of this, I will probably delay the start of my driver with tasmota.cmd("delay -1",true) and set a timer with ~100 ms for the subsequent tasks so that I am always in the safe zone with the timestamp.

def every_second()
    tasmota.set_timer(100, /-> <func> )
end

But I still hope this will be solved.

[s-hadinger]

Thanks. Let me have a look

[Grumium]

Thank you!

I did spend quite some time now on investigating this. Actually, minimizing the desync is not really advantageous, I am afraid. Surprisingly, I am getting the same 90% success rate with the following adjustment only.

  if (DT_LOCAL_MILLIS == time_type) {
    char ms[10];
    uint32_t time_millis = RtcMillis();
    if (time_millis == 0) {
      dt = GetDT(time+1);
    }
    snprintf_P(ms, sizeof(ms), PSTR(".%03d"), time_millis);
    dt += ms;               // 2017-03-07T11:08:02.123
    time_type = DT_LOCAL;
  }

I would explain this as follows: time is defined above the conditional statements, thus calling RTCMillis() and testing for time_millis == 0 'as late as possible' yields quite stable results, since we stay away from the tipping point, i.e., when time is not longer equal to the true local time.