diag: log every cancel_download caller with a trigger label
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.
This commit is contained in:
parent
716ec66cf5
commit
a685f9ca4a
5 changed files with 47 additions and 7 deletions
|
|
@ -125,6 +125,9 @@ def register_routes(bp):
|
||||||
if not soulseek:
|
if not soulseek:
|
||||||
return api_error("NOT_AVAILABLE", "Soulseek client not configured.", 503)
|
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))
|
ok = run_async(soulseek.cancel_download(download_id, username, remove=True))
|
||||||
if ok:
|
if ok:
|
||||||
return api_success({"message": "Download cancelled."})
|
return api_success({"message": "Download cancelled."})
|
||||||
|
|
|
||||||
|
|
@ -45,6 +45,9 @@ _TERMINAL_STATUSES = {
|
||||||
def cancel_single_download(download_orchestrator, run_async: Callable,
|
def cancel_single_download(download_orchestrator, run_async: Callable,
|
||||||
download_id: str, username: str) -> bool:
|
download_id: str, username: str) -> bool:
|
||||||
"""Cancel one specific slskd download (with `remove=True`)."""
|
"""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))
|
return run_async(download_orchestrator.cancel_download(download_id, username, remove=True))
|
||||||
|
|
||||||
|
|
||||||
|
|
|
||||||
|
|
@ -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")
|
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 to cancel the download immediately
|
||||||
try:
|
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))
|
deps.run_async(deps.download_orchestrator.cancel_download(download_id, username, remove=True))
|
||||||
logger.warning(f"Successfully cancelled active download {download_id}")
|
logger.warning(f"Successfully cancelled active download {download_id}")
|
||||||
except Exception as cancel_error:
|
except Exception as cancel_error:
|
||||||
|
|
|
||||||
|
|
@ -197,8 +197,21 @@ class WebUIDownloadMonitor:
|
||||||
for op in deferred_ops:
|
for op in deferred_ops:
|
||||||
try:
|
try:
|
||||||
if op[0] == 'cancel_download':
|
if op[0] == 'cancel_download':
|
||||||
_, download_id, username = op
|
# Issue #648 diagnostic — `op` now carries a trigger
|
||||||
logger.debug(f"[Deferred] Cancelling download: {download_id} from {username}")
|
# 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))
|
run_async(download_orchestrator.cancel_download(download_id, username, remove=True))
|
||||||
logger.debug(f"[Deferred] Successfully cancelled download {download_id}")
|
logger.debug(f"[Deferred] Successfully cancelled download {download_id}")
|
||||||
elif op[0] == 'cleanup_orphan':
|
elif op[0] == 'cleanup_orphan':
|
||||||
|
|
@ -353,7 +366,8 @@ class WebUIDownloadMonitor:
|
||||||
|
|
||||||
# Defer slskd cancel to outside the lock
|
# Defer slskd cancel to outside the lock
|
||||||
if task_username and download_id:
|
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)
|
# Mark current source as used (full filename to match worker format)
|
||||||
if task_username and task_filename:
|
if task_username and task_filename:
|
||||||
|
|
@ -424,7 +438,8 @@ class WebUIDownloadMonitor:
|
||||||
|
|
||||||
# Defer slskd cancel to outside the lock
|
# Defer slskd cancel to outside the lock
|
||||||
if username and download_id:
|
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
|
# Mark current source as used to prevent retry loops
|
||||||
# CRITICAL: Use full filename (not basename) to match worker's source_key format
|
# 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
|
# Defer slskd cancel to outside the lock
|
||||||
if username and download_id:
|
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
|
# UNIFIED RETRY LOGIC: Handle timeout retry exactly like error retry
|
||||||
# Mark current source as used to prevent retry loops
|
# Mark current source as used to prevent retry loops
|
||||||
|
|
@ -615,7 +631,8 @@ class WebUIDownloadMonitor:
|
||||||
|
|
||||||
# Defer slskd cancel to outside the lock
|
# Defer slskd cancel to outside the lock
|
||||||
if username and download_id:
|
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
|
# UNIFIED RETRY LOGIC: Handle 0% timeout retry exactly like error retry
|
||||||
# Mark current source as used to prevent retry loops
|
# Mark current source as used to prevent retry loops
|
||||||
|
|
@ -704,7 +721,8 @@ class WebUIDownloadMonitor:
|
||||||
download_id = task.get('download_id')
|
download_id = task.get('download_id')
|
||||||
|
|
||||||
if username and 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:
|
if username and filename:
|
||||||
used_sources = task.get('used_sources', set())
|
used_sources = task.get('used_sources', set())
|
||||||
|
|
|
||||||
|
|
@ -6068,6 +6068,10 @@ def get_download_status():
|
||||||
transfer_id = file_info.get('id')
|
transfer_id = file_info.get('id')
|
||||||
if transfer_id:
|
if transfer_id:
|
||||||
try:
|
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))
|
run_async(download_orchestrator.cancel_download(str(transfer_id), username, remove=True))
|
||||||
except Exception as e:
|
except Exception as e:
|
||||||
logger.debug("orphan transfer cancel failed: %s", 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)
|
# Optionally try to cancel the Soulseek download (don't block worker progression)
|
||||||
if download_id and username:
|
if download_id and username:
|
||||||
try:
|
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
|
# This is an async call, so we run it and wait
|
||||||
run_async(download_orchestrator.cancel_download(download_id, username, remove=True))
|
run_async(download_orchestrator.cancel_download(download_id, username, remove=True))
|
||||||
logger.warning(f"Successfully cancelled Soulseek download {download_id} for task {task_id}")
|
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.
|
# and silently left streaming downloads running in background.
|
||||||
try:
|
try:
|
||||||
logger.info(f"[Atomic Cancel] Dispatching cancel to orchestrator: username={username} download_id={download_id}")
|
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(
|
cancel_success = run_async(
|
||||||
download_orchestrator.cancel_download(download_id, username, remove=True)
|
download_orchestrator.cancel_download(download_id, username, remove=True)
|
||||||
)
|
)
|
||||||
|
|
|
||||||
Loading…
Reference in a new issue