Improve debug-level strikehandler output

src/jobs/strikes_handler.py

@@ -8,12 +8,12 @@ class StrikesHandler:
         self.max_strikes = max_strikes
         self.tracker.defective.setdefault(job_name, {})
 
-    def check_permitted_strikes(self, affected_downloads, queue):
-        recovered, paused = self._recover_downloads(affected_downloads, queue)
-        affected_downloads = self._apply_strikes_and_filter(affected_downloads)
+    def filter_strike_exceeds(self, affected_downloads, queue):
+        recovered, removed_from_queue, paused = self._recover_downloads(affected_downloads, queue)
+        strike_exceeds = self._apply_strikes_and_filter(affected_downloads)
         if logger.isEnabledFor(logging.DEBUG):
-            self.log_change(recovered, paused, affected_downloads)
-        return affected_downloads
+            self.log_change(recovered, removed_from_queue, paused, strike_exceeds)
+        return strike_exceeds
 
     def get_entry(self, download_id):
         return self.tracker.defective[self.job_name].get(download_id)
@@ -32,42 +32,65 @@ class StrikesHandler:
             entry.pop("pause_reason", None)
             logger.debug("strikes_handler.py/StrikesHandler/unpause_entry: Unpaused tracking for %s", download_id)
 
-    def log_change(self, recovered, paused, affected_items):
+    # pylint: disable=too-many-locals, too-many-branches
+    def log_change(self, recovered, removed_from_queue, paused, strike_exceeds):
         """
         Logs changes in strike tracking:
-        - Added = new items with 1 strike
-        - Incremented = items with >1 strike
-        - Recovered = items removed from the tracker
-        - Paused = items whose tracking is paused
-        - Removed = all affected item IDs
+        - Added = Downloads caught for first time (1 strike)
+        - Incremented = Downloads caught previously (>1 strikes)
+        - Recovered = Downloads caught previously but now no longer (as they recovered)
+        - removed_from_queue = Downloads caught previously but now no longer (as they are no longer in queue)
+        - Paused = Downloads flagged as paused for tracking
+        - strike_exceeds = Downloads that have too many strikes
         """
         tracker = self.tracker.defective[self.job_name]
 
         added = []
         incremented = []
+        paused_entries = []
+        recovered_entries = []
+        removed_entries = []
+        strike_exceeded = []
 
         for d_id, entry in tracker.items():
-            strikes = entry["strikes"]
-            if strikes == 1:
+            entry = tracker.get(d_id, {})
+            strikes = entry.get("strikes")
+            if d_id in paused:
+                reason = entry.get("pause_reason", "unknown reason")
+                paused_entries.append(f"'{d_id}' [{strikes}/{self.max_strikes}, {reason}]")
+            elif d_id in strike_exceeds:
+                strike_exceeded.append(f"'{d_id}' [{strikes}/{self.max_strikes}]")
+            elif strikes == 1:
                 added.append(d_id)
             elif strikes > 1:
-                incremented.append(f"{d_id} ({strikes}/{self.max_strikes})")
+                incremented.append(f"'{d_id}' [{strikes}/{self.max_strikes}]")
+
+        for d_id in recovered:
+            recovered_entries.append(d_id)
+
+        for d_id in removed_from_queue:
+            removed_entries.append(d_id)
+
+        log_lines = [f"strikes_handler.py/log_change/defective tracker '{self.job_name}':"]
+
+        if added:
+            log_lines.append(f"Added ({len(added)}): {', '.join(added)}")
+        if incremented:
+            log_lines.append(f"Incremented ({len(incremented)}) [strikes]: {', '.join(incremented)}")
+        if paused_entries:
+            log_lines.append(f"Tracking Paused ({len(paused_entries)}) [strikes, reason]: {', '.join(paused_entries)}")
+        if removed_entries:
+            log_lines.append(f"Removed from queue ({len(removed_entries)}): {', '.join(removed_entries)}")
+        if recovered_entries:
+            log_lines.append(f"Recovered ({len(recovered_entries)}): {', '.join(recovered_entries)}")
+        if strike_exceeded:
+            log_lines.append(f"Strikes Exceeded ({len(strike_exceeded)}): {', '.join(strike_exceeded)}")
+
+        logger.debug("\n".join(log_lines))
+
+        return added, incremented, paused, recovered, strike_exceeds, removed_from_queue
+
 
