From a685f9ca4a86ea41b6056ffe120bda12248aa9f9 Mon Sep 17 00:00:00 2001
From: Broque Thomas <26755000+Nezreka@users.noreply.github.com>
Date: Tue, 19 May 2026 22:31:29 -0700
Subject: [PATCH] diag: log every cancel_download caller with a trigger label
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Diagnostic-only change for issue Technodude reported: Tidal sync-playlist
downloads getting mass-cancelled mid-flight with no clear cause in the
logs. App.log shows ~91 second gaps between Tidal download start and
cancel — matches the monitor's 90s queue-timeout exactly — but none of
the monitor's WARNING log lines fire, so the trigger is ambiguous
between five `_should_retry_task` paths, three web_server cancel paths,
and the API endpoints.

Added a single `[CancelTrigger:<label>]` INFO log line immediately
before every `download_orchestrator.cancel_download(...)` call so the
next log dump pins down which path is firing.

Labels (grep-able, prefix tells the file, suffix tells the trigger):

  monitor.not_in_live_transfers_90s
  monitor.errored_state_retry
  monitor.queued_state_timeout
  monitor.stuck_at_0pct_timeout
  monitor.unknown_state_no_progress_timeout
  candidates.worker_cancelled_during_download
  web.orphan_cleanup
  web.cancel_download_task
  web.atomic_cancel_v2
  api.manual_cancel_single
  api.public_cancel

The monitor's `deferred_ops` tuple grew from 3 elements to 4 (added
trigger label as last element). The dispatch loop unpacks both legacy
and new shapes so the change is backward-compatible for any in-flight
ops mid-deploy.

Zero behavior change. 367 download tests still green. WHATS_NEW left
untouched — diagnostic only, not user-facing.

After ship: ask Technodude to re-run the same sync playlist scenario,
attach the new app.log, grep `[CancelTrigger:` lines for the trigger
context, then write the actual fix.
---
 api/downloads.py             |  3 +++
 core/downloads/cancel.py     |  3 +++
 core/downloads/candidates.py |  4 ++++
 core/downloads/monitor.py    | 32 +++++++++++++++++++++++++-------
 web_server.py                | 12 ++++++++++++
 5 files changed, 47 insertions(+), 7 deletions(-)

diff --git a/api/downloads.py b/api/downloads.py
index 69a9846d..29a6989d 100644
--- a/api/downloads.py
+++ b/api/downloads.py
@@ -125,6 +125,9 @@ def register_routes(bp):
             if not soulseek:
                 return api_error("NOT_AVAILABLE", "Soulseek client not configured.", 503)
 
+            current_app.logger.info(
+                f"[CancelTrigger:api.public_cancel] download_id={download_id} username={username}"
+            )
             ok = run_async(soulseek.cancel_download(download_id, username, remove=True))
             if ok:
                 return api_success({"message": "Download cancelled."})
