From 67e084cdf0a2829018c179ffcecdfd1796acd72e Mon Sep 17 00:00:00 2001
From: Yaroslav Halchenko <debian@onerussian.com>
Date: Mon, 18 Nov 2024 18:52:59 -0500
Subject: [PATCH 1/2] ENH: add logging information on when check in
 test_memoize_path_dir fails

---
 src/fscacher/tests/test_cache.py | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

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]
 

From b1032ad16aa1a70e118fba8276c0c90d694cf066 Mon Sep 17 00:00:00 2001
From: Yaroslav Halchenko <debian@onerussian.com>
Date: Mon, 18 Nov 2024 18:45:10 -0500
Subject: [PATCH 2/2] ENH: log (at debug) cases where file time stamp is in the
 future

It might be able to provide explanation for a flaky test observed on debian
build systems etc: https://github.com/con/fscacher/issues/55
---
 src/fscacher/cache.py | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

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