Merge pull request #343 from kettui/fix/replace-print-with-logger

Tidy up logging across the app
pull/344/head
BoulderBadgeDad 2 months ago committed by GitHub
commit 9863c947dc
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194

3
.gitignore vendored

@ -22,3 +22,6 @@ logs/*.log.*
# Auto-downloaded binaries
bin/
# Any hidden folders
**/.*/

@ -63,6 +63,7 @@ environment:
- FLASK_ENV=production # Flask environment
- PYTHONPATH=/app # Python path
- SOULSYNC_CONFIG_PATH=/app/config/config.json # Config file location
- SOULSYNC_LOG_LEVEL=INFO # Optional startup log level override, takes precedence over the UI-configured log level
- TZ=America/New_York # Timezone
```
@ -268,4 +269,4 @@ services:
- [ ] Configure firewall rules
- [ ] Set up backup strategy
- [ ] Test health checks
- [ ] Verify external service connectivity
- [ ] Verify external service connectivity

File diff suppressed because it is too large Load Diff

@ -5,8 +5,14 @@ import sqlite3
from typing import Dict, Any, Optional
from cryptography.fernet import Fernet, InvalidToken
from pathlib import Path
from utils.logging_config import get_logger
logger = get_logger("config")
class ConfigManager:
_VALID_LOG_LEVELS = frozenset({"DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"})
def __init__(self, config_path: str = "config/config.json"):
# Determine strict absolute path to settings.py directory to help resolve config.json
# This handles cases where CWD is different (e.g. running from /Users vs /Users/project)
@ -33,7 +39,7 @@ class ConfigManager:
# Default to project path even if it doesn't exist yet (for creation/fallback)
self.config_path = project_path
print(f"ConfigManager initialized with path: {self.config_path}")
logger.info(f"ConfigManager initialized with path: {self.config_path}")
self.config_data: Dict[str, Any] = {}
self._fernet: Optional[Fernet] = None
@ -45,7 +51,7 @@ class ConfigManager:
else:
self.database_path = self.base_dir / "database" / "music_library.db"
print(f"Database path set to: {self.database_path}")
logger.info(f"Database path set to: {self.database_path}")
self.load_config(str(self.config_path))
@ -107,7 +113,7 @@ class ConfigManager:
try:
import shutil
shutil.move(str(old_key_file), str(key_file))
print(f"[MIGRATE] Moved encryption key to {key_file}")
logger.info(f"Moved encryption key to {key_file}")
except Exception:
key_file = old_key_file # Fall back to old location
if key_file.exists():
@ -155,8 +161,10 @@ class ConfigManager:
return decrypted
except InvalidToken:
# Key mismatch — encrypted with a different key (key file deleted/replaced)
print(f"[ERROR] Failed to decrypt a config value — encryption key may have changed. "
f"Re-enter credentials in Settings or restore the original .encryption_key file.")
logger.error(
"Failed to decrypt a config value — encryption key may have changed. "
"Re-enter credentials in Settings or restore the original .encryption_key file."
)
return value
except Exception:
return value
@ -243,11 +251,11 @@ class ConfigManager:
needs_migration = True
break
if needs_migration:
print("[MIGRATE] Encrypting sensitive config values at rest...")
logger.info("Encrypting sensitive config values at rest...")
self._save_to_database(self.config_data)
print("[OK] Sensitive config values encrypted successfully")
logger.info("Sensitive config values encrypted successfully")
except Exception as e:
print(f"[WARN] Could not migrate encryption: {e}")
logger.warning(f"Could not migrate encryption: {e}")
def _ensure_database_exists(self):
"""Ensure database file and metadata table exist"""
@ -271,7 +279,7 @@ class ConfigManager:
conn.commit()
conn.close()
except Exception as e:
print(f"Warning: Could not ensure database exists: {e}")
logger.warning(f"Could not ensure database exists: {e}")
def _load_from_database(self) -> Optional[Dict[str, Any]]:
"""Load configuration from database, decrypting sensitive values."""
@ -289,18 +297,70 @@ class ConfigManager:
config_data = json.loads(row[0])
# Decrypt sensitive values (gracefully handles plaintext migration)
config_data = self._decrypt_sensitive(config_data)
print("[OK] Configuration loaded from database")
logger.info("Configuration loaded from database")
return config_data
else:
return None
except Exception as e:
print(f"Warning: Could not load config from database: {e}")
logger.warning(f"Could not load config from database: {e}")
return None
finally:
if conn:
conn.close()
def _load_stored_log_level(self) -> Optional[str]:
"""Load the persisted UI log level preference, if one exists."""
conn = None
try:
self._ensure_database_exists()
conn = sqlite3.connect(str(self.database_path), timeout=30.0)
conn.execute("PRAGMA journal_mode=WAL")
cursor = conn.cursor()
cursor.execute("SELECT value FROM metadata WHERE key = 'log_level'")
row = cursor.fetchone()
if not row or not row[0]:
return None
level = str(row[0]).upper()
if level not in self._VALID_LOG_LEVELS:
logger.warning(f"Ignoring invalid stored log level: {row[0]}")
return None
return level
except Exception as e:
logger.warning(f"Could not load stored log level from database: {e}")
return None
finally:
if conn:
conn.close()
def _load_env_log_level(self) -> Optional[str]:
"""Load the log level override from the environment, if one exists."""
raw_level = os.environ.get("SOULSYNC_LOG_LEVEL")
if not raw_level:
return None
level = raw_level.upper()
if level not in self._VALID_LOG_LEVELS:
logger.warning(f"Ignoring invalid SOULSYNC_LOG_LEVEL value: {raw_level}")
return None
return level
def _apply_log_level_overrides(self, config_data: Dict[str, Any]) -> Dict[str, Any]:
"""Overlay env and persisted log level preferences onto the loaded config."""
env_level = self._load_env_log_level()
if env_level:
config_data.setdefault("logging", {})["level"] = env_level
logger.info(f"Using log level from SOULSYNC_LOG_LEVEL: {env_level}")
return config_data
stored_level = self._load_stored_log_level()
if stored_level:
config_data.setdefault("logging", {})["level"] = stored_level
logger.info(f"Using stored logging level from database: {stored_level}")
return config_data
def _save_to_database(self, config_data: Dict[str, Any]) -> bool:
"""Save configuration to database, encrypting sensitive values."""
conn = None
@ -325,7 +385,7 @@ class ConfigManager:
return True
except Exception as e:
print(f"Error: Could not save config to database: {e}")
logger.error(f"Could not save config to database: {e}")
return False
finally:
if conn:
@ -337,12 +397,12 @@ class ConfigManager:
if self.config_path.exists():
with open(self.config_path, 'r') as f:
config_data = json.load(f)
print(f"[OK] Configuration loaded from {self.config_path}")
logger.info(f"Configuration loaded from {self.config_path}")
return config_data
else:
return None
except Exception as e:
print(f"Warning: Could not load config from file: {e}")
logger.warning(f"Could not load config from file: {e}")
return None
def _get_default_config(self) -> Dict[str, Any]:
@ -506,45 +566,45 @@ class ConfigManager:
2. config.json (migration from file-based config)
3. Defaults (fresh install)
"""
print(f"Loading configuration...")
logger.info("Loading configuration...")
# Try loading from database first
config_data = self._load_from_database()
if config_data:
# Configuration exists in database
self.config_data = config_data
self.config_data = self._apply_log_level_overrides(config_data)
# Ensure sensitive values are encrypted at rest (one-time migration)
self._migrate_encrypt_if_needed()
return
# Database is empty - try migration from config.json
print(f"Configuration not found in database. Attempting migration from: {self.config_path}")
logger.info(f"Configuration not found in database. Attempting migration from: {self.config_path}")
config_data = self._load_from_config_file()
if config_data:
# Migrate from config.json to database
print("[MIGRATE] Migrating configuration from config.json to database...")
logger.info("Migrating configuration from config.json to database...")
if self._save_to_database(config_data):
print("[OK] Configuration migrated successfully to database.")
self.config_data = config_data
logger.info("Configuration migrated successfully to database.")
self.config_data = self._apply_log_level_overrides(config_data)
return
else:
print("[WARN] Migration failed - using file-based config temporarily.")
self.config_data = config_data
logger.warning("Migration failed - using file-based config temporarily.")
self.config_data = self._apply_log_level_overrides(config_data)
return
# No config.json either - use defaults
print("[INFO] No existing configuration found (DB or File) - using defaults")
logger.info("No existing configuration found (DB or File) - using defaults")
config_data = self._get_default_config()
# Try to save defaults to database
if self._save_to_database(config_data):
print("[OK] Default configuration saved to database")
logger.info("Default configuration saved to database")
else:
print("[WARN] Could not save defaults to database - using in-memory config")
logger.warning("Could not save defaults to database - using in-memory config")
self.config_data = config_data
self.config_data = self._apply_log_level_overrides(config_data)
def _save_config(self):
"""Save configuration to database with retry on lock."""
@ -558,14 +618,14 @@ class ConfigManager:
if not success:
# Fallback: Try to save to config.json if database fails
print("[WARN] Database save failed - attempting file fallback")
logger.warning("Database save failed - attempting file fallback")
try:
self.config_path.parent.mkdir(parents=True, exist_ok=True)
with open(self.config_path, 'w') as f:
json.dump(self.config_data, f, indent=2)
print("[OK] Configuration saved to config.json as fallback")
logger.info("Configuration saved to config.json as fallback")
except Exception as e:
print(f"[ERROR] Failed to save configuration: {e}")
logger.error(f"Failed to save configuration: {e}")
def get(self, key: str, default: Any = None) -> Any:
keys = key.split('.')

@ -20,6 +20,7 @@ from typing import Dict, List, Optional, Any, Tuple
from pathlib import Path
import os
import shutil
import logging
import logging.handlers
from utils.logging_config import get_logger
@ -29,22 +30,23 @@ from config.settings import config_manager
FPCALC_BIN_DIR = Path(__file__).parent.parent / "bin"
CHROMAPRINT_VERSION = "1.5.1"
# Set up dedicated AcoustID logger with its own file
logger = get_logger("acoustid_client")
# Add dedicated file handler for AcoustID logs
_acoustid_log_path = Path(__file__).parent.parent / "logs" / "acoustid.log"
_acoustid_logger = logging.getLogger("soulsync.acoustid")
_acoustid_logger.setLevel(logging.DEBUG)
_acoustid_log_path = Path(config_manager.get('logging.path', 'logs/app.log')).parent / "acoustid.log"
_acoustid_log_path.parent.mkdir(parents=True, exist_ok=True)
_acoustid_file_handler = logging.handlers.RotatingFileHandler(
_acoustid_log_path, encoding='utf-8', maxBytes=5*1024*1024, backupCount=2
)
_acoustid_file_handler.setLevel(logging.DEBUG)
_acoustid_file_handler.setFormatter(logging.Formatter(
fmt='%(asctime)s - %(name)s - %(levelname)s - %(funcName)s:%(lineno)d - %(message)s',
datefmt='%Y-%m-%d %H:%M:%S'
))
logger.addHandler(_acoustid_file_handler)
logging.getLogger("newmusic.acoustid_verification").addHandler(_acoustid_file_handler)
if not _acoustid_logger.handlers:
_acoustid_file_handler = logging.handlers.RotatingFileHandler(
_acoustid_log_path, encoding='utf-8', maxBytes=5*1024*1024, backupCount=2
)
_acoustid_file_handler.setLevel(logging.DEBUG)
_acoustid_file_handler.setFormatter(logging.Formatter(
fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
datefmt='%Y-%m-%d %H:%M:%S'
))
_acoustid_logger.addHandler(_acoustid_file_handler)
_acoustid_logger.propagate = False
logger = get_logger("acoustid.client")
# Check if pyacoustid is available
try:
@ -194,7 +196,7 @@ class AcoustIDClient:
result = client.fingerprint_and_lookup("/path/to/audio.mp3")
if result:
for mbid in result['recording_mbids']:
print(f"Match: {mbid}")
logger.info(f"Match: {mbid}")
"""
def __init__(self):

@ -17,7 +17,7 @@ from utils.logging_config import get_logger
from core.acoustid_client import AcoustIDClient
from core.musicbrainz_client import MusicBrainzClient
logger = get_logger("acoustid_verification")
logger = get_logger("acoustid.verification")
# Thresholds
MIN_ACOUSTID_SCORE = 0.80 # Minimum AcoustID fingerprint score to trust

@ -12,6 +12,11 @@ import threading
import time
from collections import deque, defaultdict
from utils.logging_config import get_logger
logger = get_logger("api_call_tracker")
# Known rate limits per service (calls/minute)
RATE_LIMITS = {
@ -281,13 +286,16 @@ class ApiCallTracker:
with open(_PERSIST_PATH, 'w') as f:
json.dump({'ts': now, 'history': data, 'events': events}, f)
except Exception as e:
print(f"[ApiCallTracker] Failed to save history: {e}")
logger.error(f"[ApiCallTracker] Failed to save history: {e}")
def _load(self):
"""Restore 24h minute history from disk. Called on init."""
try:
if not os.path.exists(_PERSIST_PATH):
return
if os.path.getsize(_PERSIST_PATH) == 0:
logger.info(f"[ApiCallTracker] History file is empty, starting fresh: {_PERSIST_PATH}")
return
with open(_PERSIST_PATH, 'r') as f:
raw = json.load(f)
saved_ts = raw.get('ts', 0)
@ -305,9 +313,11 @@ class ApiCallTracker:
for e in events:
if e.get('ts', 0) >= cutoff:
self._events.append(e)
print(f"[ApiCallTracker] Restored history for {len(history)} services, {len(events)} events")
logger.info(f"[ApiCallTracker] Restored history for {len(history)} services, {len(events)} events")
except json.JSONDecodeError as e:
logger.warning(f"[ApiCallTracker] History file is not valid JSON, starting fresh: {_PERSIST_PATH} ({e})")
except Exception as e:
print(f"[ApiCallTracker] Failed to load history: {e}")
logger.error(f"[ApiCallTracker] Failed to load history: {e}")
# Singleton instance

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

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

@ -1633,14 +1633,14 @@ class JellyfinClient:
def is_library_scanning(self, library_name: str = "Music") -> bool:
"""Check if Jellyfin library is currently scanning"""
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
try:
# Check scheduled tasks for library scan activities
response = self._make_request('/ScheduledTasks')
if not response:
logger.debug("DEBUG: Could not get scheduled tasks")
logger.debug("Could not get scheduled tasks")
return False
for task in response:
@ -1650,10 +1650,14 @@ class JellyfinClient:
# 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 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
logger.debug("DEBUG: No active scan tasks detected")
logger.debug("No active scan tasks detected")
return False
except Exception as e:
@ -1819,4 +1823,4 @@ class JellyfinClient:
return True
except Exception as e:
logger.error(f"Error setting metadata-only mode: {e}")
return False
return False

@ -421,7 +421,7 @@ class MusicMatchingEngine:
if is_likely_album and 4 <= len(potential_album_part) <= 30:
cleaned_title = re.sub(dash_pattern, '', track_title).strip()
print(f"Heuristic album detection: '{original_title}''{cleaned_title}' (removed: '{potential_album_part}')")
logger.debug(f"Heuristic album detection: '{original_title}''{cleaned_title}' (removed: '{potential_album_part}')")
return cleaned_title, True
return track_title, False
@ -1004,13 +1004,13 @@ class MusicMatchingEngine:
# Debug logging for troubleshooting
if scored_results and not confident_results:
print(f"DEBUG: Found {len(scored_results)} scored results but none met confidence threshold 0.58")
logger.debug(f"Found {len(scored_results)} scored results but none met confidence threshold 0.58")
for i, result in enumerate(sorted_results[:3]): # Show top 3
print(f" {i+1}. {result.confidence:.3f} - {getattr(result, 'version_type', 'unknown')} - {result.filename[:60]}...")
logger.debug(f" {i+1}. {result.confidence:.3f} - {getattr(result, 'version_type', 'unknown')} - {result.filename[:60]}...")
elif confident_results:
print(f"DEBUG: {len(confident_results)} results passed confidence threshold 0.58")
logger.debug(f"{len(confident_results)} results passed confidence threshold 0.58")
for i, result in enumerate(confident_results[:3]): # Show top 3
print(f" {i+1}. {result.confidence:.3f} - {getattr(result, 'version_type', 'unknown')} - {result.filename[:60]}...")
logger.debug(f" {i+1}. {result.confidence:.3f} - {getattr(result, 'version_type', 'unknown')} - {result.filename[:60]}...")
return confident_results

@ -1052,7 +1052,7 @@ def check_album_completion(
if total_tracks == 0 and album_id:
logger.debug("No track count found for '%s' (%s)", album_name, album_id)
print(f"Checking album: '{album_name}' ({total_tracks} tracks)")
logger.debug(f"Checking album: '{album_name}' ({total_tracks} tracks)")
formats = []
# Check if album exists in database with completeness info
@ -1068,7 +1068,7 @@ def check_album_completion(
candidate_albums=candidate_albums
)
except Exception as db_error:
print(f"Database error for album '{album_name}': {db_error}")
logger.error(f"Database error for album '{album_name}': {db_error}")
return {
"id": album_id,
"name": album_name,
@ -1096,7 +1096,14 @@ def check_album_completion(
else:
status = "missing"
print(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 {
"id": album_id,
@ -1111,7 +1118,7 @@ def check_album_completion(
}
except Exception as e:
print(f"Error checking album completion for '{album_data.get('name', 'Unknown')}': {e}")
logger.error(f"Error checking album completion for '{album_data.get('name', 'Unknown')}': {e}")
return {
"id": album_data.get('id', ''),
"name": album_data.get('name', 'Unknown'),
@ -1153,7 +1160,12 @@ def check_single_completion(
if total_tracks == 0:
total_tracks = _resolve_completion_track_total(single_data, source_chain) or 1
print(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:
try:
@ -1168,7 +1180,7 @@ def check_single_completion(
candidate_albums=candidate_albums
)
except Exception as db_error:
print(f"Database error for EP '{single_name}': {db_error}")
logger.error(f"Database error for EP '{single_name}': {db_error}")
owned_tracks, expected_tracks, confidence = 0, total_tracks, 0.0
db_album = None
@ -1184,7 +1196,14 @@ def check_single_completion(
else:
status = "missing"
print(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 {
"id": single_id,
@ -1210,7 +1229,7 @@ def check_single_completion(
candidate_tracks=candidate_tracks
)
except Exception as db_error:
print(f"Database error for single '{single_name}': {db_error}")
logger.error(f"Database error for single '{single_name}': {db_error}")
db_track, confidence = None, 0.0
owned_tracks = 1 if db_track else 0
@ -1226,7 +1245,12 @@ def check_single_completion(
elif ext:
formats = [ext]
print(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 {
"id": single_id,
@ -1242,7 +1266,7 @@ def check_single_completion(
}
except Exception as e:
print(f"Error checking single/EP completion for '{single_data.get('name', 'Unknown')}': {e}")
logger.error(f"Error checking single/EP completion for '{single_data.get('name', 'Unknown')}': {e}")
return {
"id": single_data.get('id', ''),
"name": single_data.get('name', 'Unknown'),

@ -937,7 +937,7 @@ class PlexClient:
def is_library_scanning(self, library_name: str = "Music") -> bool:
"""Check if Plex library is currently scanning"""
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
try:
@ -946,31 +946,31 @@ class PlexClient:
# Check if library has a scanning attribute or is refreshing
# The Plex API exposes this through the library's refreshing property
refreshing = hasattr(library, 'refreshing') and library.refreshing
logger.debug(f"DEBUG: Library.refreshing = {refreshing}")
logger.debug("Library.refreshing = %s", refreshing)
if refreshing:
logger.debug(f"DEBUG: Library is refreshing")
logger.debug("Library is refreshing")
return True
# Alternative method: Check server activities for scanning
try:
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:
# Look for library scan activities
activity_type = getattr(activity, 'type', '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
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
except Exception as 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
except Exception as e:

@ -455,11 +455,23 @@ class SoulIDWorker:
matching.normalize_string(db_name)
)
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
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
return None

@ -16,7 +16,7 @@ from mutagen.mp4 import MP4, MP4Cover, MP4FreeForm
from mutagen.oggvorbis import OggVorbis
from mutagen.apev2 import APEv2, APENoHeaderError
logger = logging.getLogger("newmusic.tag_writer")
logger = logging.getLogger("tag_writer")
# Supported extensions
SUPPORTED_EXTENSIONS = {'.mp3', '.flac', '.ogg', '.oga', '.opus', '.m4a', '.mp4'}

@ -311,15 +311,17 @@ class WishlistService:
def _spotify_track_object_to_dict(self, spotify_track) -> Dict[str, Any]:
"""Convert a Spotify track object or TrackResult object to a dictionary"""
try:
# Add debug logging to see what we're dealing with
logger.info(f"DEBUG: Converting track object to dict. Type: {type(spotify_track)}")
logger.info(f"DEBUG: Has 'title' attribute: {hasattr(spotify_track, 'title')}")
logger.info(f"DEBUG: Has 'artist' attribute: {hasattr(spotify_track, 'artist')}")
logger.info(f"DEBUG: Has 'id' attribute: {hasattr(spotify_track, 'id')}")
logger.debug(
"Converting track object to dict: type=%s has_title=%s has_artist=%s has_id=%s",
type(spotify_track),
hasattr(spotify_track, 'title'),
hasattr(spotify_track, 'artist'),
hasattr(spotify_track, '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'):
logger.info("DEBUG: Detected TrackResult object, converting...")
logger.debug("Detected TrackResult object, converting")
# Handle TrackResult objects - these don't have Spotify IDs
album_name = getattr(spotify_track, 'album', '') or getattr(spotify_track, 'title', 'Unknown Album')
result = {
@ -333,19 +335,23 @@ class WishlistService:
'popularity': 0,
'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
# 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
artists_list = []
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:
logger.info(f"DEBUG: Processing artist: {artist}, type: {type(artist)}")
logger.debug("Processing artist: %r (type=%s)", artist, type(artist))
if hasattr(artist, 'name'):
artists_list.append({'name': artist.name})
elif isinstance(artist, str):
@ -375,16 +381,20 @@ class WishlistService:
'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
try:
import json
json.dumps(result)
logger.info("DEBUG: Conversion result is JSON serializable")
logger.debug("Conversion result is JSON serializable")
except Exception as json_error:
logger.error(f"DEBUG: Conversion result is NOT JSON serializable: {json_error}")
logger.error(f"DEBUG: Result content: {result}")
logger.error("Conversion result is NOT JSON serializable: %s", json_error)
logger.error("Conversion result content: %r", result)
# Return a safe fallback
return {
'id': f"fallback_{hash(str(spotify_track))}",
@ -413,4 +423,4 @@ def get_wishlist_service() -> WishlistService:
global _wishlist_service
if _wishlist_service is None:
_wishlist_service = WishlistService()
return _wishlist_service
return _wishlist_service

@ -26,8 +26,6 @@ try:
except ImportError:
logger.warning("Could not import MusicMatchingEngine, falling back to basic similarity")
_matching_engine = None
# Temporarily enable debug logging for edition matching
logger.setLevel(logging.DEBUG)
@dataclass
class DatabaseArtist:

@ -11,7 +11,9 @@ timeout = 120
# Keep shutdowns under Docker's stop window so container restarts stay graceful.
graceful_timeout = 8
# Logging goes to stdout/stderr so Docker can collect it.
# Logging goes to stdout/stderr and is filtered by the custom logger class.
accesslog = "-"
errorlog = "-"
access_log_format = '%(h)s - - "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
loglevel = "info"
logger_class = "utils.gunicorn_logger.FilteredGunicornLogger"

@ -13,7 +13,10 @@ timeout = 120
# Don't let local reloads wait too long for shutdown.
graceful_timeout = 1
# Logging goes to stdout/stderr so the shell launcher can collect it.
# Logging goes to stdout/stderr and is filtered by the custom logger class.
accesslog = "-"
errorlog = "-"
# Mimic process log format
access_log_format = '%(h)s - - "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
loglevel = "info"
logger_class = "utils.gunicorn_logger.FilteredGunicornLogger"

@ -1,12 +1,18 @@
#!/usr/bin/env python3
"""Reports basic system info — useful for debugging Docker setups."""
import logging
import os
import platform
import shutil
print(f"Platform: {platform.system()} {platform.release()}")
print(f"Python: {platform.python_version()}")
print(f"Working Dir: {os.getcwd()}")
if not logging.getLogger().handlers:
logging.basicConfig(level=logging.INFO, format="%(message)s")
logger = logging.getLogger("system_info")
logger.info(f"Platform: {platform.system()} {platform.release()}")
logger.info(f"Python: {platform.python_version()}")
logger.info(f"Working Dir: {os.getcwd()}")
# Disk usage for common SoulSync paths
for path in ['/app/downloads', '/app/Transfer', '/app/data', './downloads', './Transfer']:
@ -14,4 +20,4 @@ for path in ['/app/downloads', '/app/Transfer', '/app/data', './downloads', './T
usage = shutil.disk_usage(path)
free_gb = usage.free / (1024**3)
total_gb = usage.total / (1024**3)
print(f"Disk {path}: {free_gb:.1f} GB free / {total_gb:.1f} GB total")
logger.info(f"Disk {path}: {free_gb:.1f} GB free / {total_gb:.1f} GB total")

@ -7,14 +7,12 @@ Run this script to identify issues with iTunes data population:
- Discovery pool tracks by source
- Recent albums by source
- Curated playlists status
Usage:
python tools/diagnose_itunes_discover.py
"""
import sys
import os
import json
import logging
import os
import sys
# Add parent directory to path for imports
sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
@ -22,36 +20,42 @@ sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
from database.music_database import MusicDatabase
if not logging.getLogger().handlers:
logging.basicConfig(level=logging.INFO, format="%(message)s")
logger = logging.getLogger("diagnose_itunes_discover")
def _section(title: str) -> None:
logger.info("")
logger.info(title)
logger.info("-" * 40)
def diagnose_itunes_discover():
"""Run diagnostic checks for iTunes discover data."""
print("=" * 60)
print("iTunes Discover Page Diagnostic Report")
print("=" * 60)
logger.info("=" * 60)
logger.info("iTunes Discover Page Diagnostic Report")
logger.info("=" * 60)
db = MusicDatabase()
# 1. Check Similar Artists
print("\n[1] SIMILAR ARTISTS")
print("-" * 40)
_section("[1] SIMILAR ARTISTS")
try:
with db._get_connection() as conn:
cursor = conn.cursor()
# Total similar artists
cursor.execute("SELECT COUNT(*) as total FROM similar_artists")
total = cursor.fetchone()['total']
# With iTunes IDs
cursor.execute("SELECT COUNT(*) as count FROM similar_artists WHERE similar_artist_itunes_id IS NOT NULL")
with_itunes = cursor.fetchone()['count']
# With Spotify IDs
cursor.execute("SELECT COUNT(*) as count FROM similar_artists WHERE similar_artist_spotify_id IS NOT NULL")
with_spotify = cursor.fetchone()['count']
# With both
cursor.execute("""
SELECT COUNT(*) as count FROM similar_artists
WHERE similar_artist_itunes_id IS NOT NULL
@ -59,34 +63,29 @@ def diagnose_itunes_discover():
""")
with_both = cursor.fetchone()['count']
print(f" Total similar artists: {total}")
print(f" With iTunes ID: {with_itunes} ({100*with_itunes/total:.1f}%)" if total > 0 else " With iTunes ID: 0")
print(f" With Spotify ID: {with_spotify} ({100*with_spotify/total:.1f}%)" if total > 0 else " With Spotify ID: 0")
print(f" With BOTH IDs: {with_both} ({100*with_both/total:.1f}%)" if total > 0 else " With BOTH IDs: 0")
logger.info(f" Total similar artists: {total}")
logger.info(f" With iTunes ID: {with_itunes} ({100 * with_itunes / total:.1f}%)" if total > 0 else " With iTunes ID: 0")
logger.info(f" With Spotify ID: {with_spotify} ({100 * with_spotify / total:.1f}%)" if total > 0 else " With Spotify ID: 0")
logger.info(f" With BOTH IDs: {with_both} ({100 * with_both / total:.1f}%)" if total > 0 else " With BOTH IDs: 0")
if with_itunes == 0 and total > 0:
print(" [CRITICAL] No similar artists have iTunes IDs - Hero section will be empty!")
logger.critical("No similar artists have iTunes IDs - Hero section will be empty!")
elif with_itunes < total * 0.5:
print(" [WARNING] Less than 50% of similar artists have iTunes IDs")
logger.warning("Less than 50% of similar artists have iTunes IDs")
else:
print(" [OK] iTunes coverage is adequate")
logger.info("iTunes coverage is adequate")
except Exception as e:
print(f" [ERROR] Could not check similar artists: {e}")
logger.error(f"Could not check similar artists: {e}")
# 2. Check Discovery Pool
print("\n[2] DISCOVERY POOL")
print("-" * 40)
_section("[2] DISCOVERY POOL")
try:
with db._get_connection() as conn:
cursor = conn.cursor()
# Total tracks
cursor.execute("SELECT COUNT(*) as total FROM discovery_pool")
total = cursor.fetchone()['total']
# By source
cursor.execute("""
SELECT source, COUNT(*) as count
FROM discovery_pool
@ -94,33 +93,28 @@ def diagnose_itunes_discover():
""")
source_counts = {row['source']: row['count'] for row in cursor.fetchall()}
print(f" Total tracks: {total}")
print(f" Spotify tracks: {source_counts.get('spotify', 0)}")
print(f" iTunes tracks: {source_counts.get('itunes', 0)}")
logger.info(f" Total tracks: {total}")
logger.info(f" Spotify tracks: {source_counts.get('spotify', 0)}")
logger.info(f" iTunes tracks: {source_counts.get('itunes', 0)}")
if source_counts.get('itunes', 0) == 0 and total > 0:
print(" [CRITICAL] No iTunes tracks in discovery pool - Fresh Tape/Archives will be empty!")
logger.critical("No iTunes tracks in discovery pool - Fresh Tape/Archives will be empty!")
elif source_counts.get('itunes', 0) < total * 0.3:
print(" [WARNING] Low iTunes track count in discovery pool")
logger.warning("Low iTunes track count in discovery pool")
else:
print(" [OK] iTunes tracks present")
logger.info("iTunes tracks present")
except Exception as e:
print(f" [ERROR] Could not check discovery pool: {e}")
logger.error(f"Could not check discovery pool: {e}")
# 3. Check Recent Albums
print("\n[3] RECENT ALBUMS CACHE")
print("-" * 40)
_section("[3] RECENT ALBUMS CACHE")
try:
with db._get_connection() as conn:
cursor = conn.cursor()
# Total albums
cursor.execute("SELECT COUNT(*) as total FROM discovery_recent_albums")
total = cursor.fetchone()['total']
# By source
cursor.execute("""
SELECT source, COUNT(*) as count
FROM discovery_recent_albums
@ -128,24 +122,21 @@ def diagnose_itunes_discover():
""")
source_counts = {row['source']: row['count'] for row in cursor.fetchall()}
print(f" Total recent albums: {total}")
print(f" Spotify albums: {source_counts.get('spotify', 0)}")
print(f" iTunes albums: {source_counts.get('itunes', 0)}")
logger.info(f" Total recent albums: {total}")
logger.info(f" Spotify albums: {source_counts.get('spotify', 0)}")
logger.info(f" iTunes albums: {source_counts.get('itunes', 0)}")
if source_counts.get('itunes', 0) == 0 and total > 0:
print(" [CRITICAL] No iTunes albums cached - Recent Releases section will be empty!")
logger.critical("No iTunes albums cached - Recent Releases section will be empty!")
elif source_counts.get('itunes', 0) < 5:
print(" [WARNING] Very few iTunes albums cached")
logger.warning("Very few iTunes albums cached")
else:
print(" [OK] iTunes albums cached")
logger.info("iTunes albums cached")
except Exception as e:
print(f" [ERROR] Could not check recent albums: {e}")
logger.error(f"Could not check recent albums: {e}")
# 4. Check Curated Playlists
print("\n[4] CURATED PLAYLISTS")
print("-" * 40)
_section("[4] CURATED PLAYLISTS")
try:
with db._get_connection() as conn:
cursor = conn.cursor()
@ -156,7 +147,7 @@ def diagnose_itunes_discover():
'release_radar_itunes',
'discovery_weekly',
'discovery_weekly_spotify',
'discovery_weekly_itunes'
'discovery_weekly_itunes',
]
for playlist_type in playlists_to_check:
@ -174,9 +165,8 @@ def diagnose_itunes_discover():
else:
status = "[NOT FOUND]"
print(f" {playlist_type}: {status}")
logger.info(f" {playlist_type}: {status}")
# Check iTunes-specific playlists
cursor.execute("""
SELECT track_ids_json FROM discovery_curated_playlists
WHERE playlist_type = 'release_radar_itunes'
@ -190,49 +180,43 @@ def diagnose_itunes_discover():
itunes_dw = cursor.fetchone()
if not itunes_rr or len(json.loads(itunes_rr['track_ids_json'])) == 0:
print("\n [CRITICAL] release_radar_itunes is empty or missing!")
logger.critical("release_radar_itunes is empty or missing!")
if not itunes_dw or len(json.loads(itunes_dw['track_ids_json'])) == 0:
print(" [CRITICAL] discovery_weekly_itunes is empty or missing!")
logger.critical("discovery_weekly_itunes is empty or missing!")
except Exception as e:
print(f" [ERROR] Could not check curated playlists: {e}")
logger.error(f"Could not check curated playlists: {e}")
# 5. Check Watchlist Artists
print("\n[5] WATCHLIST ARTISTS")
print("-" * 40)
_section("[5] WATCHLIST ARTISTS")
try:
with db._get_connection() as conn:
cursor = conn.cursor()
# Total artists
cursor.execute("SELECT COUNT(*) as total FROM watchlist_artists")
total = cursor.fetchone()['total']
# With iTunes IDs
cursor.execute("SELECT COUNT(*) as count FROM watchlist_artists WHERE itunes_artist_id IS NOT NULL")
with_itunes = cursor.fetchone()['count']
# With Spotify IDs
cursor.execute("SELECT COUNT(*) as count FROM watchlist_artists WHERE spotify_artist_id IS NOT NULL")
with_spotify = cursor.fetchone()['count']
print(f" Total watchlist artists: {total}")
print(f" With iTunes ID: {with_itunes} ({100*with_itunes/total:.1f}%)" if total > 0 else " With iTunes ID: 0")
print(f" With Spotify ID: {with_spotify} ({100*with_spotify/total:.1f}%)" if total > 0 else " With Spotify ID: 0")
logger.info(f" Total watchlist artists: {total}")
logger.info(f" With iTunes ID: {with_itunes} ({100 * with_itunes / total:.1f}%)" if total > 0 else " With iTunes ID: 0")
logger.info(f" With Spotify ID: {with_spotify} ({100 * with_spotify / total:.1f}%)" if total > 0 else " With Spotify ID: 0")
if with_itunes == 0 and total > 0:
print(" [WARNING] No watchlist artists have iTunes IDs - source artist data limited")
logger.warning("No watchlist artists have iTunes IDs - source artist data limited")
except Exception as e:
print(f" [ERROR] Could not check watchlist artists: {e}")
logger.error(f"Could not check watchlist artists: {e}")
# Summary
print("\n" + "=" * 60)
print("SUMMARY & RECOMMENDED ACTIONS")
print("=" * 60)
print("""
If you see [CRITICAL] or [WARNING] messages above, follow these steps:
logger.info("")
logger.info("=" * 60)
logger.info("SUMMARY & RECOMMENDED ACTIONS")
logger.info("=" * 60)
logger.info(
"""
If you see critical or warning messages above, follow these steps:
QUICK FIX - Force Refresh Discover Data:
-----------------------------------------
@ -263,7 +247,8 @@ ROOT CAUSE NOTES:
The discover page will now fall back to watchlist artists if similar
artists are not available, so basic functionality should still work.
""")
""".strip()
)
if __name__ == '__main__':

@ -0,0 +1,83 @@
"""Gunicorn logger tweaks for SoulSync."""
from __future__ import annotations
import logging
from gunicorn.glogging import Logger as GunicornLogger
from utils.logging_config import ColoredFormatter
class FilteredGunicornLogger(GunicornLogger):
"""Gunicorn logger that skips noisy static and Socket.IO access logs."""
_STATIC_PREFIXES = (
"/static/",
"/assets/",
"/socket.io",
"/favicon.ico",
"/robots.txt",
)
_STATIC_SUFFIXES = (
".css",
".js",
".map",
".png",
".jpg",
".jpeg",
".gif",
".svg",
".ico",
".woff",
".woff2",
".ttf",
".eot",
)
_HEALTHCHECK_USER_AGENTS = (
"curl/",
)
def _should_skip_access_log(self, environ) -> bool:
path = environ.get("PATH_INFO") or ""
if not path:
return False
normalized = path if path.startswith("/") else f"/{path}"
lower_path = normalized.lower()
if any(
lower_path == prefix.rstrip("/") or lower_path.startswith(prefix)
for prefix in self._STATIC_PREFIXES
):
return True
if lower_path == "/":
user_agent = (environ.get("HTTP_USER_AGENT") or "").lower()
if any(token in user_agent for token in self._HEALTHCHECK_USER_AGENTS):
return True
return any(lower_path.endswith(suffix) for suffix in self._STATIC_SUFFIXES)
def access(self, resp, req, environ, request_time):
if self._should_skip_access_log(environ):
return
super().access(resp, req, environ, request_time)
def setup(self, cfg):
super().setup(cfg)
app_like_formatter = ColoredFormatter(
fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
datefmt="%Y-%m-%d %H:%M:%S",
)
error_level = getattr(logging, cfg.loglevel.upper(), logging.INFO)
for handler in self.access_log.handlers:
handler.setFormatter(app_like_formatter)
handler.setLevel(logging.INFO)
for handler in self.error_log.handlers:
handler.setFormatter(app_like_formatter)
handler.setLevel(error_level)

@ -6,6 +6,8 @@ from pathlib import Path
from datetime import datetime
from typing import Optional
LOGGER_NAMESPACE = "soulsync"
class SafeFormatter(logging.Formatter):
"""Formatter that handles Unicode characters safely on Windows"""
@ -52,7 +54,7 @@ class ColoredFormatter(SafeFormatter):
def setup_logging(level: str = "INFO", log_file: Optional[str] = None) -> logging.Logger:
log_level = getattr(logging, level.upper(), logging.INFO)
logger = logging.getLogger("newmusic")
logger = logging.getLogger(LOGGER_NAMESPACE)
logger.setLevel(log_level)
if logger.handlers:
@ -91,15 +93,15 @@ def setup_logging(level: str = "INFO", log_file: Optional[str] = None) -> loggin
return logger
def get_logger(name: str) -> logging.Logger:
return logging.getLogger(f"newmusic.{name}")
return logging.getLogger(f"{LOGGER_NAMESPACE}.{name}")
def set_log_level(level: str) -> bool:
"""Dynamically change the log level for all loggers without restart"""
try:
log_level = getattr(logging, level.upper(), logging.INFO)
# Get the root "newmusic" logger
root_logger = logging.getLogger("newmusic")
# Get the root "soulsync" logger
root_logger = logging.getLogger(LOGGER_NAMESPACE)
root_logger.setLevel(log_level)
# Update all handlers
@ -109,12 +111,12 @@ def set_log_level(level: str) -> bool:
root_logger.info(f"Log level changed to: {level.upper()}")
return True
except Exception as e:
print(f"Error setting log level: {e}")
logging.getLogger(LOGGER_NAMESPACE).error(f"Error setting log level: {e}")
return False
def get_current_log_level() -> str:
"""Get the current log level"""
root_logger = logging.getLogger("newmusic")
root_logger = logging.getLogger(LOGGER_NAMESPACE)
return logging.getLevelName(root_logger.level)
main_logger = get_logger("main")
main_logger = get_logger("main")

File diff suppressed because it is too large Load Diff
Loading…
Cancel
Save