diff --git a/core/downloads/cancel.py b/core/downloads/cancel.py
index 9536eda4..b375f8fa 100644
--- a/core/downloads/cancel.py
+++ b/core/downloads/cancel.py
@@ -45,6 +45,9 @@ _TERMINAL_STATUSES = {
 def cancel_single_download(download_orchestrator, run_async: Callable,
                             download_id: str, username: str) -> bool:
     """Cancel one specific slskd download (with `remove=True`)."""
+    logger.info(
+        f"[CancelTrigger:api.manual_cancel_single] download_id={download_id} username={username}"
+    )
     return run_async(download_orchestrator.cancel_download(download_id, username, remove=True))
 
 
diff --git a/core/downloads/candidates.py b/core/downloads/candidates.py
index b2e92fcb..52700ca9 100644
--- a/core/downloads/candidates.py
+++ b/core/downloads/candidates.py
@@ -343,6 +343,10 @@ def attempt_download_with_candidates(task_id, candidates, track, batch_id=None,
                             logger.warning(f"[Modal Worker] Task {task_id} cancelled after download {download_id} started - attempting to cancel download")
                             # Try to cancel the download immediately
                             try:
+                                logger.info(
+                                    f"[CancelTrigger:candidates.worker_cancelled_during_download] "
+                                    f"download_id={download_id} username={username} task_id={task_id}"
+                                )
                                 deps.run_async(deps.download_orchestrator.cancel_download(download_id, username, remove=True))
                                 logger.warning(f"Successfully cancelled active download {download_id}")
                             except Exception as cancel_error:
diff --git a/core/downloads/monitor.py b/core/downloads/monitor.py
index 3252f324..79a90d8d 100644
--- a/core/downloads/monitor.py
+++ b/core/downloads/monitor.py
@@ -197,8 +197,21 @@ class WebUIDownloadMonitor:
         for op in deferred_ops:
             try:
                 if op[0] == 'cancel_download':
-                    _, download_id, username = op
-                    logger.debug(f"[Deferred] Cancelling download: {download_id} from {username}")
+                    # Issue #648 diagnostic — `op` now carries a trigger
+                    # label (4-tuple, was 3-tuple) so the next log dump
+                    # tells us WHICH path in `_should_retry_task` is
+                    # firing for users seeing "Tidal downloads failed to
+                    # start" mass-cancels. Label format pinned in commit
+                    # message for grep-ability.
+                    if len(op) >= 4:
+                        _, download_id, username, trigger = op[0], op[1], op[2], op[3]
+                    else:
+                        _, download_id, username = op
+                        trigger = 'unlabeled'
+                    logger.info(
+                        f"[CancelTrigger:monitor.{trigger}] download_id={download_id} "
+                        f"username={username}"
+                    )
                     run_async(download_orchestrator.cancel_download(download_id, username, remove=True))
                     logger.debug(f"[Deferred] Successfully cancelled download {download_id}")
                 elif op[0] == 'cleanup_orphan':
@@ -353,7 +366,8 @@ class WebUIDownloadMonitor:
 
                     # Defer slskd cancel to outside the lock
                     if task_username and download_id:
-                        deferred_ops.append(('cancel_download', download_id, task_username))
+                        deferred_ops.append(('cancel_download', download_id, task_username,
+                                             'not_in_live_transfers_90s'))
 
                     # Mark current source as used (full filename to match worker format)
                     if task_username and task_filename:
@@ -424,7 +438,8 @@ class WebUIDownloadMonitor:
 
                 # Defer slskd cancel to outside the lock
                 if username and download_id:
-                    deferred_ops.append(('cancel_download', download_id, username))
+                    deferred_ops.append(('cancel_download', download_id, username,
+                                         'errored_state_retry'))
 
                 # Mark current source as used to prevent retry loops
                 # CRITICAL: Use full filename (not basename) to match worker's source_key format
@@ -527,7 +542,8 @@ class WebUIDownloadMonitor:
 
                         # Defer slskd cancel to outside the lock
                         if username and download_id:
-                            deferred_ops.append(('cancel_download', download_id, username))
+                            deferred_ops.append(('cancel_download', download_id, username,
+                                                 'queued_state_timeout'))
 
                         # UNIFIED RETRY LOGIC: Handle timeout retry exactly like error retry
                         # Mark current source as used to prevent retry loops
@@ -615,7 +631,8 @@ class WebUIDownloadMonitor:
 
                         # Defer slskd cancel to outside the lock
                         if username and download_id:
-                            deferred_ops.append(('cancel_download', download_id, username))
+                            deferred_ops.append(('cancel_download', download_id, username,
+                                                 'stuck_at_0pct_timeout'))
 
                         # UNIFIED RETRY LOGIC: Handle 0% timeout retry exactly like error retry
                         # Mark current source as used to prevent retry loops
@@ -704,7 +721,8 @@ class WebUIDownloadMonitor:
                         download_id = task.get('download_id')
 
                         if username and download_id:
-                            deferred_ops.append(('cancel_download', download_id, username))
+                            deferred_ops.append(('cancel_download', download_id, username,
+                                                 'unknown_state_no_progress_timeout'))
 
                         if username and filename:
                             used_sources = task.get('used_sources', set())
diff --git a/web_server.py b/web_server.py
index b735c7c7..9d3b27b8 100644
--- a/web_server.py
+++ b/web_server.py
@@ -6068,6 +6068,10 @@ def get_download_status():
                                                 transfer_id = file_info.get('id')
                                                 if transfer_id:
                                                     try:
+                                                        logger.info(
+                                                            f"[CancelTrigger:web.orphan_cleanup] "
+                                                            f"download_id={transfer_id} username={username}"
+                                                        )
                                                         run_async(download_orchestrator.cancel_download(str(transfer_id), username, remove=True))
                                                     except Exception as e:
                                                         logger.debug("orphan transfer cancel failed: %s", e)
@@ -16980,6 +16984,10 @@ def cancel_download_task():
         # Optionally try to cancel the Soulseek download (don't block worker progression)
         if download_id and username:
             try:
+                logger.info(
+                    f"[CancelTrigger:web.cancel_download_task] "
+                    f"download_id={download_id} username={username} task_id={task_id}"
+                )
                 # This is an async call, so we run it and wait
                 run_async(download_orchestrator.cancel_download(download_id, username, remove=True))
                 logger.warning(f"Successfully cancelled Soulseek download {download_id} for task {task_id}")
@@ -17232,6 +17240,10 @@ def cancel_task_v2():
                 # and silently left streaming downloads running in background.
                 try:
                     logger.info(f"[Atomic Cancel] Dispatching cancel to orchestrator: username={username} download_id={download_id}")
+                    logger.info(
+                        f"[CancelTrigger:web.atomic_cancel_v2] "
+                        f"download_id={download_id} username={username}"
+                    )
                     cancel_success = run_async(
                         download_orchestrator.cancel_download(download_id, username, remove=True)
                     )