-        removed = list(affected_items.keys())
-        logger.debug(
-            "Strike status changed | %s Added: %s | %s Incremented (strikes): %s | %s Recovered: %s | %s Tracking Paused: %s | %s Removed: %s",
-            len(added) or 0,
-            added or "None",
-            len(incremented) or 0,
-            incremented or "None",
-            len(recovered) or 0,
-            recovered or "None",
-            len(paused) or 0,
-            paused or "None",
-            len(removed) or 0,
-            removed or "None",
-        )
-        return added, incremented, recovered, removed, paused
 
     def _recover_downloads(self, affected_downloads, queue):
         """
@@ -75,6 +98,7 @@ class StrikesHandler:
         If a download is marked as tracking_paused, they are not recovered (will be recovered later potentially)
         """
         recovered = []
+        removed_from_queue = []
         paused = {}
         job_tracker = self.tracker.defective[self.job_name]
         affected_ids = dict(affected_downloads)
@@ -92,22 +116,20 @@ class StrikesHandler:
                         pause_reason,
                     )
                     paused[d_id] = pause_reason
-                elif d_id not in queue_download_ids:
-                    logger.verbose(
-                        ">>> Job '%s' no longer flagging download (download no longer in queue): %s",
-                        self.job_name,
-                        entry["title"],
-                    )
-                    recovered.append(d_id)
                 else:
-                    logger.info(
-                        ">>> Job '%s' no longer flagging download (download has recovered): %s",
-                        self.job_name,
-                        entry["title"],
-                    )
-                    recovered.append(d_id)
+                    if d_id not in queue_download_ids:
+                        recovery_reason = "no longer in queue"
+                        log_level = logger.verbose
+                        removed_from_queue.append(d_id)
+                    else:
+                        recovery_reason = "has recovered"
+                        log_level = logger.info
+                        recovered.append(d_id)
+
+                    log_level(f">>> Job '{self.job_name,}' no longer flagging download (download {recovery_reason}): {entry["title"]}")
                     del job_tracker[d_id]
-        return recovered, paused
+
+        return recovered, removed_from_queue, paused
 
     def _apply_strikes_and_filter(self, affected_downloads):
         for d_id, affected_download in list(affected_downloads.items()):
@@ -135,11 +157,14 @@ class StrikesHandler:
         # Thus putting it to verbose level
         log_level = logger.verbose if strikes_left == -1 else logger.info
 
+        will_trigger_removal = " -> too many" if strikes_left < 0 else ""
+
         log_level(
-            ">>> Job '%s' flagged download (%s/%s strikes): %s",
+            ">>> Job '%s' flagged download (%s/%s strikes%s): %s",
             self.job_name,
             strikes,
             self.max_strikes,
+            will_trigger_removal,
             title,
         )
 

tests/jobs/test_strikes_handler.py

@@ -5,58 +5,93 @@ import pytest
 from src.jobs.strikes_handler import StrikesHandler
 
 # pylint: disable=W0212
