int32 milliseconds overflow when time difference is over 24 days

[mcbp223]

It seems I had the snapserver turned on for a long time, and now the time difference between server and client overflows when calculated in milliseconds, 2^31 / 1000 / 3600 / 24 = 24.855 134 81. This can be overcome by calling settimeofday(...) when appropriate.

I'm experimenting with the following:

• changed the return of SnapTime::toMillis(timeval) and SnapTime::timeDifferenceMs(...) from uint32_t to int64_t.

int64_t toMillis(timeval tv) { return int64_t(tv.tv_sec) * 1000 + (tv.tv_usec / 1000); }

• in SnapProcessor::processMessageTime() I call 'settimeofday()' instead of assert, the part after the trx assignment is

    int64_t time_diff = snap_time.timeDifferenceMs(trx, ttx);

  #if 1 && LOG_LOCAL_LEVEL >= ARDUHAL_LOG_LEVEL_INFO
    char buf[64];
    strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", localtime(&ttx.tv_sec));
    LOGI("time srv: %s.%06d", buf, ttx.tv_usec);
    strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", localtime(&trx.tv_sec));
    LOGI("time cli: %s.%06d\tdiff: %lldms", buf, trx.tv_usec, time_diff);
  #endif

    // for time management
    snap_time.updateServerTime(trx);
    // for synchronization
    p_snap_output->snapTimeSync().updateServerTime(snap_time.toMillis(trx));

    int32_t time_diff_int = time_diff;
    //assert(time_diff_int == time_diff);
    if(time_diff_int != time_diff) {
      LOGE("int32 time overflow %d != %lld", time_diff_int, time_diff);
      settimeofday(&ttx, NULL);
    }
    ESP_LOGD(TAG, "Time Difference to Server: %lld ms", time_diff);
    snap_time.setTimeDifferenceClientServerMs(time_diff);

    return true;

The log when set to show the time difference is:

[I] SnapProcessor.h : 485 - time srv: 1970-03-02 02:38:33.168752
[I] SnapProcessor.h : 487 - time cli: 1970-01-01 00:00:07.602949        diff: -5193505566ms
[E] SnapProcessor.h : 498 - int32 time overflow -898538270 != -5193505566

There's also a detail that can easily be overlooked, the printf format for int64_t is %lld with double 'l`.

[pschatzmann]

Interesting: I am usually shutting down my client when I don't use it.
Can you provide a pull request ?

[mcbp223]

Same here, the client gets shut down every time I recompile and upload a new firmware, it's the server that's kept running for a long time.

I'm not sure yet what to do in a pull request, either convert all millisecond times to int64, or keep them int32 for small lags and store the large time difference between client and server in one place, to use it when translating server time.
If stored in one place, for ESP32 we can call settimeofday(...) which in turn calls esp_time_impl_set_boot_time(uint64_t) that stores the 64-bit value in two 32-bit processor registers, RTC_BOOT_TIME_LOW_REG and RTC_BOOT_TIME_HIGH_REG. However the call is protected by a multithread lock, not sure but it can be costly when called every second. To be more generic and for cases where the framework doesn't provide the time of day functions, you can store it in a variable, probably you already do, that if called from only one thread doesn't need to be mutex protected.

I believe that this time difference must be updated at every server reply to a Time message from client, this would make it at a rate of about once every second from what I see on the logs. In between these updates it's considered that the client time and the server time are synchronized, so the packets can be scheduled to be played at the server time indicated in each WireChunk message.

[pschatzmann]

OK, I thought you already solved the issue.
I will move this to the issues, so that I don't forget it...