Add debug logging to filter_unallowed_hashes().

src/pip/_internal/index.py

@@ -442,8 +442,9 @@ class LinkEvaluator(object):
 
 
 def filter_unallowed_hashes(
-    candidates,  # type: List[InstallationCandidate]
-    hashes,      # type: Hashes
+    candidates,    # type: List[InstallationCandidate]
+    hashes,        # type: Hashes
+    project_name,  # type: str
 ):
     # type: (...) -> List[InstallationCandidate]
     """
@@ -461,23 +462,58 @@ def filter_unallowed_hashes(
     have been installed (e.g. permitting the user to more easily update
     their requirements file with the desired hash).
     """
-    applicable = []
-    found_allowed_hash = False
+    if not hashes:
+        logger.debug(
+            'Given no hashes to check %s links for project %r: '
+            'discarding no candidates',
+            len(candidates),
+            project_name,
+        )
+        # Make sure we're not returning back the given value.
+        return list(candidates)
+
+    matches_or_no_digest = []
+    # Collect the non-matches for logging purposes.
+    non_matches = []
+    match_count = 0
     for candidate in candidates:
         link = candidate.location
         if not link.has_hash:
-            applicable.append(candidate)
+            pass
+        elif link.is_hash_allowed(hashes=hashes):
+            match_count += 1
+        else:
+            non_matches.append(candidate)
             continue
 
-        if link.is_hash_allowed(hashes=hashes):
-            found_allowed_hash = True
-            applicable.append(candidate)
+        matches_or_no_digest.append(candidate)
 
-    if found_allowed_hash:
-        return applicable
+    if match_count:
+        filtered = matches_or_no_digest
+    else:
+        # Make sure we're not returning back the given value.
+        filtered = list(candidates)
 
-    # Make sure we're not returning back the given value.
-    return list(candidates)
+    if len(filtered) == len(candidates):
+        discard_message = 'discarding no candidates'
+    else:
+        discard_message = 'discarding {} non-matches:\n  {}'.format(
+            len(non_matches),
+            '\n  '.join(str(candidate.location) for candidate in non_matches)
+        )
+
+    logger.debug(
+        'Checked %s links for project %r against %s hashes '
+        '(%s matches, %s no digest): %s',
+        len(candidates),
+        project_name,
+        hashes.digest_count,
+        match_count,
+        len(matches_or_no_digest) - match_count,
+        discard_message
+    )
+
+    return filtered
 
 
 class CandidatePreferences(object):
@@ -587,7 +623,9 @@ class CandidateEvaluator(object):
         ]
 
         return filter_unallowed_hashes(
-            candidates=applicable_candidates, hashes=self._hashes,
+            candidates=applicable_candidates,
+            hashes=self._hashes,
+            project_name=self._project_name,
         )
 
     def make_found_candidates(

src/pip/_internal/utils/hashes.py

@@ -44,6 +44,11 @@ class Hashes(object):
         """
         self._allowed = {} if hashes is None else hashes
 
+    @property
+    def digest_count(self):
+        # type: () -> int
+        return sum(len(digests) for digests in self._allowed.values())
+
     def is_hash_allowed(
         self,
         hash_name,   # type: str

tests/unit/test_index.py

@@ -199,7 +199,9 @@ def test_filter_unallowed_hashes(hex_digest, expected_versions):
         'sha256': [hex_digest],
     }
     hashes = Hashes(hashes_data)
-    actual = filter_unallowed_hashes(candidates, hashes=hashes)
+    actual = filter_unallowed_hashes(
+        candidates, hashes=hashes, project_name='my-project',
+    )
 
     actual_versions = [str(candidate.version) for candidate in actual]
     assert actual_versions == expected_versions
@@ -207,6 +209,85 @@ def test_filter_unallowed_hashes(hex_digest, expected_versions):
     assert actual is not candidates
 
 
+def test_filter_unallowed_hashes__no_hashes(caplog):
+    caplog.set_level(logging.DEBUG)
+
+    candidates = [
+        make_mock_candidate('1.0'),
+        make_mock_candidate('1.1'),
+    ]
+    actual = filter_unallowed_hashes(
+        candidates, hashes=Hashes(), project_name='my-project',
+    )
+
+    # Check that the return value is a copy.
+    assert actual == candidates
+    assert actual is not candidates
+
+    expected_message = (
+        "Given no hashes to check 2 links for project 'my-project': "
+        "discarding no candidates"
+    )
+    check_caplog(caplog, 'DEBUG', expected_message)
+
+
+def test_filter_unallowed_hashes__log_message_with_match(caplog):
+    caplog.set_level(logging.DEBUG)
+
+    # Test 1 match, 2 non-matches, 3 no hashes so all 3 values will be
+    # different.
+    candidates = [
+        make_mock_candidate('1.0'),
+        make_mock_candidate('1.1',),
+        make_mock_candidate('1.2',),
+        make_mock_candidate('1.3', hex_digest=(64 * 'a')),
+        make_mock_candidate('1.4', hex_digest=(64 * 'b')),
+        make_mock_candidate('1.5', hex_digest=(64 * 'c')),
+    ]
+    hashes_data = {
+        'sha256': [64 * 'a', 64 * 'd'],
+    }
+    hashes = Hashes(hashes_data)
+    actual = filter_unallowed_hashes(
+        candidates, hashes=hashes, project_name='my-project',
+    )
+    assert len(actual) == 4
+
+    expected_message = (
+        "Checked 6 links for project 'my-project' against 2 hashes "
+        "(1 matches, 3 no digest): discarding 2 non-matches:\n"
+        "  https://example.com/pkg-1.4.tar.gz#sha256="
+        "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb\n"
+        "  https://example.com/pkg-1.5.tar.gz#sha256="
+        "cccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccc"
+    )
+    check_caplog(caplog, 'DEBUG', expected_message)
+
+
+def test_filter_unallowed_hashes__log_message_with_no_match(caplog):
+    caplog.set_level(logging.DEBUG)
+
+    candidates = [
+        make_mock_candidate('1.0'),
+        make_mock_candidate('1.1', hex_digest=(64 * 'b')),
+        make_mock_candidate('1.2', hex_digest=(64 * 'c')),
+    ]
+    hashes_data = {
+        'sha256': [64 * 'a', 64 * 'd'],
+    }
+    hashes = Hashes(hashes_data)
+    actual = filter_unallowed_hashes(
+        candidates, hashes=hashes, project_name='my-project',
+    )
+    assert len(actual) == 3
+
+    expected_message = (
+        "Checked 3 links for project 'my-project' against 2 hashes "
+        "(0 matches, 1 no digest): discarding no candidates"
+    )
+    check_caplog(caplog, 'DEBUG', expected_message)
+
+
 class TestCandidateEvaluator:
 
     @pytest.mark.parametrize('allow_all_prereleases, prefer_binary', [