From 3b3a03dbc2fba6a372b7fa24a0e2f12656a4a56c Mon Sep 17 00:00:00 2001 From: Benjamin Harder Date: Sun, 15 Jun 2025 21:22:34 +0200 Subject: [PATCH] Improve debug-level strikehandler output --- src/jobs/strikes_handler.py | 113 ++++++++++++++---------- tests/jobs/test_strikes_handler.py | 134 +++++++++++++++++++---------- 2 files changed, 156 insertions(+), 91 deletions(-) diff --git a/src/jobs/strikes_handler.py b/src/jobs/strikes_handler.py index 6131943..2dbb249 100644 --- a/src/jobs/strikes_handler.py +++ b/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, ) diff --git a/tests/jobs/test_strikes_handler.py b/tests/jobs/test_strikes_handler.py index 392e372..94a5672 100644 --- a/tests/jobs/test_strikes_handler.py +++ b/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 "