diff --git a/docs/internals/data-structures.rst b/docs/internals/data-structures.rst index 38cfa5add..d5a6094a3 100644 --- a/docs/internals/data-structures.rst +++ b/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 diff --git a/src/borg/storelocking.py b/src/borg/storelocking.py index 9aa158b49..b850f4cf2 100644 --- a/src/borg/storelocking.py +++ b/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]): diff --git a/src/borg/testsuite/storelocking_test.py b/src/borg/testsuite/storelocking_test.py index 226bc510c..90c3713cd 100644 --- a/src/borg/testsuite/storelocking_test.py +++ b/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