The download analysis already matches every track to a library row via check_track_exists / manual match, then discarded the result. Keep it: each analysis_results entry now carries matched_file_path + matched_track_id (the owned file's real location, or None). Symmetrically, a completed download task now records final_file_path (where the import landed). Purely additive, no behavior change, no new matching, zero perf cost — just stops throwing away what the pipeline already computed. This is the foundation for playlist materialization: owned + downloaded tracks both report where their real file is, so the folder can be built by name match, not source IDs.
1339 lines
68 KiB
Python
1339 lines
68 KiB
Python
"""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
|
||
|
||
playlist_folder_mode = track_info.get("_playlist_folder_mode", False)
|
||
logger.debug(f"[Debug] Post-processing - track_info type: {type(track_info)}, is None: {track_info is None}, is empty: {not track_info}")
|
||
logger.debug(f"[Debug] Post-processing - playlist_folder_mode: {playlist_folder_mode}")
|
||
if track_info:
|
||
logger.debug(f"[Debug] Post-processing - track_info keys: {list(track_info.keys())}")
|
||
|
||
if playlist_folder_mode:
|
||
playlist_name = track_info.get("_playlist_name", "Unknown Playlist")
|
||
logger.info(f"[Playlist Folder Mode] Organizing in playlist folder: {playlist_name}")
|
||
|
||
file_ext = os.path.splitext(file_path)[1]
|
||
final_path, _ = build_final_path_for_track(context, artist_context, None, file_ext)
|
||
logger.info(f"Playlist mode final path: '{final_path}'")
|
||
|
||
if not os.path.exists(file_path):
|
||
if os.path.exists(final_path):
|
||
logger.info(
|
||
f"[Playlist Folder Mode] Source gone but destination exists — already processed by another thread: "
|
||
f"{os.path.basename(final_path)}"
|
||
)
|
||
context['_final_processed_path'] = final_path
|
||
return
|
||
pp_logger.info(f"[inner] EXCEPTION in post-processing for {context_key}: Source file not found and destination does not exist: {file_path}")
|
||
raise FileNotFoundError(f"Source file not found and destination does not exist: {file_path}")
|
||
|
||
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
|
||
|
||
try:
|
||
logger.warning(
|
||
f"[Metadata Input] Playlist mode - artist: '{artist_context.get('name', 'MISSING')}' "
|
||
f"(id: {artist_context.get('id', 'MISSING')})"
|
||
)
|
||
enhance_file_metadata(file_path, context, artist_context, None, runtime=metadata_runtime)
|
||
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))
|
||
|
||
logger.info(f"Moving '{os.path.basename(file_path)}' to '{final_path}'")
|
||
safe_move_file(file_path, final_path)
|
||
context['_final_processed_path'] = final_path
|
||
cleanup_slskd_dedup_siblings(file_path)
|
||
|
||
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 — {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"[Playlist Folder Mode] Post-processing complete: {final_path}")
|
||
|
||
try:
|
||
check_and_remove_from_wishlist(context)
|
||
except Exception as wishlist_error:
|
||
logger.error(f"[Playlist Folder] Error checking wishlist removal: {wishlist_error}")
|
||
|
||
emit_track_downloaded(context, automation_engine)
|
||
record_library_history_download(context)
|
||
record_download_provenance(context)
|
||
|
||
try:
|
||
pf_album_info = build_import_album_info(context, force_album=False)
|
||
if not pf_album_info or not pf_album_info.get("album_name"):
|
||
pf_album_info = {
|
||
"is_album": True,
|
||
"album_name": playlist_name,
|
||
"track_number": track_info.get("track_number", 1) or 1,
|
||
"disc_number": track_info.get("disc_number", 1) or 1,
|
||
"clean_track_name": get_import_clean_title(
|
||
context,
|
||
default=get_import_original_search(context).get("title", "Unknown"),
|
||
),
|
||
"source": get_import_source(context) or "spotify",
|
||
}
|
||
elif not pf_album_info.get("is_album"):
|
||
pf_album_info["is_album"] = True
|
||
record_soulsync_library_entry(context, artist_context, pf_album_info)
|
||
except Exception as lib_err:
|
||
logger.error(f"[Playlist Folder] SoulSync library registration failed: {lib_err}")
|
||
|
||
task_id = context.get('task_id')
|
||
batch_id = context.get('batch_id')
|
||
if task_id and batch_id:
|
||
with tasks_lock:
|
||
if task_id in download_tasks:
|
||
download_tasks[task_id]['stream_processed'] = True
|
||
download_tasks[task_id]['status'] = 'completed'
|
||
download_tasks[task_id]['final_file_path'] = context.get('_final_processed_path')
|
||
logger.info(f"[Playlist Folder Mode] Marked task {task_id} as completed")
|
||
_notify_download_completed(batch_id, task_id, success=True)
|
||
return
|
||
|
||
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)
|