Clock instance does not appear to handle rollover on ESP-IDF

[devunwired]

The time retrieval function for Clock::now() relies on the platform-defined function mocpp_tick_ms(). For ESP-IDF, this function is defined as follows:

unsigned long mocpp_tick_ms_espidf() {
    auto ticks_now = xTaskGetTickCount();
    MicroOcpp::mocpp_millis_count += ((ticks_now - MicroOcpp::mocpp_ticks_count) * 1000UL) / configTICK_RATE_HZ;
    MicroOcpp::mocpp_ticks_count = ticks_now;
    return MicroOcpp::mocpp_millis_count;
}

While the frequency of xTaskGetTickCount() is configurable (defaults to 1000), on the Xtensa architecture unsigned long and TickType_t are both defined as 32-bits. This means that, regardless of the tick counter configuration, a value like mocpp_millis_count will overflow after ~49.7 days of continuous operation.

Clock::now() does not account for this rollover and simply calculates the difference, allowing a potentially negative time difference to be applied to the internal clock.

[razvanphp]

Good catch, I think I saw some strange times from the future in our logs and was wondering what's wrong. Can you write a unit test for it? The we can do some TDD to fix it. I'm also doing the same with all the bugs we are finding and fixing for the certification.

Just hope @matth-x will come back online to approve and merge the PRs, or otherwise find some other maintainers who can do that so project goes forward.

[devunwired]

@razvanphp indeed that's what we are seeing as well. Timestamps are periodically jumping forward 49,250s (~12hrs) for a short period and then returning back to normal. Upon further examination, I'm not certain it's the rollover I mentioned initially. In general, the unsigned arithmetic appears to handle tick counter rollover properly and presents the correct tick difference (e.g. 0x00000000 - 0xFFFFFFFF = 1). We are seeing this behavior even if the device has only been active for a few minutes.

However, there is still an overflow in the following calculation: ((ticks_now - MicroOcpp::mocpp_ticks_count) * 1000UL). If the tick difference multiplied by 1000 is too large to fit in a uint32_t the result is truncated. For example, running this code with the maximum possible tick difference of 4,294,967,295 produces the magic difference of 49,250s applied to the timestamp in Clock::now().

I still haven't quite managed to bring this to the root cause. Need to understand what condition could cause the tick counter to generate such an overflow at seemingly random times.