Tighten legacy logging output

- collapse old multi-line debug bursts into single structured rows
- remove leftover DEBUG-style prefixes from message text
- keep the app log readable without losing useful trace detail
This commit is contained in:
Antti Kettunen 2026-04-21 16:19:36 +03:00
parent 01d118daa6
commit 71e114b6fe
No known key found for this signature in database
GPG key ID: C6B2A3D250359BD7
8 changed files with 221 additions and 113 deletions

View file

@ -930,10 +930,16 @@ class DatabaseUpdateWorker:
if (db_track.title != current_title or if (db_track.title != current_title or
db_track.artist_name != current_artist or db_track.artist_name != current_artist or
db_track.album_title != current_album): db_track.album_title != current_album):
logger.debug(f"Metadata change detected for track ID {track_id}:") logger.debug(
logger.debug(f" Title: '{db_track.title}''{current_title}'") "Metadata change detected for track %s: title=%r%r artist=%r%r album=%r%r",
logger.debug(f" Artist: '{db_track.artist_name}''{current_artist}'") track_id,
logger.debug(f" Album: '{db_track.album_title}''{current_album}'") db_track.title,
current_title,
db_track.artist_name,
current_artist,
db_track.album_title,
current_album,
)
changes_detected += 1 changes_detected += 1
except Exception as e: except Exception as e:

View file

@ -61,10 +61,12 @@ class DownloadOrchestrator:
logger.info(f"Download Orchestrator initialized - Mode: {self.mode}") logger.info(f"Download Orchestrator initialized - Mode: {self.mode}")
if self.mode == 'hybrid': if self.mode == 'hybrid':
if self.hybrid_order: logger.info(
logger.info(f" Source priority: {''.join(self.hybrid_order)}") "Hybrid source order: order=%s primary=%s secondary=%s",
else: "".join(self.hybrid_order) if self.hybrid_order else "default",
logger.info(f" Primary: {self.hybrid_primary}, Fallback: {self.hybrid_secondary}") self.hybrid_primary,
self.hybrid_secondary,
)
def _safe_init(self, name, cls): def _safe_init(self, name, cls):
"""Initialize a download client, returning None on failure instead of crashing.""" """Initialize a download client, returning None on failure instead of crashing."""
@ -154,8 +156,10 @@ class DownloadOrchestrator:
except Exception: except Exception:
results[source] = False results[source] = False
status_parts = [f"{s}: {'' if ok else ''}" for s, ok in results.items()] logger.info(
logger.info(f" {' | '.join(status_parts)}") "Hybrid connection check: %s",
" | ".join(f"{source}={'ok' if ok else 'fail'}" for source, ok in results.items()),
)
return any(results.values()) return any(results.values())

View file

@ -1633,14 +1633,14 @@ class JellyfinClient:
def is_library_scanning(self, library_name: str = "Music") -> bool: def is_library_scanning(self, library_name: str = "Music") -> bool:
"""Check if Jellyfin library is currently scanning""" """Check if Jellyfin library is currently scanning"""
if not self.ensure_connection(): if not self.ensure_connection():
logger.debug("DEBUG: Not connected to Jellyfin, cannot check scan status") logger.debug("Not connected to Jellyfin, cannot check scan status")
return False return False
try: try:
# Check scheduled tasks for library scan activities # Check scheduled tasks for library scan activities
response = self._make_request('/ScheduledTasks') response = self._make_request('/ScheduledTasks')
if not response: if not response:
logger.debug("DEBUG: Could not get scheduled tasks") logger.debug("Could not get scheduled tasks")
return False return False
for task in response: for task in response:
@ -1650,10 +1650,14 @@ class JellyfinClient:
# Look for library scan related tasks that are running # Look for library scan related tasks that are running
if ('scan' in task_name or 'refresh' in task_name or 'library' in task_name): if ('scan' in task_name or 'refresh' in task_name or 'library' in task_name):
if task_state in ['Running', 'Cancelling']: if task_state in ['Running', 'Cancelling']:
logger.debug(f"DEBUG: Found running scan task: {task.get('Name')} (State: {task_state})") logger.debug(
"Found running scan task: name=%s state=%s",
task.get('Name'),
task_state,
)
return True return True
logger.debug("DEBUG: No active scan tasks detected") logger.debug("No active scan tasks detected")
return False return False
except Exception as e: except Exception as e:
@ -1819,4 +1823,4 @@ class JellyfinClient:
return True return True
except Exception as e: except Exception as e:
logger.error(f"Error setting metadata-only mode: {e}") logger.error(f"Error setting metadata-only mode: {e}")
return False return False

