Merge pull request #1136 from ryanpetrello/cooldown-info-logging

feat(resolver): provide an INFO level summary log for packages that are skipped due to cooldown settings

Author: LalatenduMohanty

e2e/test_bootstrap_cooldown.sh

@@ -59,6 +59,12 @@ if ! find "$OUTDIR/wheels-repo/downloads/" -name 'stevedore-5.3.0*.whl' | grep -
   pass=false
 fi
 
+# The cooldown must have logged that it blocked stevedore version(s).
+if ! grep -q "cooldown blocked .* version(s):" "$OUTDIR/bootstrap-flag.log"; then
+  echo "FAIL (flag): no cooldown enforcement message for stevedore found in log" 1>&2
+  pass=false
+fi
+
 # --- Pass 2: enforce the same cooldown via environment variable (FROMAGER_MIN_RELEASE_AGE) ---
 
 # Wipe output so the second run starts clean.
@@ -82,4 +88,9 @@ if ! find "$OUTDIR/wheels-repo/downloads/" -name 'stevedore-5.3.0*.whl' | grep -
   pass=false
 fi
 
+if ! grep -q "cooldown blocked .* version(s):" "$OUTDIR/bootstrap-envvar.log"; then
+  echo "FAIL (envvar): no cooldown enforcement message for stevedore found in log" 1>&2
+  pass=false
+fi
+
 $pass

e2e/test_bootstrap_cooldown_gitlab.sh

@@ -75,4 +75,10 @@ if ! grep -q "GitLabTagProvider" "$OUTDIR/bootstrap.log"; then
   pass=false
 fi
 
+# The cooldown must have logged that it blocked python-gitlab version(s).
+if ! grep -q "cooldown blocked .* version(s):" "$OUTDIR/bootstrap.log"; then
+  echo "FAIL: no cooldown enforcement message for python-gitlab found in log" 1>&2
+  pass=false
+fi
+
 $pass

e2e/test_bootstrap_cooldown_prebuilt.sh

@@ -62,4 +62,10 @@ if find "$OUTDIR/sdists-repo/" \( -name 'stevedore*.tar.gz' -o -name 'stevedore*
   pass=false
 fi
 
+# The cooldown must have logged that it blocked stevedore version(s).
+if ! grep -q "cooldown blocked .* version(s):" "$OUTDIR/bootstrap.log"; then
+  echo "FAIL: no cooldown enforcement message for stevedore found in log" 1>&2
+  pass=false
+fi
+
 $pass

e2e/test_bootstrap_cooldown_transitive.sh

@@ -69,4 +69,10 @@ if ! find "$OUTDIR/wheels-repo/downloads/" -name 'pbr-6.1.1*.whl' | grep -q .; t
   pass=false
 fi
 
+# The cooldown must have logged that it blocked pbr version(s).
+if ! grep -q "cooldown blocked .* version(s):" "$OUTDIR/bootstrap.log"; then
+  echo "FAIL: no cooldown enforcement message for pbr found in log" 1>&2
+  pass=false
+fi
+
 $pass

src/fromager/resolver.py

@@ -680,9 +680,6 @@ def is_satisfied_by(self, requirement: Requirement, candidate: Candidate) -> boo
                 )
             return False
 
-        if self.is_blocked_by_cooldown(candidate):
-            return False
-
         return True
 
     def is_blocked_by_cooldown(self, candidate: Candidate) -> bool:
@@ -700,10 +697,9 @@ def is_blocked_by_cooldown(self, candidate: Candidate) -> bool:
                 if candidate.name not in BaseProvider._cooldown_unsupported_warned:
                     BaseProvider._cooldown_unsupported_warned.add(candidate.name)
                     logger.warning(
-                        "%s: release-age cooldown cannot be enforced — upload "
+                        "release-age cooldown cannot be enforced — upload "
                         "timestamp support is not yet implemented for %s; "
                         "cooldown check skipped",
-                        candidate.name,
                         self.get_provider_description(),
                     )
                 return False
@@ -712,8 +708,7 @@ def is_blocked_by_cooldown(self, candidate: Candidate) -> bool:
             # Fail closed: we cannot verify the age of this candidate, so reject it.
             if DEBUG_RESOLVER:
                 logger.debug(
-                    "%s: skipping %s — upload_time unknown, required for cooldown",
-                    candidate.name,
+                    "skipping %s — upload_time unknown, required for cooldown",
                     candidate.version,
                 )
             return True
