Merge pull request #98 from yarikoptic/enh-time-diff

Log when file timestamp unexpectedly in the future + more information in the failing test_memoize_path_dir

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

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]