View file

@ -1088,7 +1088,14 @@ def check_album_completion(
else: else:
status = "missing" status = "missing"
logger.debug(f" Result: {owned_tracks}/{expected_tracks or total_tracks} tracks ({completion_percentage:.1f}%) - {status}") logger.debug(
"Album completion result: owned=%s expected=%s total=%s completion=%.1f status=%s",
owned_tracks,
expected_tracks or total_tracks,
total_tracks,
completion_percentage,
status,
)
return { return {
"id": album_id, "id": album_id,
@ -1137,7 +1144,12 @@ def check_single_completion(
if total_tracks == 0: if total_tracks == 0:
total_tracks = _resolve_completion_track_total(single_data, source_chain) or 1 total_tracks = _resolve_completion_track_total(single_data, source_chain) or 1
logger.debug(f"Checking {album_type}: '{single_name}' ({total_tracks} tracks)") logger.debug(
"Checking %s: name=%r tracks=%s",
album_type,
single_name,
total_tracks,
)
if album_type == 'ep' or total_tracks > 1: if album_type == 'ep' or total_tracks > 1:
try: try:
@ -1167,7 +1179,14 @@ def check_single_completion(
else: else:
status = "missing" status = "missing"
logger.debug(f" EP Result: {owned_tracks}/{expected_tracks or total_tracks} tracks ({completion_percentage:.1f}%) - {status}") logger.debug(
"EP completion result: owned=%s expected=%s total=%s completion=%.1f status=%s",
owned_tracks,
expected_tracks or total_tracks,
total_tracks,
completion_percentage,
status,
)
return { return {
"id": single_id, "id": single_id,
@ -1208,7 +1227,12 @@ def check_single_completion(
elif ext: elif ext:
formats = [ext] formats = [ext]
logger.debug(f" Single Result: {owned_tracks}/1 tracks ({completion_percentage:.1f}%) - {status}") logger.debug(
"Single completion result: owned=%s expected=1 completion=%.1f status=%s",
owned_tracks,
completion_percentage,
status,
)
return { return {
"id": single_id, "id": single_id,

View file

@ -937,7 +937,7 @@ class PlexClient:
def is_library_scanning(self, library_name: str = "Music") -> bool: def is_library_scanning(self, library_name: str = "Music") -> bool:
"""Check if Plex library is currently scanning""" """Check if Plex library is currently scanning"""
if not self.ensure_connection(): if not self.ensure_connection():
logger.debug(f"DEBUG: Not connected to Plex, cannot check scan status") logger.debug("Not connected to Plex, cannot check scan status")
return False return False
try: try:
@ -946,31 +946,31 @@ class PlexClient:
# Check if library has a scanning attribute or is refreshing # Check if library has a scanning attribute or is refreshing
# The Plex API exposes this through the library's refreshing property # The Plex API exposes this through the library's refreshing property
refreshing = hasattr(library, 'refreshing') and library.refreshing refreshing = hasattr(library, 'refreshing') and library.refreshing
logger.debug(f"DEBUG: Library.refreshing = {refreshing}") logger.debug("Library.refreshing = %s", refreshing)
if refreshing: if refreshing:
logger.debug(f"DEBUG: Library is refreshing") logger.debug("Library is refreshing")
return True return True
# Alternative method: Check server activities for scanning # Alternative method: Check server activities for scanning
try: try:
activities = self.server.activities() activities = self.server.activities()
logger.debug(f"DEBUG: Found {len(activities)} server activities") logger.debug("Found %s server activities", len(activities))
for activity in activities: for activity in activities:
# Look for library scan activities # Look for library scan activities
activity_type = getattr(activity, 'type', 'unknown') activity_type = getattr(activity, 'type', 'unknown')
activity_title = getattr(activity, 'title', 'unknown') activity_title = getattr(activity, 'title', 'unknown')
logger.debug(f"DEBUG: Activity - type: {activity_type}, title: {activity_title}") logger.debug("Activity - type=%s title=%s", activity_type, activity_title)
if (activity_type in ['library.scan', 'library.refresh'] and if (activity_type in ['library.scan', 'library.refresh'] and
library_name.lower() in activity_title.lower()): library_name.lower() in activity_title.lower()):
logger.debug(f"DEBUG: Found matching scan activity: {activity_title}") logger.debug("Found matching scan activity: %s", activity_title)
return True return True
except Exception as activities_error: except Exception as activities_error:
logger.debug(f"Could not check server activities: {activities_error}") logger.debug(f"Could not check server activities: {activities_error}")
logger.debug(f"DEBUG: No scan activity detected") logger.debug("No scan activity detected")
return False return False
except Exception as e: except Exception as e:

View file

@ -455,11 +455,23 @@ class SoulIDWorker:
matching.normalize_string(db_name) matching.normalize_string(db_name)
) )
if score >= self.album_match_threshold: if score >= self.album_match_threshold:
logger.debug(f" {source_name}: matched '{artist.name}' via album '{api_name}''{db_name}' (score={score:.2f})") logger.debug(
"%s matched artist=%r via album api=%r db=%r score=%.2f",
source_name,
artist.name,
api_name,
db_name,
score,
)
return discog return discog
except Exception as e: except Exception as e:
logger.debug(f" {source_name}: discography fetch failed for '{artist.name}': {e}") logger.debug(
"%s discography fetch failed for artist=%r: %s",
source_name,
artist.name,
e,
)
continue continue
return None return None

View file

@ -311,15 +311,17 @@ class WishlistService:
def _spotify_track_object_to_dict(self, spotify_track) -> Dict[str, Any]: def _spotify_track_object_to_dict(self, spotify_track) -> Dict[str, Any]:
"""Convert a Spotify track object or TrackResult object to a dictionary""" """Convert a Spotify track object or TrackResult object to a dictionary"""
try: try:
# Add debug logging to see what we're dealing with logger.debug(
logger.info(f"DEBUG: Converting track object to dict. Type: {type(spotify_track)}") "Converting track object to dict: type=%s has_title=%s has_artist=%s has_id=%s",
logger.info(f"DEBUG: Has 'title' attribute: {hasattr(spotify_track, 'title')}") type(spotify_track),
logger.info(f"DEBUG: Has 'artist' attribute: {hasattr(spotify_track, 'artist')}") hasattr(spotify_track, 'title'),
logger.info(f"DEBUG: Has 'id' attribute: {hasattr(spotify_track, 'id')}") hasattr(spotify_track, 'artist'),
hasattr(spotify_track, 'id'),
)
# Check if this is a TrackResult object (has title/artist but no id) # Check if this is a TrackResult object (has title/artist but no id)
if hasattr(spotify_track, 'title') and hasattr(spotify_track, 'artist') and not hasattr(spotify_track, 'id'): if hasattr(spotify_track, 'title') and hasattr(spotify_track, 'artist') and not hasattr(spotify_track, 'id'):
logger.info("DEBUG: Detected TrackResult object, converting...") logger.debug("Detected TrackResult object, converting")
# Handle TrackResult objects - these don't have Spotify IDs # Handle TrackResult objects - these don't have Spotify IDs
album_name = getattr(spotify_track, 'album', '') or getattr(spotify_track, 'title', 'Unknown Album') album_name = getattr(spotify_track, 'album', '') or getattr(spotify_track, 'title', 'Unknown Album')
result = { result = {
@ -333,19 +335,23 @@ class WishlistService:
'popularity': 0, 'popularity': 0,
'source': 'trackresult' 'source': 'trackresult'
} }
logger.info(f"DEBUG: TrackResult converted successfully: {result['name']} by {result['artists'][0]['name']}") logger.debug(
"TrackResult converted successfully: name=%s artist=%s",
result['name'],
result['artists'][0]['name'],
)
return result return result
# Handle regular Spotify Track objects # Handle regular Spotify Track objects
logger.info("DEBUG: Processing as Spotify Track object") logger.debug("Processing as Spotify Track object")
# Handle artists list carefully to avoid TrackResult serialization issues # Handle artists list carefully to avoid TrackResult serialization issues
artists_list = [] artists_list = []
raw_artists = getattr(spotify_track, 'artists', []) raw_artists = getattr(spotify_track, 'artists', [])
logger.info(f"DEBUG: Raw artists: {raw_artists}, type: {type(raw_artists)}") logger.debug("Raw artists: %r (type=%s)", raw_artists, type(raw_artists))
for artist in raw_artists: for artist in raw_artists:
logger.info(f"DEBUG: Processing artist: {artist}, type: {type(artist)}") logger.debug("Processing artist: %r (type=%s)", artist, type(artist))
if hasattr(artist, 'name'): if hasattr(artist, 'name'):
artists_list.append({'name': artist.name}) artists_list.append({'name': artist.name})
elif isinstance(artist, str): elif isinstance(artist, str):
@ -375,16 +381,20 @@ class WishlistService:
'disc_number': getattr(spotify_track, 'disc_number', 1) 'disc_number': getattr(spotify_track, 'disc_number', 1)
} }
logger.info(f"DEBUG: Spotify Track converted: {result['name']} by {[a['name'] for a in result['artists']]}") logger.debug(
"Spotify Track converted: name=%s artists=%s",
result['name'],
[a['name'] for a in result['artists']],
)
# Test JSON serialization before returning to catch any remaining issues # Test JSON serialization before returning to catch any remaining issues
try: try:
import json import json
json.dumps(result) json.dumps(result)
logger.info("DEBUG: Conversion result is JSON serializable") logger.debug("Conversion result is JSON serializable")
except Exception as json_error: except Exception as json_error:
logger.error(f"DEBUG: Conversion result is NOT JSON serializable: {json_error}") logger.error("Conversion result is NOT JSON serializable: %s", json_error)
logger.error(f"DEBUG: Result content: {result}") logger.error("Conversion result content: %r", result)
# Return a safe fallback # Return a safe fallback
return { return {
'id': f"fallback_{hash(str(spotify_track))}", 'id': f"fallback_{hash(str(spotify_track))}",
@ -413,4 +423,4 @@ def get_wishlist_service() -> WishlistService:
global _wishlist_service global _wishlist_service
if _wishlist_service is None: if _wishlist_service is None:
_wishlist_service = WishlistService() _wishlist_service = WishlistService()
return _wishlist_service return _wishlist_service

View file

@ -8206,14 +8206,9 @@ def get_beatport_hero_tracks():
# SMART FILTERING - Remove duplicates and invalid tracks # SMART FILTERING - Remove duplicates and invalid tracks
valid_tracks = [] valid_tracks = []
seen_urls = set() seen_urls = set()
filtered_reasons = collections.Counter()
logger.debug(f"Processing {len(tracks)} raw tracks from scraper (SMART FILTERING)...")
for i, track in enumerate(tracks): for i, track in enumerate(tracks):
logger.debug(f" Track {i+1}: {track.get('title', 'NO_TITLE')} - {track.get('artist', 'NO_ARTIST')}")
logger.debug(f" URL: {track.get('url', 'NO_URL')}")
logger.debug(f" Image: {'YES' if track.get('image_url') else 'NO'}")
# Extract and clean basic data # Extract and clean basic data
title = track.get('title', '').strip() title = track.get('title', '').strip()
artist = track.get('artist', '').strip() artist = track.get('artist', '').strip()
@ -8258,7 +8253,7 @@ def get_beatport_hero_tracks():
skip_reasons.append("Duplicate URL") skip_reasons.append("Duplicate URL")
if not is_valid: if not is_valid:
logger.debug(f" Track {i+1} filtered out: {', '.join(skip_reasons)}") filtered_reasons.update(skip_reasons)
continue continue
# Mark URL as seen for deduplication # Mark URL as seen for deduplication
@ -8301,7 +8296,16 @@ def get_beatport_hero_tracks():
break break
valid_tracks.append(track_data) valid_tracks.append(track_data)
logger.debug(f" Track {i+1} added: {title} - {artist}")
sample_titles = [f"{t['title']} - {t['artist']}" for t in valid_tracks[:3]]
logger.debug(
"Beatport smart filter summary: raw=%s valid=%s filtered=%s reasons=%s sample=%s",
len(tracks),
len(valid_tracks),
len(tracks) - len(valid_tracks),
dict(filtered_reasons),
sample_titles,
)
logger.info(f"Retrieved {len(valid_tracks)} valid unique Beatport tracks (SMART FILTERING)") logger.info(f"Retrieved {len(valid_tracks)} valid unique Beatport tracks (SMART FILTERING)")
@ -16257,10 +16261,14 @@ def _start_enhanced_album_download(enhanced_tracks, unmatched_tracks, spotify_ar
"has_full_spotify_metadata": True # Flag for robust processing "has_full_spotify_metadata": True # Flag for robust processing
} }
logger.info(f"Queued matched track: '{spotify_track['name']}' (track #{spotify_track['track_number']})") logger.info(
"Queued matched track: title=%r track_number=%s",
spotify_track['name'],
spotify_track['track_number'],
)
started_count += 1 started_count += 1
else: else:
logger.error(f"Failed to queue track: {filename}") logger.error("Failed to queue track: filename=%s", filename)
except Exception as e: except Exception as e:
logger.error(f"Error processing matched track: {e}") logger.error(f"Error processing matched track: {e}")
@ -16399,10 +16407,14 @@ def _start_album_download_tasks(album_result, spotify_artist, spotify_album):
"original_search_result": enhanced_context, # Contains corrected data + clean title "original_search_result": enhanced_context, # Contains corrected data + clean title
"is_album_download": True "is_album_download": True
} }
logger.info(f" + Queued track: {filename} (Matched to: '{corrected_meta.get('title')}')") logger.info(
"Queued track: filename=%s matched_title=%r",
filename,
corrected_meta.get('title'),
)
started_count += 1 started_count += 1
else: else:
logger.error(f" - Failed to queue track: {filename}") logger.error("Failed to queue track: filename=%s", filename)
except Exception as e: except Exception as e:
logger.error(f"Error processing track in album batch: {track_data.get('filename')}: {e}") logger.error(f"Error processing track in album batch: {track_data.get('filename')}: {e}")
@ -16804,35 +16816,44 @@ def _detect_album_info_web(context: dict, artist: dict) -> dict:
try: try:
# Log available data for debugging (GUI PARITY) # Log available data for debugging (GUI PARITY)
original_search = context.get("original_search_result", {}) original_search = context.get("original_search_result", {})
logger.info(f"\n[Album Detection] Starting for track: '{original_search.get('title', 'Unknown')}'") logger.info(
logger.info(f"[Data Available]:") "[Album Detection] start: track=%r clean_spotify_title=%r clean_spotify_album=%r "
logger.info(f" - Clean Spotify title: '{original_search.get('spotify_clean_title', 'None')}'") "filename_album=%r artist=%r clean_data=%s album_download=%s",
logger.info(f" - Clean Spotify album: '{original_search.get('spotify_clean_album', 'None')}'") original_search.get('title', 'Unknown'),
logger.info(f" - Filename album: '{original_search.get('album', 'None')}'") original_search.get('spotify_clean_title', 'None'),
logger.info(f" - Artist: '{artist.get('name', 'Unknown')}'") original_search.get('spotify_clean_album', 'None'),
logger.info(f" - Context has clean data: {context.get('has_clean_spotify_data', False)}") original_search.get('album', 'None'),
logger.info(f" - Is album download: {context.get('is_album_download', False)}") artist.get('name', 'Unknown'),
context.get('has_clean_spotify_data', False),
context.get('is_album_download', False),
)
spotify_album_context = context.get("spotify_album") spotify_album_context = context.get("spotify_album")
is_album_download = context.get("is_album_download", False) is_album_download = context.get("is_album_download", False)
artist_name = artist['name'] artist_name = artist['name']
logger.info(f"Album detection for '{original_search.get('title', 'Unknown')}' by '{artist_name}':") logger.info(
logger.info(f" Has album attr: {bool(original_search.get('album'))}") "[Album Detection] track=%r artist=%r has_album_attr=%s album=%r",
if original_search.get('album'): original_search.get('title', 'Unknown'),
logger.info(f" Album value: '{original_search.get('album')}'") artist_name,
bool(original_search.get('album')),
original_search.get('album'),
)
# --- THIS IS THE CRITICAL FIX --- # --- THIS IS THE CRITICAL FIX ---
# If this is part of a matched album download, we TRUST the context data completely. # If this is part of a matched album download, we TRUST the context data completely.
# This is the exact logic from downloads.py. # This is the exact logic from downloads.py.
if is_album_download and spotify_album_context: if is_album_download and spotify_album_context:
logger.info("Matched Album context found. Prioritizing pre-matched Spotify data.")
# We exclusively use the track number and title that were matched # We exclusively use the track number and title that were matched
# *before* the download started. We do not try to re-parse the filename. # *before* the download started. We do not try to re-parse the filename.
track_number = original_search.get('track_number', 1) track_number = original_search.get('track_number', 1)
clean_track_name = original_search.get('title', 'Unknown Track') clean_track_name = original_search.get('title', 'Unknown Track')
logger.info(f" -> Using pre-matched Track #{track_number} and Title '{clean_track_name}'") logger.info(
"[Album Detection] using matched context: track_number=%s title=%r album=%r",
track_number,
clean_track_name,
spotify_album_context['name'],
)
return { return {
'is_album': True, 'is_album': True,
@ -21333,11 +21354,12 @@ def _post_process_matched_download(context_key, context, file_path):
clean_track_name = original_search.get('spotify_clean_title', 'Unknown Track') clean_track_name = original_search.get('spotify_clean_title', 'Unknown Track')
clean_album_name = original_search.get('spotify_clean_album', 'Unknown Album') clean_album_name = original_search.get('spotify_clean_album', 'Unknown Album')
# DEBUG: Check what's in original_search logger.debug(
logger.debug("Path 1 - Clean Spotify data path:") "Path 1 - Clean Spotify data path: keys=%s has_track_number=%s track_number=%s",
logger.info(f" original_search keys: {list(original_search.keys())}") list(original_search.keys()),
logger.info(f" track_number in original_search: {'track_number' in original_search}") 'track_number' in original_search,
logger.info(f" track_number value: {original_search.get('track_number', 'NOT_FOUND')}") original_search.get('track_number', 'NOT_FOUND'),
)
album_info = { album_info = {
'is_album': True, 'is_album': True,
@ -21358,12 +21380,13 @@ def _post_process_matched_download(context_key, context, file_path):
spotify_album = context.get("spotify_album", {}) spotify_album = context.get("spotify_album", {})
clean_track_name = original_search.get('spotify_clean_title') or original_search.get('title', 'Unknown Track') clean_track_name = original_search.get('spotify_clean_title') or original_search.get('title', 'Unknown Track')
# DEBUG: Check what's in original_search for path 2 logger.debug(
logger.debug("Path 2 - Enhanced fallback album context path:") "Path 2 - Enhanced fallback album context path: keys=%s has_track_number=%s track_number=%s spotify_album=%s",
logger.info(f" original_search keys: {list(original_search.keys())}") list(original_search.keys()),
logger.info(f" track_number in original_search: {'track_number' in original_search}") 'track_number' in original_search,
logger.info(f" track_number value: {original_search.get('track_number', 'NOT_FOUND')}") original_search.get('track_number', 'NOT_FOUND'),
logger.info(f" spotify_album name: {spotify_album.get('name', 'NOT_FOUND')}") spotify_album.get('name', 'NOT_FOUND'),
)
# ENHANCEMENT: Use spotify_clean_album if available for consistency # ENHANCEMENT: Use spotify_clean_album if available for consistency
album_name = (original_search.get('spotify_clean_album') or album_name = (original_search.get('spotify_clean_album') or
@ -21391,8 +21414,11 @@ def _post_process_matched_download(context_key, context, file_path):
# Explicit album downloads already have the correct Spotify album name — # Explicit album downloads already have the correct Spotify album name —
# re-grouping would mangle names like "(Reworked and Remastered)" into "(Deluxe Edition)". # re-grouping would mangle names like "(Reworked and Remastered)" into "(Deluxe Edition)".
if album_info and album_info['is_album'] and not is_album_download: if album_info and album_info['is_album'] and not is_album_download:
logger.info(f"\nSMART ALBUM GROUPING for track: '{album_info.get('clean_track_name', 'Unknown')}'") logger.info(
logger.info(f" Original album: '{album_info.get('album_name', 'None')}'") "SMART ALBUM GROUPING for track=%r original_album=%r",
album_info.get('clean_track_name', 'Unknown'),
album_info.get('album_name', 'None'),
)
# Get original album name from context if available # Get original album name from context if available
original_album = None original_album = None
@ -21403,11 +21429,12 @@ def _post_process_matched_download(context_key, context, file_path):
consistent_album_name = _resolve_album_group(spotify_artist, album_info, original_album) consistent_album_name = _resolve_album_group(spotify_artist, album_info, original_album)
album_info['album_name'] = consistent_album_name album_info['album_name'] = consistent_album_name
logger.info(f" Final album name: '{consistent_album_name}'") logger.info("Album grouping complete: final_album=%r", consistent_album_name)
logger.info(f"Album grouping complete!\n")
elif album_info and album_info['is_album'] and is_album_download: elif album_info and album_info['is_album'] and is_album_download:
logger.info(f"\nEXPLICIT ALBUM DOWNLOAD - preserving Spotify album name: '{album_info.get('album_name', 'None')}'") logger.info(
logger.info(f" Skipping smart grouping (not needed for explicit album downloads)\n") "EXPLICIT ALBUM DOWNLOAD - preserving Spotify album name=%r; skipping smart grouping",
album_info.get('album_name', 'None'),
)
# 1. Get transfer path (directory creation handled by _build_final_path_for_track) # 1. Get transfer path (directory creation handled by _build_final_path_for_track)
file_ext = os.path.splitext(file_path)[1] file_ext = os.path.splitext(file_path)[1]
@ -21443,17 +21470,21 @@ def _post_process_matched_download(context_key, context, file_path):
final_track_name_sanitized = _sanitize_filename(clean_track_name) final_track_name_sanitized = _sanitize_filename(clean_track_name)
track_number = album_info['track_number'] track_number = album_info['track_number']
# DEBUG: Check final track_number values logger.debug(
logger.debug("Final track_number processing:") "Final track_number processing: source=%s album_info_track_number=%s track_number=%s",
logger.info(f" album_info source: {album_info.get('source', 'unknown')}") album_info.get('source', 'unknown'),
logger.info(f" album_info track_number: {album_info.get('track_number', 'NOT_FOUND')}") album_info.get('track_number', 'NOT_FOUND'),
logger.info(f" track_number variable: {track_number}") track_number,
)
# Fix: Handle None track_number # Fix: Handle None track_number
if track_number is None: if track_number is None:
logger.info(f"Track number is None, extracting from filename: {os.path.basename(file_path)}")
track_number = _extract_track_number_from_filename(file_path) track_number = _extract_track_number_from_filename(file_path)
logger.info(f" -> Extracted track number: {track_number}") logger.info(
"Track number was None; extracted from filename=%r -> %s",
os.path.basename(file_path),
track_number,
)
# Ensure track_number is valid # Ensure track_number is valid
if not isinstance(track_number, int) or track_number < 1: if not isinstance(track_number, int) or track_number < 1:
@ -29288,9 +29319,12 @@ def _run_post_processing_worker(task_id, batch_id):
# If no track number in context, extract from filename # If no track number in context, extract from filename
if track_number == 1 and found_file: if track_number == 1 and found_file:
logger.warning(f"[Verification] No track_number in context, extracting from filename: {os.path.basename(found_file)}")
track_number = _extract_track_number_from_filename(found_file) track_number = _extract_track_number_from_filename(found_file)
logger.info(f" -> Extracted track number: {track_number}") logger.warning(
"[Verification] missing track_number; extracted from filename=%r -> %s",
os.path.basename(found_file),
track_number,
)
# Ensure track_number is valid # Ensure track_number is valid
if not isinstance(track_number, int) or track_number < 1: if not isinstance(track_number, int) or track_number < 1:
@ -32990,24 +33024,37 @@ def get_spotify_playlists():
# Handle snapshot_id safely - may not exist in core Playlist class # Handle snapshot_id safely - may not exist in core Playlist class
playlist_snapshot = getattr(p, 'snapshot_id', '') playlist_snapshot = getattr(p, 'snapshot_id', '')
logger.info(f"Processing playlist: {p.name} (ID: {p.id})")
logger.info(f" - Playlist snapshot: '{playlist_snapshot}'")
logger.info(f" - Status info: {status_info}")
if 'last_synced' in status_info: if 'last_synced' in status_info:
stored_snapshot = status_info.get('snapshot_id') stored_snapshot = status_info.get('snapshot_id')
last_sync_time = datetime.fromisoformat(status_info['last_synced']).strftime('%b %d, %H:%M') last_sync_time = datetime.fromisoformat(status_info['last_synced']).strftime('%b %d, %H:%M')
logger.info(f" - Stored snapshot: '{stored_snapshot}'")
logger.info(f" - Snapshots match: {playlist_snapshot == stored_snapshot}")
if playlist_snapshot != stored_snapshot: if playlist_snapshot != stored_snapshot:
sync_status = f"Last Sync: {last_sync_time}" sync_status = f"Last Sync: {last_sync_time}"
logger.info(f" - Result: Needs Sync (showing: {sync_status})") logger.info(
"Playlist sync status: name=%s id=%s snapshot=%r stored_snapshot=%r result=Needs Sync display=%s",
p.name,
p.id,
playlist_snapshot,
stored_snapshot,
sync_status,
)
else: else:
sync_status = f"Synced: {last_sync_time}" sync_status = f"Synced: {last_sync_time}"
logger.info(f" - Result: {sync_status}") logger.info(
"Playlist sync status: name=%s id=%s snapshot=%r stored_snapshot=%r result=Synced display=%s",
p.name,
p.id,
playlist_snapshot,
stored_snapshot,
sync_status,
)
else: else:
logger.warning(f" - No last_synced found - Never Synced") logger.warning(
"Playlist sync status: name=%s id=%s snapshot=%r result=Never Synced display=%s",
p.name,
p.id,
playlist_snapshot,
sync_status,
)
playlist_data.append({ playlist_data.append({
"id": p.id, "name": p.name, "owner": p.owner, "id": p.id, "name": p.name, "owner": p.owner,
@ -46872,18 +46919,19 @@ def start_metadata_update():
add_activity_item("", "Metadata Update", "Plex client not available", "Now") add_activity_item("", "Metadata Update", "Plex client not available", "Now")
return jsonify({"success": False, "error": "Plex client not available"}), 400 return jsonify({"success": False, "error": "Plex client not available"}), 400
# DEBUG: Check Plex connection details logger.debug("Plex connection details: active_server=%s client=%s", active_server, media_client)
logger.debug(f"Active server: {active_server}")
logger.debug(f"Plex client: {media_client}")
if hasattr(media_client, 'server') and media_client.server: if hasattr(media_client, 'server') and media_client.server:
logger.debug(f"Plex server URL: {getattr(media_client.server, '_baseurl', 'NO_URL')}") logger.debug(
logger.debug(f"Plex server name: {getattr(media_client.server, 'friendlyName', 'NO_NAME')}") "Plex server details: url=%s name=%s",
getattr(media_client.server, '_baseurl', 'NO_URL'),
getattr(media_client.server, 'friendlyName', 'NO_NAME'),
)
# Check available libraries # Check available libraries
try: try:
sections = media_client.server.library.sections() sections = media_client.server.library.sections()
logger.debug(f"Available Plex libraries: {[(s.title, s.type) for s in sections]}") logger.debug("Available Plex libraries: %s", [(s.title, s.type) for s in sections])
except Exception as e: except Exception as e:
logger.debug(f"Error getting Plex libraries: {e}") logger.debug("Error getting Plex libraries: %s", e)
else: else:
logger.debug("Plex server is NOT connected!") logger.debug("Plex server is NOT connected!")