+# pylint: disable=too-many-locals
 @pytest.mark.parametrize(
-    ("before_recovery", "expected_remaining_in_tracker"),
+    (
+        "download_id",
+        "already_in_tracker",
+        "in_queue",
+        "in_affected_ids",
+        "expected_in_tracker",
+        "expected_in_paused",
+        "expected_in_recovered",
+        "expected_in_removed_from_queue"
+    ),
     [
-        ([], []),  # nothing active → all removed
-        (["HASH1", "HASH2"], ["HASH1", "HASH2"]),  # both active → none removed
-        (["HASH2"], ["HASH2"]),  # only HASH2 active → HASH1 removed
+        # Not tracked previously, in queue, not affected → ignore
+        ("HASH1", False, True, False, False, False, False, False),
+
+        # Previously tracked, no longer in queue and not affected → recover with reason "no longer in queue"
+        ("HASH2", True, False, False, False, False, False, True),
+
+        # Previously tracked, still in queue but no longer affected → recover with reason "has recovered"
+        ("HASH3", True, True, False, False, False, True, False),
+
+        # Previously tracked, still in queue and still affected → remain tracked, no pause, no recover
+        ("HASH4", True, True, True, True, False, False, False),
+
+        # Previously tracked, still in queue, not affected but tracking paused → remain tracked in paused, no recover
+        ("HASH5", True, True, False, True, True, False, False),
     ],
 )
-def test_recover_downloads(before_recovery, expected_remaining_in_tracker):
-    """Test if tracker correctly removes items (if recovered) and adds new ones."""
-    # Fix
+def test_recover_downloads(
+    download_id,
+    already_in_tracker,
+    in_queue,
+    in_affected_ids,
+    expected_in_tracker,
+    expected_in_paused,
+    expected_in_recovered,
+    expected_in_removed_from_queue
+):
+    # Setup mock tracker with or without the download
+    strikes = 1 if already_in_tracker else None
+    defective_entry = {
+        "title": f"Title-{download_id}",
+        "strikes": strikes,
+    }
+    if expected_in_paused:
+        defective_entry["tracking_paused"] = True
+        defective_entry["pause_reason"] = "Paused for testing"
+
     tracker = MagicMock()
     tracker.defective = {
         "remove_stalled": {
-            "HASH1": {"title": "Movie-with-one-strike", "strikes": 1},
-            "HASH2": {"title": "Movie-with-three-strikes", "strikes": 3},
-        },
+            download_id: defective_entry,
+        } if already_in_tracker else {}
     }
+
     arr = MagicMock()
     arr.tracker = tracker
+
     handler = StrikesHandler(job_name="remove_stalled", arr=arr, max_strikes=3)
-    affected_downloads = [(hash_id, {"title": "dummy"}) for hash_id in before_recovery]
 
-    # Act
-    handler._recover_downloads(affected_downloads)  # pylint: disable=W0212
+    affected_downloads = []
+    if in_affected_ids:
+        affected_downloads.append((download_id, {"title": "dummy"}))
 
-    # Assert
-    assert sorted(tracker.defective["remove_stalled"].keys()) == sorted(
-        expected_remaining_in_tracker
-    )
+    queue = []
+    if in_queue:
+        queue.append({"downloadId": download_id})
 
+    # Unpack all three returned values from _recover_downloads
+    recovered, removed_from_queue, paused = handler._recover_downloads(affected_downloads, queue=queue)  # pylint: disable=W0212
 
-def test_recover_downloads2_no_patch():
-    """Test if recovery correctly skips those items where tracking is paused."""
-    handler = StrikesHandler(
-        job_name="remove_stalled", arr=MagicMock(), max_strikes=3
-    )
-    handler.tracker = MagicMock()
-    handler.tracker.defective = {
-        "remove_stalled": {
-            "id1": {"title": "Title1", "tracking_paused": False},
-            "id2": {"title": "Title2", "tracking_paused": True, "pause_reason": "manual"},
-            "id3": {"title": "Title3"},  # no paused flag = False
-        }
-    }
+    is_in_tracker = download_id in tracker.defective["remove_stalled"]
+    assert is_in_tracker == expected_in_tracker, f"{download_id} tracker presence mismatch"
 
-    affected_downloads = {"id3": {}}
+    is_in_paused = download_id in paused
+    assert is_in_paused == expected_in_paused, f"{download_id} paused presence mismatch"
 
