- Keep our v3 ranked-targets quality system (filter_and_rank, QualityTarget) in soulseek_client.py, settings.js, database presets, and index.html - Take upstream removal of standalone quality-scanner code: QualityScannerDeps + run_quality_scanner moved to repair job (core/repair_jobs/quality_upgrade_scanner.py) - Take upstream AAC-tier addition in database/music_database.py default profile - Take upstream removal of /api/quality-scanner/* routes from web_server.py - Remove test_discovery_quality_scanner.py (deleted upstream) - 47 upstream commits absorbed (2.7.3 + 2.7.4 including re-identify flow, dead-folder cleanup, track-number prefix strip, and more) Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
1282 lines
65 KiB
Python
1282 lines
65 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, check_quality_target, move_to_quarantine
|
||
from core.imports.silence import detect_broken_audio
|
||
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 quality filter"
|
||
if context.get('_silence_rejected'):
|
||
return "rejected by audio guard (incomplete or silent audio)"
|
||
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')})"
|
||
)
|
||
|
||
# Audio-completeness guard — runs right where the length is verified,
|
||
# BEFORE the AcoustID/quality gates, so a truncated file (container
|
||
# claims the full length but only ~30s actually decodes, e.g. HiFi/
|
||
# Monochrome HLS assembly) or a mostly-silent file is caught regardless
|
||
# of its quality verdict and gets the right reason. Same quarantine +
|
||
# next-candidate retry pattern as the integrity check.
|
||
_skip_audio = _should_skip_quarantine_check(context, 'silence')
|
||
audio_reason = None if _skip_audio else detect_broken_audio(file_path)
|
||
if audio_reason:
|
||
logger.error(f"[AudioGuard] Rejected {_basename}: {audio_reason}")
|
||
context['_silence_rejected'] = True
|
||
try:
|
||
quarantine_path = move_to_quarantine(
|
||
file_path, context, audio_reason, automation_engine,
|
||
trigger='silence',
|
||
)
|
||
_mark_task_quarantined(context, quarantine_path)
|
||
logger.warning("File quarantined — incomplete/silent audio: %s", 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 del_error:
|
||
logger.debug("delete broken file fallback: %s", del_error)
|
||
|
||
with matched_context_lock:
|
||
matched_downloads_context.pop(context_key, None)
|
||
|
||
task_id = context.get('task_id')
|
||
batch_id = context.get('batch_id')
|
||
# Try the next-best candidate before giving up — same pattern as
|
||
# the integrity / AcoustID / quality failures.
|
||
if _requeue_quarantined_task_for_retry(task_id, batch_id, 'silence'):
|
||
logger.info(
|
||
"Incomplete/silent audio for task %s — retrying next-best candidate: %s",
|
||
task_id, audio_reason,
|
||
)
|
||
return
|
||
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"Audio guard: {audio_reason}"
|
||
if task_id and batch_id:
|
||
_notify_download_completed(batch_id, task_id, success=False)
|
||
return
|
||
|
||
# QUALITY GATE — runs BEFORE AcoustID so (1) a wrong-quality file is
|
||
# rejected without paying for an AcoustID fingerprint, and (2) the real
|
||
# audio quality is recorded on the context (→ quarantine sidecar) for
|
||
# EVERY trigger, so it's known when reviewing/approving any quarantined
|
||
# file. force_import still never fires on a quality mismatch.
|
||
context['_audio_quality'] = get_audio_quality_string(file_path)
|
||
if context['_audio_quality']:
|
||
logger.info(f"Audio quality detected: {context['_audio_quality']}")
|
||
|
||
_skip_quality = _should_skip_quarantine_check(context, 'bit_depth') or \
|
||
_should_skip_quarantine_check(context, 'quality')
|
||
rejection_reason = None if _skip_quality else check_quality_target(file_path, context)
|
||
if _skip_quality:
|
||
logger.info(f"[QualityGuard] Skipped (user approval) for {_basename}")
|
||
if rejection_reason:
|
||
try:
|
||
quarantine_path = move_to_quarantine(
|
||
file_path,
|
||
context,
|
||
rejection_reason,
|
||
automation_engine,
|
||
trigger='quality',
|
||
)
|
||
_mark_task_quarantined(context, quarantine_path)
|
||
logger.info(f"File quarantined due to quality mismatch: {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
|
||
task_id = context.get('task_id')
|
||
batch_id = context.get('batch_id')
|
||
with matched_context_lock:
|
||
matched_downloads_context.pop(context_key, None)
|
||
|
||
# Try the next-best candidate before giving up — same pattern
|
||
# as AcoustID and integrity failures.
|
||
if _requeue_quarantined_task_for_retry(task_id, batch_id, 'quality'):
|
||
logger.info(
|
||
"Quality mismatch for task %s — retrying next-best candidate: %s",
|
||
task_id, rejection_reason,
|
||
)
|
||
return
|
||
|
||
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"Quality filter: {rejection_reason}"
|
||
if task_id and batch_id:
|
||
_notify_download_completed(batch_id, task_id, success=False)
|
||
return
|
||
|
||
_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'),
|
||
)
|
||
|
||
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, read_embedded_track_number
|
||
track_info_for_resolve = context.get('track_info') if isinstance(context, dict) else None
|
||
# "Track 01" bug: a single Deezer track is matched via an endpoint
|
||
# that omits track_position, so the context never carried the real
|
||
# number. The downloaded file itself does (deemix/source wrote it),
|
||
# so read it as a source between metadata and the filename guess.
|
||
embedded_track_number = read_embedded_track_number(file_path)
|
||
track_number = resolve_track_number(
|
||
album_info, track_info_for_resolve, file_path,
|
||
embedded_track_number=embedded_track_number,
|
||
)
|
||
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
|
||
|
||
# Quality / audio-guard quarantine. Unlike acoustid/integrity (whose
|
||
# retry+fail is driven by THIS wrapper below), the inner pipeline fully
|
||
# owns the quality and audio-guard outcome: it quarantines the file and
|
||
# then either re-queues the next-best candidate or marks the task failed
|
||
# and notifies. The wrapper must NOT continue to the "assume success"
|
||
# fall-through — that marked the quarantined file Completed, so the same
|
||
# track showed in BOTH Completed and Quarantine (e.g. an MP3-VBR rejected
|
||
# by a FLAC-only profile). It must also NOT mark it failed here, which
|
||
# would clobber a successful next-candidate retry. Just return.
|
||
if context.get('_bitdepth_rejected') or context.get('_silence_rejected'):
|
||
logger.info(
|
||
f"Task {task_id} quarantined by the quality/audio guard — inner "
|
||
f"pipeline already handled retry/fail; wrapper not marking completed"
|
||
)
|
||
return
|
||
|
||
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']
|
||
if context.get('_history_id'):
|
||
download_tasks[task_id]['history_id'] = context['_history_id']
|
||
if context.get('_audio_quality'):
|
||
download_tasks[task_id]['quality'] = context['_audio_quality']
|
||
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']
|
||
if context.get('_history_id'):
|
||
download_tasks[task_id]['history_id'] = context['_history_id']
|
||
if context.get('_audio_quality'):
|
||
download_tasks[task_id]['quality'] = context['_audio_quality']
|
||
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)
|