diff --git a/src/fscacher/cache.py b/src/fscacher/cache.py index e775859..855d9c1 100644 --- a/src/fscacher/cache.py +++ b/src/fscacher/cache.py @@ -209,7 +209,7 @@ def from_stat(cls, s): return cls(s.st_mtime_ns, s.st_ctime_ns, s.st_size, s.st_ino) def modified_in_window(self, min_dtime): - return abs(time.time() - self.mtime_ns * 1e-9) < min_dtime + return abs(elapsed_since(self.mtime_ns * 1e-9)) < min_dtime def to_tuple(self): return tuple(self) @@ -236,7 +236,7 @@ def modified_in_window(self, min_dtime): if self.last_modified is None: return False else: - return abs(time.time() - self.last_modified * 1e-9) < min_dtime + return abs(elapsed_since(self.last_modified * 1e-9)) < min_dtime def to_tuple(self): if self.hash is None: @@ -250,3 +250,13 @@ def xor_bytes(b1: bytes, b2: bytes) -> bytes: i1 = int.from_bytes(b1, sys.byteorder) i2 = int.from_bytes(b2, sys.byteorder) return (i1 ^ i2).to_bytes(length, sys.byteorder) + +def elapsed_since(t: float) -> float: + t_now = time.time() + dt = t_now - t + if dt < 0: + lgr.debug( + "Time is in the future: %f; now: %f; dt=%g", + t, t_now, dt + ) + return dt diff --git a/src/fscacher/tests/test_cache.py b/src/fscacher/tests/test_cache.py index 86bb8b5..a01efc0 100644 --- a/src/fscacher/tests/test_cache.py +++ b/src/fscacher/tests/test_cache.py @@ -15,6 +15,9 @@ on_windows = platform_system == "windows" on_pypy = platform.python_implementation().lower() == "pypy" +import logging +lgr = logging.getLogger(__name__) + @pytest.fixture(autouse=True) def capture_all_logs(caplog): @@ -207,7 +210,12 @@ def check_new_memoread(arg, content, expect_new=False): except AssertionError: # pragma: no cover # if computer is indeed slow (happens on shared CIs) we might fail # because distance is too short - if time.time() - t0 < cache._min_dtime: + t_now = time.time() + if t_now - t0 < cache._min_dtime: + # Log more information to troubleshoot + lgr.error(f"Failing test with t0={t0}, t_now={t_now}, dt={t_now - t0}, min_dtime={cache._min_dtime}") + for p in ("a.txt", "b.txt"): + lgr.error(f" {p}: {op.getmtime(path / p)}") raise # if we were quick but still failed -- legit assert calls[-1] == [path, 0, None]