"""Import/post-processing pipeline for downloads and imported files.""" from __future__ import annotations import json import os import threading import time from types import SimpleNamespace from typing import Any from config.settings import config_manager from core.imports.file_ops import ( cleanup_empty_directories, cleanup_slskd_dedup_siblings, create_lossy_copy, downsample_hires_flac, get_audio_quality_string, get_quality_tier_from_extension, safe_move_file, ) from core.imports.context import ( build_import_album_info, detect_album_info_web, extract_artist_name, get_import_clean_artist, get_import_clean_title, get_import_context_artist, get_import_has_clean_metadata, get_import_original_search, get_import_source, get_import_track_info, normalize_import_context, ) from core.imports.file_integrity import check_audio_integrity, expected_duration_for_check, resolve_duration_tolerance from core.imports.filename import extract_track_number_from_filename from core.imports.guards import check_flac_bit_depth, move_to_quarantine from core.imports.quarantine import ( approve_quarantine_entry, entry_id_from_quarantined_filename, list_quarantine_entries, ) from core.imports.version_mismatch_fallback import try_accept_version_mismatch_fallback from core.imports.side_effects import ( emit_track_downloaded, record_download_provenance, record_library_history_download, record_soulsync_library_entry, ) from core.wishlist.resolution import check_and_remove_from_wishlist from core.runtime_state import ( add_activity_item, download_batches, download_tasks, matched_context_lock, matched_downloads_context, mark_task_completed as _mark_task_completed, post_process_locks, post_process_locks_lock, processed_download_ids, tasks_lock, ) from core.metadata.artwork import download_cover_art from core.metadata.common import wipe_source_tags from core.imports.tag_policy import should_wipe_tags_on_enhancement_failure from core.metadata.enrichment import enhance_file_metadata from core.imports.paths import ( build_final_path_for_track, build_simple_download_destination, docker_resolve_path, ) from core.imports.album_naming import resolve_album_group from core.metadata.lyrics import generate_lrc_file from database.music_database import get_database from utils.logging_config import get_logger logger = get_logger("imports.pipeline") pp_logger = get_logger("post_processing") __all__ = [ "build_import_pipeline_runtime", "post_process_matched_download", "post_process_matched_download_with_verification", ] def _should_skip_quarantine_check(context: dict, check_name: str) -> bool: bypass = context.get('_skip_quarantine_check') if bypass == 'all': return True if isinstance(bypass, (list, tuple, set)): return 'all' in bypass or check_name in bypass return bypass == check_name def _mark_task_quarantined(context: dict, quarantine_path: str | None) -> None: if not quarantine_path: return entry_id = entry_id_from_quarantined_filename(quarantine_path) # Always stash the entry id on the context. The verification wrapper # (post_process_matched_download_with_verification) pops task_id/batch_id # OUT of the context before running the inner pipeline, so when a quarantine # happens inside that inner run context.get('task_id') is None here and the # direct write below no-ops. The wrapper restores task_id afterward and # applies this stashed id to the real task — without this, downloads that go # through the wrapper (album-bundle / staging path) quarantined with no # quarantine_entry_id, so the UI had no way to manage the file (#756-adjacent). context['_quarantine_entry_id'] = entry_id task_id = context.get('task_id') if not task_id: return with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['quarantine_entry_id'] = entry_id def _requeue_quarantined_task_for_retry(task_id, batch_id, trigger) -> bool: """Ask the download monitor to re-run this task on its next-best candidate. Thin lazy-import wrapper around ``core.downloads.monitor.requeue_quarantined_task_for_retry``. Imported lazily (and defensively) so the post-processing pipeline stays importable on its own — the monitor's retry globals are wired by web_server at startup, and manual-import callers that never started a download worker simply get False. Returns True when a retry was queued (caller must not mark the task failed). """ if not task_id: return False try: from core.downloads.monitor import requeue_quarantined_task_for_retry except Exception as exc: # pragma: no cover - defensive logger.debug(f"next-candidate retry unavailable ({trigger}): {exc}") return False try: return requeue_quarantined_task_for_retry(task_id, batch_id, trigger) except Exception as exc: # pragma: no cover - defensive logger.error(f"next-candidate retry failed ({trigger}): {exc}") return False def import_rejection_reason(context: dict) -> str | None: """Human-readable reason if post-processing terminally rejected the file (quarantine or race-guard), else ``None`` for a clean import. ``post_process_matched_download`` signals these outcomes by setting context flags and returning normally — it only raises on unexpected errors. The download path reads those flags in ``post_process_matched_download_with_verification`` and marks the task failed, but the MANUAL-import routes call ``post_process_matched_download`` directly with no task_id, so without this check a quarantined file (now in ss_quarantine, not the library) is counted as a successful import and the UI shows a green "Done" (#764). Pure + testable: it only inspects the context dict the inner pipeline populated.""" if context.get('_integrity_failure_msg'): return f"integrity check failed: {context['_integrity_failure_msg']}" if context.get('_acoustid_quarantined'): return ( "AcoustID verification failed: " f"{context.get('_acoustid_failure_msg', 'fingerprint mismatch')}" ) if context.get('_bitdepth_rejected'): return "rejected by bit-depth filter" if context.get('_race_guard_failed'): return "source file disappeared before import completed" return None def build_import_pipeline_runtime( *, automation_engine: Any | None = None, on_download_completed: Any | None = None, web_scan_manager: Any | None = None, repair_worker: Any | None = None, ) -> SimpleNamespace: """Build the runtime object consumed by core.imports.pipeline.""" return SimpleNamespace( automation_engine=automation_engine, on_download_completed=on_download_completed, web_scan_manager=web_scan_manager, repair_worker=repair_worker, ) def _persist_verification_status(context, final_path): """Compute + persist the verification status (verified / unverified / force_imported) for a finished import: embedded tag on the file, plus context['_verification_status'] for the history row and the Downloads UI. MUST be called on EVERY success exit of post-processing (main, playlist folder mode, simple download) — a missed exit means no badge and no tag. Never raises.""" try: from core.matching.verification_status import status_for_import from core.tag_writer import write_verification_status status = status_for_import(context) if status: context['_verification_status'] = status if final_path: write_verification_status(str(final_path), status) except Exception as _vs_err: logger.debug(f"verification-status persist skipped: {_vs_err}") def post_process_matched_download(context_key, context, file_path, runtime, metadata_runtime=None): on_download_completed = getattr(runtime, "on_download_completed", None) automation_engine = getattr(runtime, "automation_engine", None) web_scan_manager = getattr(runtime, "web_scan_manager", None) repair_worker = getattr(runtime, "repair_worker", None) metadata_runtime = metadata_runtime or runtime def _notify_download_completed(batch_id, task_id, success=True): if on_download_completed: on_download_completed(batch_id, task_id, success=success) with post_process_locks_lock: if context_key not in post_process_locks: post_process_locks[context_key] = threading.Lock() file_lock = post_process_locks[context_key] file_lock.acquire() try: if not os.path.exists(file_path): existing_final = context.get('_final_processed_path') if existing_final and os.path.exists(existing_final): logger.info( f"[Race Guard] Source gone but destination exists — already processed by another thread: " f"{os.path.basename(existing_final)}" ) return # File was intentionally moved to quarantine by a concurrent/earlier # post-process call — this is a stale duplicate dispatch, not a race. # _mark_task_quarantined sets _quarantine_entry_id for every quarantine # trigger (AcoustID, integrity, bit-depth). The quarantine entry and # its retry are already in flight; don't overwrite the task state with # a spurious race-guard failure. if context.get('_quarantine_entry_id'): logger.debug( f"[Race Guard] Source gone but already quarantined (entry %s) — stale duplicate call, ignoring: " f"{os.path.basename(file_path)}", context['_quarantine_entry_id'], ) return logger.error( f"[Race Guard] Source file gone and no known destination — marking as failed: " f"{os.path.basename(file_path)}" ) context['_race_guard_failed'] = True return _basename = os.path.basename(file_path) _prev_size = -1 for _stability_check in range(5): try: _cur_size = os.path.getsize(file_path) except OSError: _cur_size = -1 if _cur_size == _prev_size and _cur_size > 0: break _prev_size = _cur_size if _stability_check == 0: logger.info(f"Waiting for file to stabilise: {_basename} ({_cur_size} bytes)") time.sleep(1.5) else: logger.info(f"File may still be writing after stability checks: {_basename} ({_prev_size} bytes)") # File integrity check: catches broken slskd transfers (truncated, # corrupted, wrong file masquerading as the target) before we burn # cycles on AcoustID + tagging + library sync. Universal across # formats; failed files get quarantined and the slot freed. try: _normalized_for_duration = normalize_import_context(context) _duration_track = get_import_track_info(_normalized_for_duration) _expected_duration_ms = int(_duration_track.get("duration_ms", 0) or 0) or None except Exception: _expected_duration_ms = None # Local/manual imports are the user's own files, not slskd transfers — # skip the duration-agreement leg (it would false-quarantine a file that # drifts from a re-resolved release; #804). Size + parse legs still run. _is_local_import = bool(context.get('is_local_import')) if isinstance(context, dict) else False _expected_duration_ms = expected_duration_for_check(_expected_duration_ms, _is_local_import) if _is_local_import and _expected_duration_ms is None: logger.debug("[Integrity] Local import — duration-agreement leg skipped for %s", _basename) # User-configurable tolerance override. None = use built-in # auto-scaled defaults (3s normal / 5s for tracks >10min). Set # higher (e.g. 10) when matched files routinely drift from the # source's reported duration (live recordings, alternate # masterings, etc). _duration_tolerance_override = resolve_duration_tolerance( config_manager.get('post_processing.duration_tolerance_seconds', 0) ) # User-approved quarantine restores can bypass quarantine gates # for this one post-processing pass. if _should_skip_quarantine_check(context, 'integrity'): logger.info(f"[Integrity] Skipped (user approval) for {_basename}") integrity = None else: try: integrity = check_audio_integrity( file_path, _expected_duration_ms, length_tolerance_s=_duration_tolerance_override, ) except Exception as integrity_error: logger.error(f"[Integrity] Check raised unexpectedly (continuing): {integrity_error}") integrity = None if integrity is not None and not integrity.ok: logger.error(f"[Integrity] Rejected {_basename}: {integrity.reason}") context['_integrity_failure_msg'] = integrity.reason context['_integrity_checks'] = integrity.checks try: quarantine_path = move_to_quarantine( file_path, context, f"Integrity check failed: {integrity.reason}", automation_engine, trigger='integrity', ) _mark_task_quarantined(context, quarantine_path) logger.error(f"File quarantined due to integrity failure: {quarantine_path}") except Exception as quarantine_error: logger.error(f"Quarantine failed ({quarantine_error}), deleting broken file: {file_path}") try: os.remove(file_path) except Exception as del_error: logger.error(f"Could not delete broken file either: {del_error}") with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] task_id = context.get('task_id') batch_id = context.get('batch_id') if task_id: with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = ( f"File integrity check failed: {integrity.reason}" ) if task_id and batch_id: _notify_download_completed(batch_id, task_id, success=False) return if integrity is not None: logger.info( f"[Integrity] {_basename} passed " f"(size={integrity.checks.get('size_bytes', '?')}b, " f"length={integrity.checks.get('actual_length_s', 0):.1f}s, " f"drift={integrity.checks.get('length_drift_s', 'n/a')})" ) _skip_acoustid = _should_skip_quarantine_check(context, 'acoustid') if _skip_acoustid: logger.info(f"[AcoustID] Skipped (user approval) for {_basename}") try: from core.acoustid_verification import AcoustIDVerification, VerificationResult verifier = AcoustIDVerification() available, available_reason = verifier.quick_check_available() if available and not _skip_acoustid: context = normalize_import_context(context) track_info = get_import_track_info(context) original_search = get_import_original_search(context) artist_context = get_import_context_artist(context) expected_track = get_import_clean_title(context, default=original_search.get('title', '')) expected_artist = '' track_artists = track_info.get('artists', []) if track_artists: first = track_artists[0] if isinstance(first, dict): expected_artist = first.get('name', '') elif isinstance(first, str): expected_artist = first if not expected_artist: expected_artist = extract_artist_name(artist_context) or get_import_clean_artist(context, default='') if expected_track and expected_artist: logger.info(f"Running AcoustID verification for: '{expected_track}' by '{expected_artist}'") verification_result, verification_msg = verifier.verify_audio_file( file_path, expected_track, expected_artist, context, ) logger.info(f"AcoustID verification result: {verification_result.value} - {verification_msg}") context['_acoustid_result'] = verification_result.value if verification_result == VerificationResult.FAIL: try: quarantine_path = move_to_quarantine( file_path, context, verification_msg, automation_engine, trigger='acoustid', ) _mark_task_quarantined(context, quarantine_path) logger.error(f"File quarantined due to verification failure: {quarantine_path}") except Exception as quarantine_error: logger.error(f"Quarantine failed ({quarantine_error}), deleting wrong file: {file_path}") logger.error(f"Quarantine failed, deleting wrong file: {file_path}") try: os.remove(file_path) except Exception as del_error: logger.error(f"Could not delete wrong file either: {del_error}") context['_acoustid_quarantined'] = True context['_acoustid_failure_msg'] = verification_msg with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] task_id = context.get('task_id') batch_id = context.get('batch_id') if task_id: with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = ( f"AcoustID verification failed: {verification_msg}" ) if task_id and batch_id: _notify_download_completed(batch_id, task_id, success=False) return else: logger.warning("AcoustID verification skipped: missing track/artist info") context['_acoustid_result'] = 'skip' else: logger.info(f"ℹ️ AcoustID verification not available: {available_reason}") context['_acoustid_result'] = 'disabled' except Exception as verify_error: logger.error(f"AcoustID verification error (continuing normally): {verify_error}") context['_acoustid_result'] = 'error' search_result = context.get('search_result', {}) or {} if not isinstance(search_result, dict): search_result = {} is_simple_download = search_result.get('is_simple_download', False) if is_simple_download: logger.info(f"Processing simple download (no metadata enhancement): {file_path}") destination, album_name, filename = build_simple_download_destination(context, file_path) if album_name: logger.info(f"Moving to album folder: {album_name}") else: logger.info("Moving to Transfer root (single track)") safe_move_file(file_path, destination) logger.info(f"Moved simple download to: {destination}") cleanup_slskd_dedup_siblings(file_path) with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] if web_scan_manager: threading.Thread( target=lambda: web_scan_manager.request_scan("Simple download completed"), daemon=True, ).start() activity_target = f"{album_name}/{filename}" if album_name else filename add_activity_item("", "Download Complete", activity_target, "Now") logger.info(f"Simple download post-processing complete: {activity_target}") context['_simple_download_completed'] = True context['_final_path'] = str(destination) _persist_verification_status(context, destination) emit_track_downloaded(context, automation_engine) record_library_history_download(context) record_download_provenance(context) try: check_and_remove_from_wishlist(context) except Exception as wishlist_error: logger.error(f"[Simple Download] Error checking wishlist removal: {wishlist_error}") return logger.info(f"Starting robust post-processing for: {context_key}") context = normalize_import_context(context) artist_context = get_import_context_artist(context) track_info = get_import_track_info(context) original_search = get_import_original_search(context) has_clean_metadata = get_import_has_clean_metadata(context) if not artist_context: logger.error("Post-processing failed: Missing artist context.") return _junk_artist_names = {'', 'unknown', 'unknown artist', 'various artists', 'none', 'null'} _artist_name = (artist_context.get('name', '') if isinstance(artist_context, dict) else '').strip() if _artist_name.lower() in _junk_artist_names: logger.info(f"[Unknown Artist Guard] Artist name is '{_artist_name}' — attempting to resolve") _resolved = False track_info_guard = track_info or {} original_search_guard = original_search or {} _ti_artists = track_info_guard.get('artists', []) if isinstance(_ti_artists, list) and _ti_artists: _first = _ti_artists[0] _name = _first.get('name', '') if isinstance(_first, dict) else str(_first) if _name and _name.strip().lower() not in _junk_artist_names: artist_context['name'] = _name.strip() logger.info(f"[Unknown Artist Guard] Resolved from track_info.artists: '{_name}'") _resolved = True if not _resolved: _os_artist = original_search_guard.get('artist') or original_search_guard.get('artist_name') or '' if isinstance(_os_artist, str) and _os_artist.strip().lower() not in _junk_artist_names: artist_context['name'] = _os_artist.strip() logger.info(f"[Unknown Artist Guard] Resolved from original_search_result: '{_os_artist}'") _resolved = True if not _resolved: _track_id = track_info_guard.get('id') or track_info_guard.get('track_id') or '' if _track_id: try: from core.metadata_service import get_client_for_source, get_primary_source _guard_source = get_import_source(context) or get_primary_source() _fb_client = get_client_for_source(_guard_source) or get_client_for_source(get_primary_source()) if hasattr(_fb_client, 'get_track_details'): _details = _fb_client.get_track_details(str(_track_id)) if _details and isinstance(_details, dict): _d_artists = _details.get('artists', []) if isinstance(_d_artists, list) and _d_artists: _d_first = _d_artists[0] _d_name = _d_first.get('name', '') if isinstance(_d_first, dict) else str(_d_first) if _d_name and _d_name.strip().lower() not in _junk_artist_names: artist_context['name'] = _d_name.strip() logger.info(f"[Unknown Artist Guard] Resolved from metadata API: '{_d_name}'") _resolved = True except Exception as _guard_err: logger.error(f"[Unknown Artist Guard] Metadata re-fetch failed: {_guard_err}") if not _resolved: logger.error(f"[Unknown Artist Guard] Could not resolve artist — proceeding with '{_artist_name}'") context['artist'] = artist_context logger.debug(f"[Debug] Post-processing - track_info type: {type(track_info)}, is None: {track_info is None}, is empty: {not track_info}") if track_info: logger.debug(f"[Debug] Post-processing - track_info keys: {list(track_info.keys())}") is_album_download = bool(context.get("is_album_download", False)) album_info = build_import_album_info(context, force_album=is_album_download) if is_album_download: if has_clean_metadata: logger.info("Album context with clean metadata found - using normalized album info") else: logger.warning("Album context found without clean metadata - using normalized album info") elif not album_info.get('is_album'): logger.info("Single track download - attempting album detection") detected_album_info = detect_album_info_web(context, artist_context) if detected_album_info: album_info = detected_album_info if album_info and album_info['is_album'] and not is_album_download: logger.info( "SMART ALBUM GROUPING for track=%r original_album=%r", album_info.get('clean_track_name', 'Unknown'), album_info.get('album_name', 'None'), ) original_album = original_search.get("album") if original_search.get("album") else None consistent_album_name = resolve_album_group(artist_context, album_info, original_album) album_info['album_name'] = consistent_album_name logger.info("Album grouping complete: final_album=%r", consistent_album_name) elif album_info and album_info['is_album'] and is_album_download: logger.info( "EXPLICIT ALBUM DOWNLOAD - preserving album name=%r; skipping smart grouping", album_info.get('album_name', 'None'), ) context['_audio_quality'] = get_audio_quality_string(file_path) if context['_audio_quality']: logger.info(f"Audio quality detected: {context['_audio_quality']}") _skip_bit_depth = _should_skip_quarantine_check(context, 'bit_depth') rejection_reason = None if _skip_bit_depth else check_flac_bit_depth(file_path, context) if _skip_bit_depth: logger.info(f"[BitDepth] Skipped (user approval) for {_basename}") if rejection_reason: try: quarantine_path = move_to_quarantine( file_path, context, rejection_reason, automation_engine, trigger='bit_depth', ) _mark_task_quarantined(context, quarantine_path) logger.info(f"File quarantined due to bit depth filter: {quarantine_path}") except Exception as quarantine_error: logger.error(f"Quarantine failed ({quarantine_error}), deleting file: {file_path}") try: os.remove(file_path) except Exception as e: logger.debug("delete quarantine fallback: %s", e) context['_bitdepth_rejected'] = True with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] task_id = context.get('task_id') batch_id = context.get('batch_id') if task_id: with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = f"Bit depth filter: {rejection_reason}" if task_id and batch_id: _notify_download_completed(batch_id, task_id, success=False) return file_ext = os.path.splitext(file_path)[1] clean_track_name = get_import_clean_title( context, album_info=album_info, default=original_search.get('title', 'Unknown Track'), ) # Resolve track_number from the richest available source. # See ``core/imports/track_number.py`` for the resolution # chain — pure function, unit-tested in isolation, single # place to fix the rule. from core.imports.track_number import resolve_track_number track_info_for_resolve = context.get('track_info') if isinstance(context, dict) else None track_number = resolve_track_number(album_info, track_info_for_resolve, file_path) logger.debug( "Final track_number processing: source=%s album_info=%s resolved=%s", album_info.get('source', 'unknown'), album_info.get('track_number', 'NOT_FOUND'), track_number, ) if not isinstance(track_number, int) or track_number < 1: logger.error(f"Invalid track number ({track_number}), defaulting to 1") track_number = 1 logger.debug(f"FINAL track_number used for filename: {track_number}") album_info['track_number'] = track_number album_info['clean_track_name'] = clean_track_name logger.info(f"[FIX] Updated album_info track_number to {track_number} for consistent metadata") final_path, _ = build_final_path_for_track(context, artist_context, album_info, file_ext) logger.info(f"Resolved path: '{final_path}'") context['_final_processed_path'] = final_path try: logger.warning(f"[Metadata Input] artist: '{artist_context.get('name', 'MISSING')}' (id: {artist_context.get('id', 'MISSING')})") if album_info: logger.warning( f"[Metadata Input] album: '{album_info.get('album_name', 'MISSING')}', " f"track#: {album_info.get('track_number', 'MISSING')}, disc#: {album_info.get('disc_number', 'MISSING')}, " f"source: {album_info.get('source', 'unknown')}" ) else: logger.info("[Metadata Input] album_info: None (single track)") _enhance_started = time.time() enhance_file_metadata(file_path, context, artist_context, album_info, runtime=metadata_runtime) # The enhancement block is the pipeline's biggest variable cost # (external source lookups) and used to be a silent multi-minute # gap in the log — always say how long it took. logger.info(f"Metadata enhancement took {time.time() - _enhance_started:.1f}s") except Exception as meta_err: import traceback pp_logger.info(f"[inner] Metadata enhancement FAILED for {context_key}: {meta_err}\n{traceback.format_exc()}") if should_wipe_tags_on_enhancement_failure(has_clean_metadata): wipe_source_tags(file_path) else: logger.warning( "[Metadata] Enhancement failed but import has clean/matched metadata — " "preserving the file's existing tags (not wiping): %s", os.path.basename(file_path)) _enhance_source_info = context.get('track_info', {}).get('source_info') or {} if isinstance(_enhance_source_info, str): try: _enhance_source_info = json.loads(_enhance_source_info) except (json.JSONDecodeError, TypeError): _enhance_source_info = {} is_enhance_download = _enhance_source_info.get('enhance', False) logger.info(f"Moving '{os.path.basename(file_path)}' to '{final_path}'") if os.path.exists(final_path): if not os.path.exists(file_path): logger.info(f"[Protection] Destination exists and source already gone - file already transferred: {os.path.basename(final_path)}") return try: from mutagen import File as MutagenFile existing_file = MutagenFile(final_path) has_metadata = existing_file is not None and len(existing_file.tags or {}) > 2 if has_metadata and not is_enhance_download: _replace_lower = config_manager.get('import.replace_lower_quality', False) if _replace_lower: _existing_tier = get_quality_tier_from_extension(final_path) _incoming_tier = get_quality_tier_from_extension(file_path) if _incoming_tier[1] < _existing_tier[1]: logger.info(f"[Quality Replace] Replacing {_existing_tier[0]} with {_incoming_tier[0]}: {os.path.basename(final_path)}") try: os.remove(final_path) except Exception as e: logger.error(f"[Quality Replace] Could not remove existing file: {e}") else: logger.info( f"[Protection] Existing file is same or better quality ({_existing_tier[0]} vs {_incoming_tier[0]}) - skipping: " f"{os.path.basename(final_path)}" ) try: os.remove(file_path) except FileNotFoundError: pass except Exception as e: logger.error(f"[Protection] Error removing redundant file: {e}") return else: logger.info(f"[Protection] Existing file already has metadata enhancement - skipping overwrite: {os.path.basename(final_path)}") logger.info(f"[Protection] Removing redundant download file: {os.path.basename(file_path)}") try: os.remove(file_path) except FileNotFoundError: logger.error(f"[Protection] Could not remove redundant file (already gone): {file_path}") except Exception as e: logger.error(f"[Protection] Error removing redundant file: {e}") return elif is_enhance_download: logger.info(f"[Enhance] Quality enhance mode — replacing existing file: {os.path.basename(final_path)}") try: os.remove(final_path) except Exception as e: logger.error(f"[Enhance] Could not remove existing file for replacement: {e}") else: logger.info(f"[Protection] Existing file lacks metadata - safe to overwrite: {os.path.basename(final_path)}") try: os.remove(final_path) except FileNotFoundError: pass except Exception as check_error: logger.error(f"[Protection] Error checking existing file metadata, proceeding with overwrite: {check_error}") try: if os.path.exists(final_path): os.remove(final_path) except Exception as e: logger.error(f"[Protection] Failed to remove existing file for overwrite: {e}") if not os.path.exists(file_path): if os.path.exists(final_path): logger.info(f"[Pre-Move] Source already gone and destination exists - another thread completed transfer: {os.path.basename(final_path)}") download_cover_art(album_info, os.path.dirname(final_path), context) generate_lrc_file(final_path, context, artist_context, album_info) return expected_dir = os.path.dirname(final_path) expected_stem = os.path.splitext(os.path.basename(final_path))[0] expected_ext = os.path.splitext(final_path)[1] found_variant = None check_exts = {expected_ext} if expected_ext == '.flac' and config_manager.get('lossy_copy.enabled', False) and config_manager.get('lossy_copy.delete_original', False): _lossy_ext_map = {'mp3': '.mp3', 'opus': '.opus', 'aac': '.m4a'} _lossy_codec = config_manager.get('lossy_copy.codec', 'mp3') check_exts.add(_lossy_ext_map.get(_lossy_codec, '.mp3')) if os.path.exists(expected_dir): for f in os.listdir(expected_dir): f_ext = os.path.splitext(f)[1].lower() if f_ext in check_exts and os.path.splitext(f)[0].startswith(expected_stem): found_variant = os.path.join(expected_dir, f) break if found_variant: logger.debug(f"[Pre-Move] Source gone but found variant in destination (stream processor handled it): {os.path.basename(found_variant)}") context['_final_processed_path'] = found_variant download_cover_art(album_info, expected_dir, context) generate_lrc_file(found_variant, context, artist_context, album_info) return logger.warning(f"[Pre-Move] Source file gone and no matching file in destination: {os.path.basename(file_path)}") raise FileNotFoundError(f"Source file vanished before move and destination does not exist: {file_path}") safe_move_file(file_path, final_path) cleanup_slskd_dedup_siblings(file_path) if is_enhance_download and _enhance_source_info.get('original_file_path'): original_enhance_path = _enhance_source_info['original_file_path'] if os.path.normpath(original_enhance_path) != os.path.normpath(final_path) and os.path.exists(original_enhance_path): try: os.remove(original_enhance_path) old_fmt = os.path.splitext(original_enhance_path)[1] new_fmt = os.path.splitext(final_path)[1] logger.info(f"[Enhance] Upgraded {old_fmt} → {new_fmt}: {os.path.basename(final_path)}") except Exception as e: logger.error(f"[Enhance] Could not remove old-format file: {e}") elif is_enhance_download: old_fmt = _enhance_source_info.get('original_format', 'unknown') new_fmt = os.path.splitext(final_path)[1] logger.info(f"[Enhance] Replaced in-place ({old_fmt} → {new_fmt}): {os.path.basename(final_path)}") download_cover_art(album_info, os.path.dirname(final_path), context) generate_lrc_file(final_path, context, artist_context, album_info) if config_manager.get('post_processing.replaygain_enabled', False): try: from core.replaygain import analyze_track as _rg_analyze, write_replaygain_tags as _rg_write, is_ffmpeg_available as _rg_ffmpeg_ok, RG_REFERENCE_LUFS as _RG_REF if _rg_ffmpeg_ok(): lufs, peak_dbfs = _rg_analyze(final_path) gain_db = _RG_REF - lufs _rg_write(final_path, gain_db, peak_dbfs) pp_logger.info(f"ReplayGain: {gain_db:+.2f} dB, peak {peak_dbfs:.2f} dBFS — {os.path.basename(final_path)}") except Exception as rg_err: pp_logger.debug(f"ReplayGain analysis skipped: {rg_err}") downsampled_path = downsample_hires_flac(final_path, context) if downsampled_path: final_path = downsampled_path context['_final_processed_path'] = final_path _persist_verification_status(context, final_path) blasphemy_path = create_lossy_copy(final_path) if blasphemy_path: context['_final_processed_path'] = blasphemy_path downloads_path = docker_resolve_path(config_manager.get('soulseek.download_path', './downloads')) cleanup_empty_directories(downloads_path, file_path) logger.info(f"Post-processing complete for: {context.get('_final_processed_path', final_path)}") emit_track_downloaded(context, automation_engine) record_library_history_download(context) record_download_provenance(context) record_soulsync_library_entry(context, artist_context, album_info) try: completed_path = context.get('_final_processed_path', final_path) batch_id_for_repair = context.get('batch_id') if completed_path and batch_id_for_repair and repair_worker: album_folder = os.path.dirname(str(completed_path)) if album_folder: repair_worker.register_folder(batch_id_for_repair, album_folder) except Exception as repair_err: logger.error(f"[Post-Process] Repair folder registration failed: {repair_err}") try: completed_path = context.get('_final_processed_path', final_path) batch_id_for_consistency = context.get('batch_id') if completed_path and batch_id_for_consistency and album_info and album_info.get('is_album'): _file_info = { 'path': str(completed_path), 'track_number': album_info.get('track_number', 1), 'disc_number': album_info.get('disc_number', 1), 'title': get_import_clean_title( context, album_info=album_info, default=album_info.get('clean_track_name', ''), ), } with tasks_lock: if batch_id_for_consistency in download_batches: download_batches[batch_id_for_consistency].setdefault('_consistency_files', []).append(_file_info) except Exception as cons_err: logger.error(f"[Post-Process] Album consistency registration failed: {cons_err}") try: check_and_remove_from_wishlist(context) except Exception as wishlist_error: logger.error(f"[Post-Process] Error checking wishlist removal: {wishlist_error}") task_id = context.get('task_id') batch_id = context.get('batch_id') if task_id and batch_id: logger.info(f"[Post-Process] Calling completion callback for task {task_id} in batch {batch_id}") with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['stream_processed'] = True download_tasks[task_id]['status'] = 'completed' # Additive: record where the imported file landed so downstream # (playlist materialization) knows the real path of a freshly # downloaded track without re-resolving it. download_tasks[task_id]['final_file_path'] = context.get('_final_processed_path') logger.info(f"[Post-Process] Marked task {task_id} as completed") _notify_download_completed(batch_id, task_id, success=True) except Exception as e: import traceback pp_logger.info(f"[inner] EXCEPTION in post-processing for {context_key}: {e}") pp_logger.info(traceback.format_exc()) logger.error(f"\nCRITICAL ERROR in post-processing for {context_key}: {e}") traceback.print_exc() source_exists = os.path.exists(file_path) if file_path else False if source_exists: if context_key in processed_download_ids: processed_download_ids.remove(context_key) logger.warning(f"Removed {context_key} from processed set - will retry on next check") with matched_context_lock: if context_key not in matched_downloads_context: matched_downloads_context[context_key] = context logger.warning(f"Re-added {context_key} to context for retry") else: logger.warning(f"Source file gone, not retrying: {context_key}") finally: file_lock.release() with post_process_locks_lock: post_process_locks.pop(context_key, None) def _attempt_version_mismatch_fallback(context, task_id, batch_id, runtime, metadata_runtime): """Opt-in last resort once AcoustID retries are exhausted: accept the best quarantined version-mismatch candidate for this track instead of failing. Delegates the decision + safety rules to ``core.imports.version_mismatch_fallback`` (version-mismatch only, all the same matched version, >= min_count, AcoustID-only bypass). Returns True when a candidate was accepted and re-dispatched — the caller then skips marking the task failed. """ try: download_path = docker_resolve_path( config_manager.get('soulseek.download_path', './downloads') ) quarantine_dir = os.path.join(download_path, 'ss_quarantine') restore_dir = os.path.join(download_path, 'Transfer') expected_title = get_import_clean_title(context, default='') expected_artist = get_import_clean_artist(context, default='') if not expected_title or not expected_artist: return False def _reprocess(restored_path, ctx, tid, bid): new_key = f"vmfallback_{tid}_{int(time.time())}" threading.Thread( target=lambda: post_process_matched_download_with_verification( new_key, ctx, restored_path, tid, bid, runtime, metadata_runtime ), daemon=True, ).start() return try_accept_version_mismatch_fallback( quarantine_dir=quarantine_dir, restore_dir=restore_dir, expected_title=expected_title, expected_artist=expected_artist, task_id=task_id, batch_id=batch_id, config_get=config_manager.get, list_entries=list_quarantine_entries, approve_entry=approve_quarantine_entry, reprocess=_reprocess, ) except Exception as exc: pp_logger.debug("[Version-Mismatch Fallback] skipped due to error: %s", exc) return False def post_process_matched_download_with_verification(context_key, context, file_path, task_id, batch_id, runtime, metadata_runtime=None): on_download_completed = getattr(runtime, "on_download_completed", None) def _notify_download_completed(batch_id, task_id, success=True): if on_download_completed: on_download_completed(batch_id, task_id, success=success) logger = pp_logger try: original_task_id = context.pop('task_id', None) original_batch_id = context.pop('batch_id', None) post_process_matched_download(context_key, context, file_path, runtime, metadata_runtime=metadata_runtime) if original_task_id: context['task_id'] = original_task_id if original_batch_id: context['batch_id'] = original_batch_id if context.get('_race_guard_failed'): logger.info(f"Race guard: source file gone for task {task_id} — marking as failed") with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = 'Source file was already processed or removed by another task' with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] _notify_download_completed(batch_id, task_id, success=False) return if context.get('_acoustid_quarantined'): failure_msg = context.get('_acoustid_failure_msg', 'AcoustID verification failed') # Before failing outright, try the next-best candidate. The wrong # file was just quarantined; re-running the worker (with the bad # source flagged used) picks the runner-up match instead. with matched_context_lock: matched_downloads_context.pop(context_key, None) if _requeue_quarantined_task_for_retry(task_id, batch_id, 'acoustid'): logger.info( f"AcoustID mismatch for task {task_id} — retrying next-best candidate: {failure_msg}" ) return # Retries exhausted. Opt-in last resort: if every quarantined # candidate for this track failed the SAME version mismatch (e.g. all # instrumental), accept the best one rather than leaving it missing. if _attempt_version_mismatch_fallback(context, task_id, batch_id, runtime, metadata_runtime): return logger.info(f"File was quarantined by AcoustID verification (task={task_id}): {failure_msg}") with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = f"AcoustID verification failed: {failure_msg}" _eid = context.get('_quarantine_entry_id') if _eid: download_tasks[task_id]['quarantine_entry_id'] = _eid _notify_download_completed(batch_id, task_id, success=False) return if context.get('_simple_download_completed'): expected_final_path = context.get('_final_path') if expected_final_path and os.path.exists(expected_final_path): with tasks_lock: if task_id in download_tasks: _mark_task_completed(task_id, context.get('track_info')) with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] _notify_download_completed(batch_id, task_id, success=True) return logger.info( f"FAILED simple download file not found at: {expected_final_path} " f"(task={task_id}, context={context_key})" ) with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = ( f"Downloaded file not found at expected location: {os.path.basename(expected_final_path)}" ) with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] _notify_download_completed(batch_id, task_id, success=False) return # Integrity rejection — the inner pipeline quarantined the file # because audio integrity (size / parse / duration) failed. Wrapper # was previously falling through to "assuming success" because # quarantined files have no _final_processed_path, which left the # task showing ✅ Completed in the UI even though the file is in # quarantine. Reported by user when downloading Mr. Morale: 3 # tracks (Rich Interlude, Savior Interlude, Savior) showed # Completed in the modal but were missing on disk because their # source files failed integrity and were quarantined. if context.get('_integrity_failure_msg'): failure_msg = context.get('_integrity_failure_msg', 'unknown') # Integrity/duration mismatch (truncated transfer, wrong-length cut, # etc). Same treatment as an AcoustID mismatch: quarantine the bad # file and retry the next-best candidate before failing. with matched_context_lock: matched_downloads_context.pop(context_key, None) if _requeue_quarantined_task_for_retry(task_id, batch_id, 'integrity'): logger.info( f"Integrity check failed for task {task_id} — retrying next-best candidate: {failure_msg}" ) return logger.error( f"Task {task_id} failed integrity check — marking failed: {failure_msg}" ) with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = ( f"File integrity check failed: {failure_msg}" ) _eid = context.get('_quarantine_entry_id') if _eid: download_tasks[task_id]['quarantine_entry_id'] = _eid _notify_download_completed(batch_id, task_id, success=False) return # Race guard failure — inner code set this when the source file # disappeared and there was no known destination to fall back on # (vs the legitimate race-guard skip where a sibling thread # already moved the file to its destination). if context.get('_race_guard_failed'): logger.error(f"Task {task_id} failed race guard — source file gone with no known destination") with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = ( "Source file disappeared before post-processing could complete" ) with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] _notify_download_completed(batch_id, task_id, success=False) return expected_final_path = context.get('_final_processed_path') if not expected_final_path: logger.info(f"No _final_processed_path in context for task {task_id} — cannot verify, assuming success") with tasks_lock: if task_id in download_tasks: _mark_task_completed(task_id, context.get('track_info')) if context.get('_verification_status'): download_tasks[task_id]['verification_status'] = context['_verification_status'] with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] _notify_download_completed(batch_id, task_id, success=True) return if os.path.exists(expected_final_path): redownload_ctx = None with tasks_lock: if task_id in download_tasks: _mark_task_completed(task_id, context.get('track_info')) download_tasks[task_id]['metadata_enhanced'] = True if context.get('_verification_status'): download_tasks[task_id]['verification_status'] = context['_verification_status'] redownload_ctx = download_tasks[task_id].get('_redownload_context') with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] if redownload_ctx: try: old_path = redownload_ctx.get('old_file_path') lib_track_id = redownload_ctx.get('library_track_id') if redownload_ctx.get('delete_old_file') and old_path and os.path.exists(old_path): if os.path.normpath(old_path) != os.path.normpath(expected_final_path): os.remove(old_path) logger.info(f"[Redownload] Deleted old file: {old_path}") if lib_track_id and expected_final_path: _rd_db = get_database() _rd_conn = _rd_db._get_connection() _rd_cursor = _rd_conn.cursor() _rd_cursor.execute( """ UPDATE tracks SET file_path = ?, updated_at = CURRENT_TIMESTAMP WHERE id = ? """, (expected_final_path, lib_track_id), ) _rd_conn.commit() _rd_conn.close() logger.info(f"[Redownload] Updated DB path for track {lib_track_id}") except Exception as e: logger.error(f"[Redownload] Post-processing hook error: {e}") _notify_download_completed(batch_id, task_id, success=True) else: track_name = get_import_clean_title(context, default=context_key) logger.info(f"FAILED verification for '{track_name}' (task={task_id})") logger.info(f" expected_final_path: {expected_final_path}") logger.info(f" file_path (source): {file_path}, exists={os.path.exists(file_path)}") logger.info( f" is_album={context.get('is_album_download', False)}, " f"has_clean_data={get_import_has_clean_metadata(context)}" ) expected_dir = os.path.dirname(expected_final_path) if os.path.exists(expected_dir): dir_contents = os.listdir(expected_dir) logger.info(f" directory contains {len(dir_contents)} files: {dir_contents[:20]}") else: logger.info(f" directory does not exist: {expected_dir}") with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = ( f'File verification failed: expected file at {os.path.basename(expected_final_path)} but it was not found after processing' ) with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] _notify_download_completed(batch_id, task_id, success=False) except Exception as e: import traceback logger.info(f"EXCEPTION in post-processing for '{context_key}' (task={task_id}): {e}") logger.info(traceback.format_exc()) with tasks_lock: if task_id in download_tasks: download_tasks[task_id]['status'] = 'failed' download_tasks[task_id]['error_message'] = f"Post-processing verification failed: {str(e)}" with matched_context_lock: if context_key in matched_downloads_context: del matched_downloads_context[context_key] _notify_download_completed(batch_id, task_id, success=False)