diff --git a/shelfmark/download/clients/base_handler.py b/shelfmark/download/clients/base_handler.py index d6a19df2..f3f903c7 100644 --- a/shelfmark/download/clients/base_handler.py +++ b/shelfmark/download/clients/base_handler.py @@ -1,5 +1,6 @@ """Shared download handler for external torrent/usenet clients.""" +import errno import shutil import time from abc import ABC, abstractmethod @@ -18,6 +19,7 @@ from shelfmark.download.clients import ( list_configured_clients, ) from shelfmark.download.fs import run_blocking_io +from shelfmark.download.permissions_debug import log_path_permission_context from shelfmark.release_sources import DownloadHandler if TYPE_CHECKING: @@ -81,6 +83,29 @@ def _diagnose_path_issue(path: str) -> str: ) +def _format_probe_error(error: OSError | None) -> str: + """Render an OSError for inclusion in log/status messages.""" + if error is None: + return "none" + code = errno.errorcode.get(error.errno, str(error.errno)) if error.errno else "?" + return f"{code}: {error.strerror or error}" + + +def _probe_completed_path(path: Path) -> tuple[bool, OSError | None]: + """Probe a completed download path and preserve the underlying stat error. + + `Path.exists()` silently converts every `OSError` to `False`, which hides + whether a failure is ENOENT (not yet written), EACCES (permission denied), + ESTALE (NFS stale handle), or something else. Callers need the real errno + to decide whether the condition is retryable and to surface diagnostics. + """ + try: + run_blocking_io(path.stat) + except OSError as error: + return False, error + return True, None + + class ExternalClientHandler(DownloadHandler, ABC): """Shared lifecycle handler for sources that hand off to torrent/usenet clients.""" @@ -378,19 +403,21 @@ class ExternalClientHandler(DownloadHandler, ABC): remote_path=source_path_obj, ) - if log_details: - remapped_exists = run_blocking_io(remapped.exists) - logger.debug( - "Remap result: %s -> %s (exists=%s, changed=%s, matched=%s)", - source_path_obj, - remapped, - remapped_exists, - remapped != source_path_obj, - matched_mapping, - ) - if matched_mapping: - if run_blocking_io(remapped.exists): + remapped_exists, remapped_error = _probe_completed_path(remapped) + + if log_details: + logger.debug( + "Remap result: %s -> %s (exists=%s, probe_error=%s, changed=%s, matched=%s)", + source_path_obj, + remapped, + remapped_exists, + _format_probe_error(remapped_error), + remapped != source_path_obj, + matched_mapping, + ) + + if remapped_exists: logger.info( "Remapped download path for %s (%s): %s -> %s", client.name, @@ -404,76 +431,76 @@ class ExternalClientHandler(DownloadHandler, ABC): f"Remapped path '{remapped}' does not exist. " f"Check your Docker volume mounts match the Local Path in Settings > Advanced > Remote Path Mappings." ) + failure_log = "Download path does not exist after remapping: %s -> %s (probe_error=%s). Client: %s, ID: %s." + failure_args = ( + raw_path, + remapped, + _format_probe_error(remapped_error), + client.name, + download_id, + ) if log_details: - logger.error( - "Download path does not exist after remapping: %s -> %s. Client: %s, ID: %s.", - raw_path, - remapped, - client.name, - download_id, - ) + log_path_permission_context("completed_download_remap", remapped) + logger.error(failure_log, *failure_args) else: - logger.debug( - "Download path does not exist after remapping: %s -> %s. Client: %s, ID: %s.", - raw_path, - remapped, - client.name, - download_id, - ) + logger.debug(failure_log, *failure_args) return None, message - if mappings: - if run_blocking_io(source_path_obj.exists): + source_exists, source_error = _probe_completed_path(source_path_obj) + + if log_details: + logger.debug( + "Remap result: %s -> %s (exists=%s, probe_error=%s, changed=%s, matched=%s)", + source_path_obj, + remapped, + source_exists, + _format_probe_error(source_error), + remapped != source_path_obj, + matched_mapping, + ) + + if source_exists: + if mappings: logger.info( "No remote path mapping matched for %s (%s); using client path: %s", client.name, download_id, source_path_obj, ) - return source_path_obj, None + return source_path_obj, None - hint = _diagnose_path_issue(raw_path) + hint = _diagnose_path_issue(raw_path) + if mappings: message = f"{hint} No remote path mapping matched for client '{client.name}'." - if log_details: - logger.error( - "Download path does not exist and no remote path mapping matched for %s (%s): %s. %s", - client.name, - download_id, - raw_path, - hint, - ) - else: - logger.debug( - "Download path does not exist and no remote path mapping matched for %s (%s): %s. %s", - client.name, - download_id, - raw_path, - hint, - ) - return None, message - - if not run_blocking_io(source_path_obj.exists): - hint = _diagnose_path_issue(raw_path) + failure_label = "completed_download_original" + failure_log = "Download path does not exist and no remote path mapping matched for %s (%s): %s (probe_error=%s). %s" + failure_args = ( + client.name, + download_id, + raw_path, + _format_probe_error(source_error), + hint, + ) + else: message = hint - if log_details: - logger.error( - "Download path does not exist: %s. Client: %s, ID: %s. %s", - raw_path, - client.name, - download_id, - hint, - ) - else: - logger.debug( - "Download path does not exist: %s. Client: %s, ID: %s. %s", - raw_path, - client.name, - download_id, - hint, - ) - return None, message + failure_label = "completed_download_direct" + failure_log = ( + "Download path does not exist: %s (probe_error=%s). Client: %s, ID: %s. %s" + ) + failure_args = ( + raw_path, + _format_probe_error(source_error), + client.name, + download_id, + hint, + ) - return source_path_obj, None + if log_details: + log_path_permission_context(failure_label, source_path_obj) + logger.error(failure_log, *failure_args) + else: + logger.debug(failure_log, *failure_args) + return None, message def _wait_for_completed_path( self,