[core] Fix FormatTimeSys rendering the same timestamp inconsistently (#3225)

srtcore/sync.cpp

@@ -60,21 +60,61 @@ std::string FormatTime(const steady_clock::time_point& timestamp)
     return out.str();
 }
 
-std::string FormatTimeSys(const steady_clock::time_point& timestamp)
+SysClockReference::SysClockReference()
 {
-    const time_t                   now_s         = ::time(NULL); // get current time in seconds
-    const steady_clock::time_point now_timestamp = steady_clock::now();
-    const int64_t                  delta_us      = count_microseconds(timestamp - now_timestamp);
-    const int64_t                  delta_s =
-        static_cast<int64_t>(floor((static_cast<double>(count_microseconds(now_timestamp.time_since_epoch()) % 1000000) + delta_us) / 1000000.0));
-    const time_t tt = now_s + delta_s;
-    struct tm    tm = SysLocalTime(tt); // in seconds
-    char         tmp_buf[512];
-    strftime(tmp_buf, 512, "%X.", &tm);
+    timeval tv;
+    gettimeofday(&tv, NULL);
+    wall_us   = static_cast<int64_t>(tv.tv_sec) * 1000000 + tv.tv_usec;
+    steady_us = count_microseconds(steady_clock::now().time_since_epoch());
+}
 
-    ostringstream out;
-    out << tmp_buf << setfill('0') << setw(6) << (count_microseconds(timestamp.time_since_epoch()) % 1000000) << " [SYST]";
-    return out.str();
+namespace
+{
+    // Map a steady clock timestamp into the wall clock domain (microseconds
+    // since the Unix epoch) using a single, microsecond-precision clock
+    // reference sampled at one instant. The previous implementation combined
+    // whole-second wall time (::time) with sub-second steady time, whose
+    // sub-second phases are unrelated; near a second boundary this made the
+    // very same timestamp render with a +/-1 second difference between calls
+    // (see issue #3225).
+    int64_t ToSysTimeMicroseconds(const steady_clock::time_point& timestamp, const SysClockReference& rf)
+    {
+        return rf.wall_us + (count_microseconds(timestamp.time_since_epoch()) - rf.steady_us);
+    }
+
+    // Format a wall clock time (microseconds since the Unix epoch) as
+    // HH:MM:SS.us [SYST].
+    std::string FormatSysTimeMicroseconds(int64_t wall_us)
+    {
+        const time_t  tt        = static_cast<time_t>(wall_us / 1000000);
+        const int64_t subsec_us = wall_us % 1000000;
+
+        struct tm tm = SysLocalTime(tt); // in seconds
+        char      tmp_buf[512];
+        strftime(tmp_buf, 512, "%X.", &tm);
+
+        ostringstream out;
+        out << tmp_buf << setfill('0') << setw(6) << subsec_us << " [SYST]";
+        return out.str();
+    }
+}
+
+std::string FormatTimeSysInternal(const steady_clock::time_point& timestamp, const SysClockReference& rf)
+{
+    return FormatSysTimeMicroseconds(ToSysTimeMicroseconds(timestamp, rf));
+}
+
+std::string FormatTimeSys(const steady_clock::time_point& timestamp)
+{
+    // A single clock reference, sampled once on first use. Using a fixed
+    // reference (rather than re-sampling on every call) guarantees that the
+    // same steady timestamp always renders to exactly the same wall-clock
+    // string. Re-sampling would reintroduce jitter: gettimeofday() and
+    // steady_clock::now() are read non-atomically, so their offset wobbles by
+    // ~1us between calls, which is enough to flip the last printed digit (and,
+    // in the old code, a whole second near a boundary - see issue #3225).
+    static const SysClockReference s_sys_clock_ref;
+    return FormatTimeSysInternal(timestamp, s_sys_clock_ref);
 }
 
 

srtcore/sync.h

@@ -879,6 +879,33 @@ std::string FormatTime(const steady_clock::time_point& time);
 /// @returns a string with a formatted time representation
 std::string FormatTimeSys(const steady_clock::time_point& time);
 
+// Exposed for testing purposes only. Not intended for any other use.
+
+/// A steady<->wall clock reference: a sample of both clocks taken at the same
+/// instant, used to map steady clock timestamps into the wall clock domain.
+struct SysClockReference
+{
+    int64_t steady_us; ///< steady clock sample (microseconds since its epoch)
+    int64_t wall_us;   ///< wall clock sample at the same instant (microseconds since Unix epoch)
+
+    /// Samples both clocks at (nearly) the same instant.
+    SysClockReference();
+
+    SysClockReference(int64_t steady, int64_t wall)
+        : steady_us(steady)
+        , wall_us(wall)
+    {
+    }
+};
+
+/// Internal version of FormatTimeSys with the clock reference passed
+/// explicitly, so the steady->wall mapping is pure and can be unit tested
+/// deterministically. Exposed for testing purposes only.
+/// @param [in] time steady clock timepoint to format
+/// @param [in] rf   steady<->wall clock reference to map the timepoint with
+/// @returns a string with a formatted time representation
+std::string FormatTimeSysInternal(const steady_clock::time_point& time, const SysClockReference& rf);
+
 enum eDurationUnit {DUNIT_S, DUNIT_MS, DUNIT_US};
 
 template <eDurationUnit u>

test/test_sync.cpp

@@ -793,4 +793,45 @@ TEST(Sync, FormatTimeSys)
 
     EXPECT_TRUE(time1 == time2);
 }
+
+// Regression test for issue #3225: FormatTimeSys must render the very same
+// steady-clock timestamp identically regardless of when it is called. The old
+// implementation mixed whole-second wall time with sub-second steady time, whose
+// sub-second phases are unrelated, so near a second boundary the same timestamp
+// could render 1 second apart. This test drives FormatTimeSysInternal with
+// explicit clock references across a range of "now" samples that repeatedly
+// cross both the steady and the wall second boundaries (using deliberately
+// different sub-second phases for the two clocks), and asserts the output is
+// stable.
+TEST(Sync, FormatTimeSysStable)
+{
+    // Fixed target timestamp to format (steady clock, microseconds since epoch).
+    const int64_t target_us = 42 * 1000000 + 676394;
+    const steady_clock::time_point target = steady_clock::time_point() + microseconds_from(target_us);
+
+    // Constant offset between the wall clock and the steady clock. Crucially it has
+    // a non-integer-second (0.5 s) sub-second component: a real steady clock counts
+    // from an arbitrary epoch (e.g. boot), so its sub-second phase does not line up
+    // with the wall clock's. That misalignment is exactly what made the old code
+    // (which mixed whole-second wall time with sub-second steady time) render the
+    // same timestamp 1 second apart near a boundary.
+    const int64_t clock_offset_us = INT64_C(1700000000) * 1000000 + 500000; // .5 s phase
+
+    std::string reference;
+    // Sweep "now" across >2 seconds in 50 ms steps, starting off a second boundary
+    // so both clocks' boundaries are crossed while their phases stay misaligned.
+    for (int64_t step_us = 123456; step_us <= 123456 + 2500000; step_us += 50000)
+    {
+        const int64_t steady_now_us = step_us;
+        const int64_t wall_now_us   = steady_now_us + clock_offset_us;
+        const SysClockReference rf(steady_now_us, wall_now_us);
+        const std::string formatted = FormatTimeSysInternal(target, rf);
+
+        if (reference.empty())
+            reference = formatted;
+        else
+            EXPECT_EQ(formatted, reference)
+                << "FormatTimeSys is unstable for a fixed timestamp (steady_now_us=" << steady_now_us << ")";
+    }
+}
 #endif