@@ -727,8 +722,7 @@ def is_blocked_by_cooldown(self, candidate: Candidate) -> bool:
             if DEBUG_RESOLVER:
                 age = self.cooldown.bootstrap_time - candidate.upload_time
                 logger.debug(
-                    "%s: skipping %s uploaded %s ago (cooldown: %s)",
-                    candidate.name,
+                    "skipping %s uploaded %s ago (cooldown: %s)",
                     candidate.version,
                     age,
                     self.cooldown.min_age,
@@ -809,6 +803,17 @@ def find_matches(
                 identifier, requirements, incompatibilities, candidate
             )
         ]
+        # Apply cooldown filtering after specifier/constraint validation
+        blocked = [c for c in candidates if self.is_blocked_by_cooldown(c)]
+        if blocked:
+            for b in blocked:
+                candidates.remove(b)
+            versions = ", ".join(str(b.version) for b in blocked)
+            logger.info(
+                "cooldown blocked %d version(s): %s",
+                len(blocked),
+                versions,
+            )
         if not candidates:
             raise resolvelib.resolvers.ResolverException(
                 self._get_no_match_error_message(identifier, requirements)

tests/test_cooldown.py

@@ -10,7 +10,6 @@
 import pathlib
 import re
 import typing
-from collections import defaultdict
 
 import pytest
 import requests_mock
@@ -117,10 +116,8 @@ def test_cooldown_filters_recent_version(
         candidate = result.mapping["test-pkg"]
         # 2.0.0 is 2 days old (within cooldown); 1.3.2 is 11 days old (outside).
         assert str(candidate.version) == "1.3.2"
-        # 2.0.0 should be logged as skipped; 1.3.2 should not.
-        assert "skipping 2.0.0" in caplog.text
-        assert "cooldown" in caplog.text
-        assert "skipping 1.3.2" not in caplog.text
+        # 2.0.0 should be logged as blocked; 1.3.2 should not appear in the summary.
+        assert "cooldown blocked 1 version(s): 2.0.0" in caplog.text
 
 
 def test_cooldown_disabled_selects_latest() -> None:
@@ -171,17 +168,11 @@ def test_cooldown_rejects_candidate_without_upload_time(
         upload_time=None,
     )
     provider = resolver.PyPIProvider(cooldown=_COOLDOWN)
-    req = Requirement("test-pkg")
-    requirements: typing.Any = defaultdict(list)
-    requirements["test-pkg"].append(req)
-    incompatibilities: typing.Any = defaultdict(list)
 
     with caplog.at_level(logging.DEBUG, logger="fromager.resolver"):
-        result = provider.validate_candidate(
-            "test-pkg", requirements, incompatibilities, candidate
-        )
+        result = provider.is_blocked_by_cooldown(candidate)
 
-    assert result is False
+    assert result is True
     assert "upload_time unknown" in caplog.text
     assert "1.0.0" in caplog.text
 
@@ -567,8 +558,7 @@ def test_gitlab_cooldown_filters_recent_tag(
         candidate = result.mapping["test-pkg"]
         # v0.0.3 (2025-05-14) is inside the 7-day window; v0.0.2 is the next newest.
         assert str(candidate.version) == "0.0.2"
-        assert "skipping 0.0.3" in caplog.text
-        assert "cooldown" in caplog.text
+        assert "cooldown blocked 1 version(s): 0.0.3" in caplog.text
 
 
 def test_gitlab_cooldown_disabled_selects_latest() -> None:
@@ -639,17 +629,11 @@ def test_github_cooldown_skips_with_warning(
         url="https://github.com/example/pkg/archive/v1.0.0.tar.gz",
         upload_time=None,
     )
-    req = Requirement("test-pkg")
-    requirements: typing.Any = defaultdict(list)
-    requirements["test-pkg"].append(req)
-    incompatibilities: typing.Any = defaultdict(list)
 
     with caplog.at_level(logging.WARNING, logger="fromager.resolver"):
-        result = provider.validate_candidate(
-            "test-pkg", requirements, incompatibilities, candidate
-        )
+        result = provider.is_blocked_by_cooldown(candidate)
 
-    assert result is True
+    assert result is False
     assert "cooldown cannot be enforced" in caplog.text