locking: warn about clock skew only when there actually is skew, see #9870

The stale-veto path warned unconditionally, but a veto is not by itself
evidence of skew: after a suspend, our store "now" estimate lags (monotonic
clock stood still), so a genuinely stale foreign lock of a perfectly synced
client gets vetoed and produced a bogus "clock skew of ~0s" warning. The
per-listing skew check in _get_locks already covers the vetoed lock with a
proper magnitude gate, so the veto-path warning (and with it the optional-skew
calling convention of _warn_clock_skew) can just go away.

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

src/borg/storelocking.py

@@ -166,14 +166,12 @@ class Lock:
         offset_other = lock["dt"].timestamp() - lock["mtime"]
         return offset_other - offset_self
 
-    def _warn_clock_skew(self, lock, skew=None):
+    def _warn_clock_skew(self, lock, skew):
         if self.skew_warned:
             return
         self.skew_warned = True
-        skew = skew if skew is not None else self._mutual_skew(lock)
-        skew_info = f" of ~{abs(skew):.0f}s" if skew is not None else ""
         logger.warning(
-            f"Clock skew{skew_info} detected between this machine and the borg client on "
+            f"Clock skew of ~{abs(skew):.0f}s detected between this machine and the borg client on "
             f"{lock['hostid']!r} (also using this repository). "
             f"The clocks of machines sharing a repository should be synchronized (e.g. via NTP)."
         )
@@ -221,10 +219,11 @@ class Lock:
                     logger.debug(f"LOCK-STALE: lock looks stale, deferring until store time is known. lock: {lock}.")
                     return False
                 if store_now <= lock["mtime"] + self.stale_td.total_seconds():
-                    # the store saw this lock object being written recently: it is NOT stale,
-                    # its writer's clock is just skewed against ours. never kill it!
-                    self._warn_clock_skew(lock)
-                    logger.debug(f"LOCK-STALE: lock only looks stale due to clock skew. lock: {lock}.")
+                    # the store saw this lock object being written recently: it is NOT stale.
+                    # either its writer's clock is skewed against ours (the skew check in
+                    # _get_locks warns about that) or our store "now" estimate lags behind
+                    # (e.g. time.monotonic() stood still while we were suspended). never kill it!
+                    logger.debug(f"LOCK-STALE: lock looks stale locally, but not to the store. lock: {lock}.")
                     return False
             # either both clock domains agree that the lock is stale, or the backend can not
             # provide store-side mtimes (mtime == 0) and the content timestamp has to suffice.

src/borg/testsuite/storelocking_test.py

@@ -264,6 +264,22 @@ class TestLock:
         assert not lock.skew_warned
         lock.release()
 
+    def test_no_skew_warning_when_only_our_store_time_lags(self, lockstore):
+        # while we are suspended, time.monotonic() stands still, so our store "now" estimate
+        # lags afterwards. a foreign lock that went genuinely stale meanwhile then gets vetoed
+        # (the safe direction), but that veto is no evidence of clock skew and must not
+        # produce a bogus "clock skew of ~0s" warning, see #9870.
+        lock = Lock(lockstore, exclusive=False, id=ID2)
+        lock.acquire()
+        assert lock.my_lock_mtime is not None  # store time reference was harvested
+        lock.my_lock_monotonic += 45 * 60  # simulate a 45 minute suspend after the anchor
+        dt = datetime.datetime.now(datetime.UTC) - datetime.timedelta(minutes=40)
+        foreign_key = write_raw_lock(lockstore, ID1, exclusive=False, dt=dt, mtime=dt.timestamp())
+        locks = lock._get_locks()
+        assert foreign_key in locks  # genuinely stale, but vetoed: store "now" lags behind
+        assert not lock.skew_warned  # the writer's clock is not skewed - no warning
+        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