locking: warn if the storage's clock jumps between two of our lock writes, see #9870

When the mtime of a freshly created lock object is harvested, compare it with
what the previous anchor extrapolates for that instant: if our own wall and
monotonic clocks agree about the elapsed time (no suspend, no local clock step)
but the storage's mtimes do not, the storage's clock jumped. Warn once.
Diagnostic only - a backward step larger than the stale timeout can defeat the
store-domain cross-check in _is_stale_lock (documented residual risk); this at
least names the cause when a vanished lock gets investigated.

Co-Authored-By: Claude Fable 5 <[email protected]>

docs/internals/data-structures.rst

@@ -1198,7 +1198,9 @@ expired by age if it looks stale in both clock domains:
   store "now" is computed from the mtime of our own lock object plus the
   monotonic time elapsed since we created it, so this comparison stays
   entirely within the storage's clock domain - neither the clients' nor the
-  storage's absolute clock error matters.
+  storage's absolute clock error matters. the storage's clock should run
+  steadily, though: borg warns if it detects that it jumped between two of
+  its own lock writes.
 
 Store-side mtimes are advisory only: they can veto an expiry, but they can
 never cause one on their own, so a hostile or broken store gains no new

src/borg/storelocking.py

@@ -93,7 +93,9 @@ class Lock:
         # together let us compute the current time in the store's clock domain, see _store_now().
         # it deliberately outlives its lock object: the calibration stays valid after deletion.
         self.my_lock_anchor = None
+        self.prev_lock_anchor = None  # the anchor before the current one, see _check_store_clock_step()
         self.skew_warned = False  # emit the clock-skew warning only once per Lock instance
+        self.store_clock_step_warned = False  # emit the storage-clock-step warning only once per Lock instance
         self.id = id or platform.get_process_id()
         assert len(self.id) == 3
         logger.debug(f"LOCK-INIT: initializing. store: {store}, stale: {stale}s, refresh: {stale // 2}s.")
@@ -127,6 +129,7 @@ class Lock:
             # the store-side mtime of the new lock object is not known yet - it is harvested
             # from the next locks listing. anchor the monotonic clock at creation time so the
             # harvested mtime can be extrapolated to "now" later, see _store_now().
+            self.prev_lock_anchor = self.my_lock_anchor
             self.my_lock_anchor = LockAnchor(key, self.last_refresh_dt, None, time.monotonic())
         return key
 
@@ -191,6 +194,31 @@ class Lock:
             f"The clocks of machines sharing a repository should be synchronized (e.g. via NTP)."
         )
 
+    def _check_store_clock_step(self, anchor, mtime):
+        """
+        Warn (once) if the storage's clock jumped between the writes of our previous and our current
+        lock object: compare the new object's store-side mtime with what the previous anchor
+        extrapolates for the new object's creation instant. Diagnostic only: a backward step larger
+        than the stale timeout can defeat the store-domain cross-check in _is_stale_lock (see there),
+        this at least names the cause.
+        """
+        prev = self.prev_lock_anchor  # single read - it gets replaced atomically as a whole
+        if prev is None or prev.mtime is None or self.store_clock_step_warned:
+            return
+        elapsed_monotonic = anchor.monotonic - prev.monotonic
+        elapsed_wall = (anchor.dt - prev.dt).total_seconds()
+        if abs(elapsed_wall - elapsed_monotonic) > MAX_MUTUAL_CLOCK_SKEW:
+            # our own two clocks disagree about the elapsed time (suspend: time.monotonic() stood
+            # still, or our wall clock was stepped): then we can not judge the storage's clock.
+            return
+        step = (mtime - prev.mtime) - elapsed_monotonic
+        if abs(step) > MAX_MUTUAL_CLOCK_SKEW:
+            self.store_clock_step_warned = True
+            logger.warning(
+                f"The clock of the repository storage jumped by ~{step:+.0f}s between two lock writes of ours. "
+                f"Storage clock steps interfere with stale lock detection, the storage's clock should run steadily."
+            )
+
     def _check_clock_skew(self, locks):
         """Warn (once) if another current lock writer's clock is skewed against ours."""
         if self.skew_warned:
@@ -277,6 +305,9 @@ class Lock:
             mtime = locks[my_key]["mtime"]
             anchor = self.my_lock_anchor
             if mtime and anchor is not None and anchor.key == my_key:
+                if anchor.mtime is None:
+                    # first harvest for this anchor: cross-check the storage clock's continuity.
+                    self._check_store_clock_step(anchor, mtime)
                 self.my_lock_anchor = anchor._replace(mtime=mtime)
         for key in list(locks):
             if self._is_stale_lock(locks[key]):

src/borg/testsuite/storelocking_test.py

@@ -144,6 +144,7 @@ class TestLock:
         new_keys = set(lock._get_locks())
         assert len(old_keys) == len(new_keys) == 1
         assert old_keys != new_keys  # refresh done, new lock has different key
+        assert not lock.store_clock_step_warned  # the storage clock ran steadily, no warning
         lock.release()
 
     def test_refresh_killed_lock(self, lockstore):
@@ -308,6 +309,21 @@ class TestLock:
         assert foreign_key in lock._get_locks()  # survived: judged with the fresh anchor
         lock.release()
 
+    def test_storage_clock_step_warning(self, lockstore):
+        # when the mtime of a freshly created lock object is harvested, it is compared with what the
+        # previous anchor extrapolates for that instant: a mismatch means the storage's clock jumped
+        # between the two writes (simulated here by a previous anchor whose mtime is 1h ahead), see
+        # #9870. diagnostic only, but it names the cause of a defeated stale-lock cross-check.
+        lock = Lock(lockstore, exclusive=False, id=ID2)
+        lock.acquire()
+        anchor = lock.my_lock_anchor
+        assert anchor.mtime is not None
+        lock.my_lock_anchor = anchor._replace(mtime=anchor.mtime + 3600)  # as if the storage clock stepped back 1h
+        lock.last_refresh_dt -= lock.refresh_td + datetime.timedelta(seconds=1)  # make refresh() act now
+        lock.refresh()  # creates a new lock object and harvests its mtime: the step is detected
+        assert lock.store_clock_step_warned
+        lock.release()
+
     def test_skew_warning_during_exclusive_acquire(self, lockstore):
         # an exclusive acquirer must warn about a skewed peer it sees while (unsuccessfully)
         # waiting for the peer's healthy shared lock to go away: the listing that would satisfy