-    recovered, paused = handler._recover_downloads(affected_downloads)
+    is_in_recovered = download_id in recovered
+    assert is_in_recovered == expected_in_recovered, f"{download_id} recovered presence mismatch"
+
+    is_in_recovered = download_id in recovered
+    assert is_in_recovered == expected_in_recovered, f"{download_id} recovered presence mismatch"
+
+    is_in_removed = download_id in removed_from_queue
+    assert is_in_removed == expected_in_removed_from_queue, f"{download_id} removed_from_queue presence mismatch"
 
-    assert recovered == ["id1"]
-    assert paused == {"id2": "manual"}
 
 
 @pytest.mark.parametrize(
@@ -94,35 +129,37 @@ def test_apply_strikes_and_filter(
     else:
         assert "HASH1" not in result
 
-
 def test_log_change_logs_expected_strike_changes(caplog):
     handler = StrikesHandler(job_name="remove_stalled", arr=MagicMock(), max_strikes=3)
     handler.tracker = MagicMock()
     handler.tracker.defective = {
         "remove_stalled": {
-            "hash_new": {"title": "A", "strikes": 1},   # should show in added
-            "hash_inc": {"title": "B", "strikes": 2},   # should show in incremented
-            "hash_paused": {"title": "C", "strikes": 2},  # should show in paused
+            "hash_new": {"strikes": 1},
+            "hash_inc": {"strikes": 2},
+            "hash_paused": {"strikes": 2, "pause_reason": "Bandwidth"},
+            "hash_exceed": {"strikes": 10},  # <- add here
         }
     }
 
-    recovered = ["hash_old"]
+    recovered = ["recovered1", "recovered2"]
+    removed_from_queue = ["removed"]
     paused = ["hash_paused"]
-    affected = {"hash_gone": {"title": "Gone"}}
+    strike_exceeds = ["hash_exceed"]
 
     with caplog.at_level(logging.DEBUG, logger="src.utils.log_setup"):
-        handler.log_change(recovered, paused, affected)
+        handler.log_change(recovered, removed_from_queue, paused, strike_exceeds)
 
     log_messages = "\n".join(record.message for record in caplog.records)
 
     # Check category keywords exist
-    for keyword in ["Added", "Incremented", "Recovered", "Removed", "Paused"]:
+    for keyword in ["Added", "Incremented", "Tracking Paused", "Removed from queue", "Recovered", "Strikes Exceeded"]:
         assert keyword in log_messages
 
-    # Check actual IDs exist
-    for key in ["hash_new", "hash_inc", "hash_old", "hash_gone", "hash_paused"]:
+    # Check actual IDs appear somewhere in the logged messages
+    for key in ["hash_new", "hash_inc", "hash_exceed", "hash_paused"]:
         assert key in log_messages
 
+
 @pytest.mark.parametrize(
     "max_strikes, initial_strikes, expected_removed_after_two_runs",
     [
@@ -148,6 +185,10 @@ def test_strikes_handler_overall(
     Note: The logging output does not show the strike where the removal will be triggered (ie., 4/3 if max strikes = 3)
     Reason: This is on verbose-level, as instead the removal handler then shows another info-level log
     """
+    # Set the logger level by name to 15 (VERBOSE)
+    logger = logging.getLogger("src.utils.log_setup")
+    logger.setLevel(15)
+
     job_name = "remove_stalled"
     d_id = "some_hash"
 
@@ -162,9 +203,8 @@ def test_strikes_handler_overall(
     affected_downloads = {d_id: {"title": "Some Title"}}
 
     handler = StrikesHandler(job_name=job_name, arr=arr, max_strikes=max_strikes)
-    handler.check_permitted_strikes(affected_downloads.copy())
-    handler = StrikesHandler(job_name=job_name, arr=arr, max_strikes=max_strikes)
-    result = handler.check_permitted_strikes(affected_downloads.copy())
+    handler.filter_strike_exceeds(affected_downloads.copy(), queue=[])
+    result = handler.filter_strike_exceeds(affected_downloads.copy(), queue=[])
 
     assert (d_id in result) == expected_removed_after_two_runs, (
         f"Expected removed={expected_removed_after_two_runs} for "