Cut down unnecessary logging (#48)
* Cut down unnecessary logging * fix format etc * fix checks * fix tests
This commit is contained in:
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
from typing import Optional
|
||||
|
||||
from fastapi import APIRouter, BackgroundTasks, Depends, HTTPException, Query, Request, status
|
||||
@@ -16,8 +15,6 @@ from infrastructure.msgspec_fastapi import MsgSpecRoute
|
||||
|
||||
import msgspec.structs
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/albums", tags=["album"])
|
||||
|
||||
|
||||
|
||||
@@ -167,7 +167,6 @@ async def get_artist_monitoring_status(
|
||||
try:
|
||||
return await artist_service.get_artist_monitoring_status(artist_id)
|
||||
except Exception: # noqa: BLE001
|
||||
logger.debug("Failed to fetch monitoring status for %s", artist_id, exc_info=True)
|
||||
return ArtistMonitoringStatus(in_lidarr=False, monitored=False, auto_download=False)
|
||||
|
||||
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
from fastapi import APIRouter, Depends, HTTPException
|
||||
|
||||
from api.v1.schemas.cache import CacheStats, CacheClearResponse
|
||||
@@ -6,8 +5,6 @@ from core.dependencies import get_cache_service
|
||||
from infrastructure.msgspec_fastapi import MsgSpecRoute
|
||||
from services.cache_service import CacheService
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/cache", tags=["cache"])
|
||||
|
||||
|
||||
|
||||
@@ -1,5 +1,4 @@
|
||||
import asyncio
|
||||
import logging
|
||||
from fastapi import APIRouter, Depends
|
||||
from fastapi.responses import StreamingResponse
|
||||
import msgspec
|
||||
@@ -9,8 +8,6 @@ from core.dependencies import get_cache_status_service
|
||||
from infrastructure.msgspec_fastapi import MsgSpecRoute
|
||||
from services.cache_status_service import CacheStatusService
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/cache/sync", tags=["cache"])
|
||||
|
||||
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
import hashlib
|
||||
from typing import Optional
|
||||
from fastapi import APIRouter, HTTPException, Path, Query, Depends, Request
|
||||
@@ -8,7 +7,6 @@ from infrastructure.msgspec_fastapi import MsgSpecRoute
|
||||
from repositories.coverart_repository import CoverArtRepository
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/covers", tags=["covers"])
|
||||
log = logging.getLogger(__name__)
|
||||
|
||||
_ALLOWED_SIZES = {"250", "500", "1200"}
|
||||
_SIZE_ALIAS_NONE = {"", "original", "full", "max", "largest"}
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
from typing import Literal
|
||||
from fastapi import APIRouter, Depends, HTTPException, Query, Response
|
||||
from api.v1.schemas.discover import (
|
||||
@@ -28,8 +27,6 @@ from repositories.youtube import YouTubeRepository
|
||||
from services.discover_service import DiscoverService
|
||||
from services.discover_queue_manager import DiscoverQueueManager
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/discover", tags=["discover"])
|
||||
|
||||
|
||||
@@ -63,7 +60,6 @@ async def get_discover_queue(
|
||||
resolved = source or discover_service.resolve_source(None)
|
||||
cached = await queue_manager.consume_queue(resolved)
|
||||
if cached:
|
||||
logger.info("Serving pre-built discover queue (source=%s, items=%d)", resolved, len(cached.items))
|
||||
return cached
|
||||
effective_count = min(count, 20) if count is not None else None
|
||||
return await queue_manager.build_hydrated_queue(resolved, effective_count)
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
from typing import Literal
|
||||
from fastapi import APIRouter, Depends, Query, HTTPException
|
||||
from api.v1.schemas.home import (
|
||||
@@ -20,8 +19,6 @@ import msgspec.structs
|
||||
from services.home_service import HomeService
|
||||
from services.home_charts_service import HomeChartsService
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/home", tags=["home"])
|
||||
|
||||
|
||||
|
||||
@@ -39,10 +39,6 @@ async def request_auth_token(
|
||||
)
|
||||
|
||||
token, auth_url = await auth_service.request_token(settings.api_key)
|
||||
logger.info(
|
||||
"Last.fm auth token requested",
|
||||
extra={"step": "token_requested", "status": "success"},
|
||||
)
|
||||
return LastFmAuthTokenResponse(token=token, auth_url=auth_url)
|
||||
except HTTPException:
|
||||
raise
|
||||
@@ -83,11 +79,6 @@ async def exchange_auth_session(
|
||||
get_lastfm_repository.cache_clear()
|
||||
get_lastfm_auth_service.cache_clear()
|
||||
clear_lastfm_dependent_caches()
|
||||
logger.info(
|
||||
"Last.fm session exchanged for user %s",
|
||||
username,
|
||||
extra={"step": "session_exchanged", "status": "success"},
|
||||
)
|
||||
|
||||
return LastFmAuthSessionResponse(
|
||||
username=username,
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
from fastapi import APIRouter, File, UploadFile
|
||||
from fastapi.responses import FileResponse
|
||||
|
||||
@@ -25,8 +24,6 @@ from core.dependencies import JellyfinLibraryServiceDep, LocalFilesServiceDep, N
|
||||
from core.exceptions import PlaylistNotFoundError
|
||||
from infrastructure.msgspec_fastapi import MsgSpecBody, MsgSpecRoute
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(
|
||||
route_class=MsgSpecRoute,
|
||||
prefix="/playlists",
|
||||
|
||||
@@ -1,12 +1,9 @@
|
||||
import logging
|
||||
from fastapi import APIRouter, Depends, HTTPException
|
||||
from api.v1.schemas.request import QueueItem
|
||||
from core.dependencies import get_lidarr_repository
|
||||
from infrastructure.msgspec_fastapi import MsgSpecRoute
|
||||
from repositories.lidarr import LidarrRepository
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/queue", tags=["queue"])
|
||||
|
||||
|
||||
|
||||
@@ -1,12 +1,9 @@
|
||||
import logging
|
||||
from fastapi import APIRouter, Depends
|
||||
from api.v1.schemas.request import AlbumRequest, RequestAcceptedResponse, QueueStatusResponse
|
||||
from core.dependencies import get_request_service
|
||||
from infrastructure.msgspec_fastapi import MsgSpecBody, MsgSpecRoute
|
||||
from services.request_service import RequestService
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/requests", tags=["requests"])
|
||||
|
||||
|
||||
|
||||
@@ -1,5 +1,3 @@
|
||||
import logging
|
||||
import time
|
||||
from fastapi import APIRouter, Query, Path, BackgroundTasks, Depends, Request
|
||||
from core.exceptions import ClientDisconnectedError
|
||||
from api.v1.schemas.search import (
|
||||
@@ -18,8 +16,6 @@ from services.search_service import SearchService
|
||||
from services.search_enrichment_service import SearchEnrichmentService
|
||||
from repositories.coverart_repository import CoverArtRepository
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/search", tags=["search"])
|
||||
|
||||
|
||||
@@ -79,11 +75,7 @@ async def suggest(
|
||||
stripped = q.strip()
|
||||
if len(stripped) < 2:
|
||||
return SuggestResponse()
|
||||
start = time.monotonic()
|
||||
result = await search_service.suggest(query=stripped, limit=limit)
|
||||
elapsed_ms = (time.monotonic() - start) * 1000
|
||||
logger.debug("Suggest query_len=%d results=%d time_ms=%.1f", len(stripped), len(result.results), elapsed_ms)
|
||||
return result
|
||||
return await search_service.suggest(query=stripped, limit=limit)
|
||||
|
||||
|
||||
@router.get("/{bucket}", response_model=SearchBucketResponse)
|
||||
|
||||
@@ -60,7 +60,6 @@ async def update_preferences(
|
||||
try:
|
||||
preferences_service.save_preferences(preferences)
|
||||
total_cleared = await settings_service.clear_caches_for_preference_change()
|
||||
logger.info(f"Updated user preferences. Cleared {total_cleared} cache entries.")
|
||||
return preferences
|
||||
except ConfigurationError as e:
|
||||
logger.warning(f"Configuration error updating preferences: {e}")
|
||||
@@ -81,7 +80,6 @@ async def update_lidarr_settings(
|
||||
):
|
||||
try:
|
||||
preferences_service.save_lidarr_settings(lidarr_settings)
|
||||
logger.info(f"Updated Lidarr settings: sync_frequency={lidarr_settings.sync_frequency}")
|
||||
return lidarr_settings
|
||||
except ConfigurationError as e:
|
||||
logger.warning(f"Configuration error updating Lidarr settings: {e}")
|
||||
@@ -132,7 +130,6 @@ async def update_advanced_settings(
|
||||
)
|
||||
preferences_service.save_advanced_settings(backend_settings)
|
||||
await settings_service.on_coverart_settings_changed()
|
||||
logger.info("Updated advanced settings")
|
||||
saved = preferences_service.get_advanced_settings()
|
||||
return AdvancedSettingsFrontend.from_backend(saved)
|
||||
except ConfigurationError as e:
|
||||
@@ -162,7 +159,6 @@ async def update_lidarr_connection(
|
||||
preferences_service.save_lidarr_connection(settings)
|
||||
reset_lidarr_circuit_breaker()
|
||||
await settings_service.on_lidarr_settings_changed()
|
||||
logger.info("Updated Lidarr connection settings")
|
||||
return settings
|
||||
except ConfigurationError as e:
|
||||
logger.warning(f"Configuration error updating Lidarr connection: {e}")
|
||||
@@ -242,7 +238,6 @@ async def update_jellyfin_settings(
|
||||
try:
|
||||
preferences_service.save_jellyfin_connection(settings)
|
||||
await settings_service.on_jellyfin_settings_changed()
|
||||
logger.info("Updated Jellyfin connection settings")
|
||||
return settings
|
||||
except ConfigurationError as e:
|
||||
logger.warning(f"Configuration error updating Jellyfin settings: {e}")
|
||||
@@ -275,7 +270,6 @@ async def update_navidrome_settings(
|
||||
try:
|
||||
preferences_service.save_navidrome_connection(settings)
|
||||
await settings_service.on_navidrome_settings_changed(enabled=settings.enabled)
|
||||
logger.info("Updated Navidrome connection settings")
|
||||
return preferences_service.get_navidrome_connection()
|
||||
except ConfigurationError as e:
|
||||
logger.warning("Configuration error updating Navidrome settings: %s", e)
|
||||
@@ -354,7 +348,6 @@ async def update_listenbrainz_settings(
|
||||
try:
|
||||
preferences_service.save_listenbrainz_connection(settings)
|
||||
await settings_service.on_listenbrainz_settings_changed()
|
||||
logger.info("Updated ListenBrainz connection settings")
|
||||
return settings
|
||||
except ConfigurationError as e:
|
||||
logger.warning(f"Configuration error updating ListenBrainz settings: {e}")
|
||||
@@ -386,7 +379,6 @@ async def update_youtube_settings(
|
||||
try:
|
||||
preferences_service.save_youtube_connection(settings)
|
||||
await settings_service.on_youtube_settings_changed()
|
||||
logger.info("Updated YouTube connection settings")
|
||||
return settings
|
||||
except ConfigurationError as e:
|
||||
logger.warning(f"Configuration error updating YouTube settings: {e}")
|
||||
@@ -418,7 +410,6 @@ async def update_home_settings(
|
||||
try:
|
||||
preferences_service.save_home_settings(settings)
|
||||
await settings_service.clear_home_cache()
|
||||
logger.info("Updated home settings")
|
||||
return settings
|
||||
except ConfigurationError as e:
|
||||
logger.warning(f"Configuration error updating home settings: {e}")
|
||||
@@ -441,7 +432,6 @@ async def update_local_files_settings(
|
||||
try:
|
||||
preferences_service.save_local_files_connection(settings)
|
||||
await settings_service.on_local_files_settings_changed()
|
||||
logger.info("Updated local files settings")
|
||||
return settings
|
||||
except ConfigurationError as e:
|
||||
logger.warning("Configuration error updating local files settings: %s", e)
|
||||
@@ -473,7 +463,6 @@ async def update_lastfm_settings(
|
||||
try:
|
||||
preferences_service.save_lastfm_connection(settings)
|
||||
await settings_service.on_lastfm_settings_changed()
|
||||
logger.info("Updated Last.fm connection settings")
|
||||
saved = preferences_service.get_lastfm_connection()
|
||||
return LastFmConnectionSettingsResponse.from_settings(saved)
|
||||
except ConfigurationError as e:
|
||||
@@ -504,7 +493,6 @@ async def update_scrobble_settings(
|
||||
):
|
||||
try:
|
||||
preferences_service.save_scrobble_settings(settings)
|
||||
logger.info("Updated scrobble settings")
|
||||
return preferences_service.get_scrobble_settings()
|
||||
except ConfigurationError as e:
|
||||
logger.warning("Configuration error updating scrobble settings: %s", e)
|
||||
@@ -528,7 +516,6 @@ async def update_primary_music_source(
|
||||
preferences_service.save_primary_music_source(settings)
|
||||
await settings_service.clear_home_cache()
|
||||
await settings_service.clear_source_resolution_cache()
|
||||
logger.info("Updated primary music source to %s", settings.source)
|
||||
return preferences_service.get_primary_music_source()
|
||||
except ConfigurationError as e:
|
||||
logger.warning("Configuration error updating primary music source: %s", e)
|
||||
|
||||
@@ -1,12 +1,9 @@
|
||||
import logging
|
||||
from fastapi import APIRouter, Depends
|
||||
from api.v1.schemas.common import StatusReport
|
||||
from core.dependencies import get_status_service
|
||||
from infrastructure.msgspec_fastapi import MsgSpecRoute
|
||||
from services.status_service import StatusService
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/status", tags=["status"])
|
||||
|
||||
|
||||
|
||||
@@ -1,5 +1,3 @@
|
||||
import logging
|
||||
|
||||
from fastapi import APIRouter, Response
|
||||
|
||||
from api.v1.schemas.discover import YouTubeQuotaResponse
|
||||
@@ -18,8 +16,6 @@ from api.v1.schemas.youtube import (
|
||||
from core.dependencies import YouTubeServiceDep
|
||||
from infrastructure.msgspec_fastapi import MsgSpecBody, MsgSpecRoute
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
router = APIRouter(route_class=MsgSpecRoute, prefix="/youtube", tags=["YouTube"])
|
||||
|
||||
|
||||
|
||||
@@ -138,7 +138,7 @@ class Settings(BaseSettings):
|
||||
validated_values: dict[str, object] = {}
|
||||
for key, value in config_data.items():
|
||||
if key not in model_fields:
|
||||
logger.warning("Unknown config key '%s' — ignoring", key)
|
||||
logger.warning("Unknown config key '%s', ignoring", key)
|
||||
continue
|
||||
try:
|
||||
field_info = model_fields[key]
|
||||
@@ -173,11 +173,10 @@ class Settings(BaseSettings):
|
||||
# Dry-run cross-field validation on merged candidate state
|
||||
self._validate_merged(validated_values)
|
||||
|
||||
# All validation passed — apply atomically
|
||||
# All validation passed; apply atomically.
|
||||
for key, value in validated_values.items():
|
||||
setattr(self, key, value)
|
||||
|
||||
logger.info(f"Loaded configuration from {self.config_file_path}")
|
||||
except (ConfigurationError, ValueError):
|
||||
raise
|
||||
except msgspec.DecodeError as e:
|
||||
@@ -225,7 +224,6 @@ class Settings(BaseSettings):
|
||||
},
|
||||
}
|
||||
atomic_write_json(self.config_file_path, config_data)
|
||||
logger.info(f"Created default config at {self.config_file_path}")
|
||||
|
||||
def save_to_file(self) -> None:
|
||||
try:
|
||||
@@ -252,7 +250,6 @@ class Settings(BaseSettings):
|
||||
|
||||
atomic_write_json(self.config_file_path, config_data)
|
||||
|
||||
logger.info(f"Saved config to {self.config_file_path}")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to save config: {e}")
|
||||
raise
|
||||
|
||||
@@ -1,8 +1,7 @@
|
||||
"""Tier 2 — Cache layer, persistence stores, and foundation providers."""
|
||||
"""Tier 2 - Cache layer, persistence stores, and foundation providers."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
import threading
|
||||
|
||||
from core.config import get_settings
|
||||
@@ -18,15 +17,11 @@ from infrastructure.persistence import (
|
||||
|
||||
from ._registry import singleton
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
@singleton
|
||||
def get_cache() -> CacheInterface:
|
||||
preferences_service = get_preferences_service()
|
||||
advanced = preferences_service.get_advanced_settings()
|
||||
max_entries = advanced.memory_cache_max_entries
|
||||
logger.info(f"Initialized RAM cache with max {max_entries} entries")
|
||||
return InMemoryCache(max_entries=max_entries)
|
||||
|
||||
|
||||
@@ -36,7 +31,6 @@ def get_disk_cache() -> DiskMetadataCache:
|
||||
preferences_service = get_preferences_service()
|
||||
advanced = preferences_service.get_advanced_settings()
|
||||
cache_dir = settings.cache_dir / "metadata"
|
||||
logger.info(f"Initialized disk metadata cache at {cache_dir}")
|
||||
return DiskMetadataCache(
|
||||
base_path=cache_dir,
|
||||
recent_metadata_max_size_mb=advanced.recent_metadata_max_size_mb,
|
||||
|
||||
@@ -54,7 +54,7 @@ def clear_listenbrainz_dependent_caches() -> None:
|
||||
|
||||
|
||||
async def init_app_state(app) -> None:
|
||||
logger.info("Application state initialized")
|
||||
pass
|
||||
|
||||
|
||||
async def cleanup_app_state() -> None:
|
||||
@@ -74,7 +74,5 @@ async def cleanup_app_state() -> None:
|
||||
except (AttributeError, RuntimeError, OSError) as exc:
|
||||
logger.error("Failed to shut down genre prewarm service during cleanup: %s", exc)
|
||||
|
||||
# Automatic cleanup via registry — no manual list needed
|
||||
# Automatic cleanup via registry; no manual list needed.
|
||||
clear_all_singletons()
|
||||
|
||||
logger.info("Application state cleaned up")
|
||||
|
||||
@@ -124,7 +124,6 @@ def make_on_queue_import(memory_cache, disk_cache, library_db):
|
||||
})
|
||||
except Exception as ex: # noqa: BLE001
|
||||
logger.warning("Queue import: failed to upsert album %s: %s", record.musicbrainz_id[:8], ex)
|
||||
logger.info("Queue import: invalidated caches for album=%s", record.musicbrainz_id[:8])
|
||||
|
||||
return on_queue_import
|
||||
|
||||
@@ -143,8 +142,6 @@ def make_processor(lidarr_repo, memory_cache, disk_cache, cover_repo, request_hi
|
||||
is_monitored = bool(result.get("monitored"))
|
||||
|
||||
if is_monitored:
|
||||
logger.info(f"Album {album_mbid[:8]}... successfully monitored - promoting cache entries to persistent")
|
||||
|
||||
try:
|
||||
await disk_cache.promote_album_to_persistent(album_mbid)
|
||||
await cover_repo.promote_cover_to_persistent(album_mbid, identifier_type="album")
|
||||
@@ -156,7 +153,6 @@ def make_processor(lidarr_repo, memory_cache, disk_cache, cover_repo, request_hi
|
||||
await disk_cache.promote_artist_to_persistent(artist_mbid)
|
||||
await cover_repo.promote_cover_to_persistent(artist_mbid, identifier_type="artist")
|
||||
|
||||
logger.info(f"Cache promotion complete for album {album_mbid[:8]}...")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to promote cache entries for album {album_mbid[:8]}...: {e}")
|
||||
else:
|
||||
@@ -173,7 +169,6 @@ def make_processor(lidarr_repo, memory_cache, disk_cache, cover_repo, request_hi
|
||||
)
|
||||
await memory_cache.delete(f"{ARTIST_INFO_PREFIX}{record.artist_mbid}")
|
||||
await disk_cache.delete_artist(record.artist_mbid)
|
||||
logger.info("Applied deferred artist monitoring for %s", record.artist_mbid[:8])
|
||||
break
|
||||
except Exception: # noqa: BLE001
|
||||
if attempt == 0:
|
||||
@@ -284,11 +279,6 @@ def get_requests_page_service() -> "RequestsPageService":
|
||||
})
|
||||
except Exception as ex: # noqa: BLE001
|
||||
logger.warning("Failed to upsert album into library cache: %s", ex)
|
||||
logger.info(
|
||||
"Invalidated caches after import: album=%s artist=%s",
|
||||
record.musicbrainz_id[:8],
|
||||
(record.artist_mbid or "?")[:8],
|
||||
)
|
||||
|
||||
request_queue = get_request_queue()
|
||||
library_service = get_library_service()
|
||||
|
||||
@@ -97,5 +97,4 @@ async def request_validation_error_handler(request: Request, exc: RequestValidat
|
||||
|
||||
|
||||
async def client_disconnected_handler(request: Request, exc: ClientDisconnectedError) -> Response:
|
||||
logger.debug("Client disconnected: %s %s", request.method, request.url.path)
|
||||
return Response(status_code=status.HTTP_204_NO_CONTENT)
|
||||
|
||||
+1
-72
@@ -53,17 +53,13 @@ async def cleanup_disk_cache_periodically(
|
||||
while True:
|
||||
try:
|
||||
await asyncio.sleep(interval)
|
||||
logger.debug("Running disk cache cleanup...")
|
||||
await disk_cache.cleanup_expired_recent()
|
||||
await disk_cache.enforce_recent_size_limits()
|
||||
await disk_cache.cleanup_expired_covers()
|
||||
await disk_cache.enforce_cover_size_limits()
|
||||
if cover_disk_cache:
|
||||
await cover_disk_cache.enforce_size_limit(force=True)
|
||||
expired = await asyncio.to_thread(cover_disk_cache.cleanup_expired)
|
||||
if expired:
|
||||
logger.info("Cover expiry sweep removed %d expired covers", expired)
|
||||
logger.debug("Disk cache cleanup complete")
|
||||
await asyncio.to_thread(cover_disk_cache.cleanup_expired)
|
||||
except asyncio.CancelledError:
|
||||
break
|
||||
except Exception as e:
|
||||
@@ -114,17 +110,14 @@ async def sync_library_periodically(
|
||||
|
||||
await asyncio.sleep(interval)
|
||||
|
||||
logger.info(f"Auto-syncing library (frequency: {sync_freq})")
|
||||
sync_success = False
|
||||
should_update_status = True
|
||||
try:
|
||||
result = await library_service.sync_library()
|
||||
if result.status == "skipped":
|
||||
logger.info("Auto-sync skipped - sync already in progress")
|
||||
should_update_status = False
|
||||
continue
|
||||
sync_success = True
|
||||
logger.info("Auto-sync completed successfully")
|
||||
|
||||
except Exception as e:
|
||||
logger.error("Auto-sync library call failed: %s", e, exc_info=True)
|
||||
@@ -140,7 +133,6 @@ async def sync_library_periodically(
|
||||
preferences_service.save_lidarr_settings(updated_settings)
|
||||
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Library sync task cancelled")
|
||||
break
|
||||
except Exception as e:
|
||||
logger.error("Library sync task failed: %s", e, exc_info=True)
|
||||
@@ -162,21 +154,16 @@ async def warm_library_cache(
|
||||
library_db: 'LibraryDB'
|
||||
) -> None:
|
||||
try:
|
||||
logger.info("Warming cache with recently-added library albums...")
|
||||
|
||||
await asyncio.sleep(5)
|
||||
|
||||
albums_data = await library_db.get_albums()
|
||||
|
||||
if not albums_data:
|
||||
logger.info("No library albums to warm cache with")
|
||||
return
|
||||
|
||||
max_warm = 30
|
||||
albums_to_warm = albums_data[:max_warm]
|
||||
|
||||
logger.info(f"Warming cache with {len(albums_to_warm)} of {len(albums_data)} library albums (first {max_warm})")
|
||||
|
||||
warmed = 0
|
||||
for i, album_data in enumerate(albums_to_warm):
|
||||
mbid = album_data.get('mbid')
|
||||
@@ -199,8 +186,6 @@ async def warm_library_cache(
|
||||
)
|
||||
continue
|
||||
|
||||
logger.info(f"Cache warming complete: {warmed} albums fetched, {len(albums_to_warm) - warmed} already cached")
|
||||
|
||||
except Exception as e:
|
||||
logger.error("Library cache warming failed: %s", e, exc_info=True)
|
||||
|
||||
@@ -215,9 +200,7 @@ async def warm_home_cache_periodically(
|
||||
try:
|
||||
for src in ("listenbrainz", "lastfm"):
|
||||
try:
|
||||
logger.debug("Warming home page cache (source=%s)...", src)
|
||||
await home_service.get_home_data(source=src)
|
||||
logger.debug("Home cache warming complete (source=%s)", src)
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
"Home cache warming failed (source=%s): %s",
|
||||
@@ -226,7 +209,6 @@ async def warm_home_cache_periodically(
|
||||
exc_info=True,
|
||||
)
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Home cache warming task cancelled")
|
||||
break
|
||||
|
||||
await asyncio.sleep(interval)
|
||||
@@ -255,16 +237,13 @@ async def warm_genre_cache_periodically(
|
||||
try:
|
||||
cached_home = await home_service.get_cached_home_data(source=src)
|
||||
if not cached_home or not cached_home.genre_list or not cached_home.genre_list.items:
|
||||
logger.debug("No cached home data for genre warming (source=%s), skipping", src)
|
||||
continue
|
||||
genre_names = [
|
||||
g.name for g in cached_home.genre_list.items[:20]
|
||||
if isinstance(g, HomeGenre)
|
||||
]
|
||||
if genre_names:
|
||||
logger.debug("Warming genre cache (source=%s, %d genres)...", src, len(genre_names))
|
||||
await home_service._genre.build_and_cache_genre_section(src, genre_names)
|
||||
logger.debug("Genre cache warming complete (source=%s)", src)
|
||||
warmed += 1
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
@@ -274,7 +253,6 @@ async def warm_genre_cache_periodically(
|
||||
exc_info=True,
|
||||
)
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Genre cache warming task cancelled")
|
||||
break
|
||||
|
||||
if warmed == 0:
|
||||
@@ -305,9 +283,7 @@ async def warm_discover_cache_periodically(
|
||||
try:
|
||||
for src in ("listenbrainz", "lastfm"):
|
||||
try:
|
||||
logger.info("Warming discover cache (source=%s)...", src)
|
||||
await discover_service.warm_cache(source=src)
|
||||
logger.info("Discover cache warming complete (source=%s)", src)
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
"Discover cache warming failed (source=%s): %s",
|
||||
@@ -321,13 +297,11 @@ async def warm_discover_cache_periodically(
|
||||
adv = preferences_service.get_advanced_settings()
|
||||
if adv.discover_queue_auto_generate and adv.discover_queue_warm_cycle_build:
|
||||
resolved = discover_service.resolve_source(None)
|
||||
logger.info("Pre-building discover queue (source=%s)...", resolved)
|
||||
await queue_manager.start_build(resolved)
|
||||
except Exception as e:
|
||||
logger.error("Discover queue pre-build failed: %s", e, exc_info=True)
|
||||
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Discover cache warming task cancelled")
|
||||
break
|
||||
|
||||
await asyncio.sleep(interval)
|
||||
@@ -355,7 +329,6 @@ async def warm_jellyfin_mbid_index(jellyfin_repo: 'JellyfinRepository') -> None:
|
||||
await asyncio.sleep(8)
|
||||
try:
|
||||
index = await jellyfin_repo.build_mbid_index()
|
||||
logger.info("Jellyfin MBID index warmed with %d entries", len(index))
|
||||
except Exception as e:
|
||||
logger.error("Jellyfin MBID index warming failed: %s", e, exc_info=True)
|
||||
|
||||
@@ -399,7 +372,6 @@ async def warm_artist_discovery_cache_periodically(
|
||||
try:
|
||||
artists = await library_db.get_artists()
|
||||
if not artists:
|
||||
logger.debug("No library artists for discovery cache warming")
|
||||
await asyncio.sleep(interval)
|
||||
continue
|
||||
|
||||
@@ -411,18 +383,10 @@ async def warm_artist_discovery_cache_periodically(
|
||||
await asyncio.sleep(interval)
|
||||
continue
|
||||
|
||||
logger.info(
|
||||
"Warming artist discovery cache for %d library artists...", len(mbids)
|
||||
)
|
||||
cached = await artist_discovery_service.precache_artist_discovery(
|
||||
mbids, delay=delay
|
||||
)
|
||||
logger.info(
|
||||
"Artist discovery cache warming complete: %d/%d artists refreshed",
|
||||
cached, len(mbids),
|
||||
)
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Artist discovery cache warming task cancelled")
|
||||
break
|
||||
except Exception as e:
|
||||
logger.error("Artist discovery cache warming failed: %s", e, exc_info=True)
|
||||
@@ -472,13 +436,11 @@ async def warm_audiodb_cache_periodically(
|
||||
|
||||
settings = preferences_service.get_advanced_settings()
|
||||
if not settings.audiodb_enabled:
|
||||
logger.debug("AudioDB sweep skipped (audiodb_enabled=false)")
|
||||
continue
|
||||
|
||||
artists = await library_db.get_artists()
|
||||
albums = await library_db.get_albums()
|
||||
if not artists and not albums:
|
||||
logger.debug("AudioDB sweep: no library items")
|
||||
continue
|
||||
|
||||
cursor = preferences_service.get_setting('audiodb_sweep_cursor')
|
||||
@@ -520,20 +482,13 @@ async def warm_audiodb_cache_periodically(
|
||||
if not items_needing_refresh:
|
||||
preferences_service.save_setting('audiodb_sweep_cursor', None)
|
||||
preferences_service.save_setting('audiodb_sweep_last_completed', time())
|
||||
logger.info("AudioDB sweep complete: all items up to date")
|
||||
continue
|
||||
|
||||
logger.info(
|
||||
"audiodb.sweep action=start items=%d cursor=%s",
|
||||
len(items_needing_refresh), cursor[:8] if cursor else 'start',
|
||||
)
|
||||
|
||||
processed = 0
|
||||
bytes_ok = 0
|
||||
bytes_fail = 0
|
||||
for entity_type, mbid, data in items_needing_refresh:
|
||||
if not preferences_service.get_advanced_settings().audiodb_enabled:
|
||||
logger.info("AudioDB disabled during sweep, stopping")
|
||||
break
|
||||
|
||||
try:
|
||||
@@ -572,31 +527,15 @@ async def warm_audiodb_cache_periodically(
|
||||
if processed % _AUDIODB_SWEEP_CURSOR_PERSIST_INTERVAL == 0:
|
||||
preferences_service.save_setting('audiodb_sweep_cursor', mbid)
|
||||
|
||||
if processed % _AUDIODB_SWEEP_LOG_INTERVAL == 0:
|
||||
logger.info(
|
||||
"audiodb.sweep processed=%d total=%d cursor=%s bytes_ok=%d bytes_fail=%d remaining=%d",
|
||||
processed, len(items_needing_refresh), mbid[:8],
|
||||
bytes_ok, bytes_fail, len(items_needing_refresh) - processed,
|
||||
)
|
||||
|
||||
await asyncio.sleep(_AUDIODB_SWEEP_INTER_ITEM_DELAY)
|
||||
|
||||
if processed >= len(items_needing_refresh):
|
||||
preferences_service.save_setting('audiodb_sweep_cursor', None)
|
||||
preferences_service.save_setting('audiodb_sweep_last_completed', time())
|
||||
logger.info(
|
||||
"audiodb.sweep action=complete refreshed=%d bytes_ok=%d bytes_fail=%d",
|
||||
processed, bytes_ok, bytes_fail,
|
||||
)
|
||||
else:
|
||||
preferences_service.save_setting('audiodb_sweep_cursor', mbid)
|
||||
logger.info(
|
||||
"audiodb.sweep action=interrupted processed=%d total=%d bytes_ok=%d bytes_fail=%d",
|
||||
processed, len(items_needing_refresh), bytes_ok, bytes_fail,
|
||||
)
|
||||
|
||||
except asyncio.CancelledError:
|
||||
logger.info("AudioDB sweep task cancelled")
|
||||
break
|
||||
except Exception as e:
|
||||
logger.error("AudioDB sweep cycle failed: %s", e, exc_info=True)
|
||||
@@ -632,7 +571,6 @@ async def sync_request_statuses_periodically(
|
||||
try:
|
||||
await requests_page_service.sync_request_statuses()
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Request status sync task cancelled")
|
||||
break
|
||||
except Exception as e:
|
||||
logger.error("Periodic request status sync failed: %s", e, exc_info=True)
|
||||
@@ -673,10 +611,7 @@ async def demote_orphaned_covers_periodically(
|
||||
valid_hashes.add(get_cache_filename(f"artist_{mbid}", "img"))
|
||||
|
||||
demoted = await asyncio.to_thread(cover_disk_cache.demote_orphaned, valid_hashes)
|
||||
if demoted:
|
||||
logger.info("Orphan cover demotion: %d covers demoted to expiring", demoted)
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Orphan cover demotion task cancelled")
|
||||
break
|
||||
except Exception as e:
|
||||
logger.error("Orphan cover demotion failed: %s", e, exc_info=True)
|
||||
@@ -710,13 +645,7 @@ async def prune_stores_periodically(
|
||||
pruned_requests = await request_history.prune_old_terminal_requests(request_retention_days)
|
||||
pruned_ignored = await mbid_store.prune_old_ignored_releases(ignored_retention_days)
|
||||
orphaned_yt = await youtube_store.delete_orphaned_track_links()
|
||||
if pruned_requests or pruned_ignored or orphaned_yt:
|
||||
logger.info(
|
||||
"Store prune: requests=%d ignored_releases=%d youtube_orphans=%d",
|
||||
pruned_requests, pruned_ignored, orphaned_yt,
|
||||
)
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Store prune task cancelled")
|
||||
break
|
||||
except Exception as e:
|
||||
logger.error("Store prune task failed: %s", e, exc_info=True)
|
||||
|
||||
+2
-5
@@ -1,7 +1,6 @@
|
||||
import asyncio
|
||||
import hashlib
|
||||
import json
|
||||
import logging
|
||||
import shutil
|
||||
import time
|
||||
from pathlib import Path
|
||||
@@ -9,8 +8,6 @@ from typing import Any
|
||||
|
||||
from infrastructure.serialization import to_jsonable
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
def _encode_json(value: Any) -> str:
|
||||
return json.dumps(value, ensure_ascii=True, separators=(",", ":"))
|
||||
@@ -204,8 +201,8 @@ class DiskMetadataCache:
|
||||
meta["last_accessed"] = time.time()
|
||||
try:
|
||||
meta_path.write_text(_encode_json(meta))
|
||||
except OSError as exc:
|
||||
logger.debug("Failed to update disk cache access time for %s: %s", meta_path, exc)
|
||||
except OSError:
|
||||
pass
|
||||
|
||||
return payload
|
||||
|
||||
|
||||
-11
@@ -1,13 +1,10 @@
|
||||
import asyncio
|
||||
import logging
|
||||
import sys
|
||||
import time
|
||||
from typing import Any, Optional
|
||||
from abc import ABC, abstractmethod
|
||||
from collections import OrderedDict
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class CacheInterface(ABC):
|
||||
@abstractmethod
|
||||
@@ -84,8 +81,6 @@ class InMemoryCache(CacheInterface):
|
||||
if key not in self._cache and len(self._cache) >= self._max_entries:
|
||||
oldest_key, _ = self._cache.popitem(last=False)
|
||||
self._evictions += 1
|
||||
if self._evictions % 100 == 0:
|
||||
logger.info(f"Cache LRU evictions: {self._evictions}, current size: {len(self._cache)}")
|
||||
|
||||
self._cache[key] = CacheEntry(value, ttl_seconds)
|
||||
self._cache.move_to_end(key)
|
||||
@@ -104,9 +99,6 @@ class InMemoryCache(CacheInterface):
|
||||
for key in keys_to_remove:
|
||||
self._cache.pop(key, None)
|
||||
|
||||
if keys_to_remove:
|
||||
logger.info(f"Cleared {len(keys_to_remove)} cache entries with prefix '{prefix}'")
|
||||
|
||||
return len(keys_to_remove)
|
||||
|
||||
async def cleanup_expired(self) -> int:
|
||||
@@ -120,9 +112,6 @@ class InMemoryCache(CacheInterface):
|
||||
for key in expired_keys:
|
||||
self._cache.pop(key, None)
|
||||
|
||||
if expired_keys:
|
||||
logger.debug(f"Cleaned up {len(expired_keys)} expired cache entries")
|
||||
|
||||
return len(expired_keys)
|
||||
|
||||
def size(self) -> int:
|
||||
|
||||
@@ -9,13 +9,10 @@ call signatures.
|
||||
from __future__ import annotations
|
||||
|
||||
import contextvars
|
||||
import logging
|
||||
from typing import Literal
|
||||
|
||||
from infrastructure.integration_result import IntegrationResult, IntegrationStatus
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
_degradation_ctx_var: contextvars.ContextVar[DegradationContext | None] = (
|
||||
contextvars.ContextVar("degradation_ctx", default=None)
|
||||
)
|
||||
@@ -34,13 +31,6 @@ class DegradationContext:
|
||||
prev = self._services.get(result.source)
|
||||
if prev is None or _severity(result.status) > _severity(prev):
|
||||
self._services[result.source] = result.status
|
||||
if result.status != "ok":
|
||||
logger.debug(
|
||||
"Degradation recorded: source=%s status=%s msg=%s",
|
||||
result.source,
|
||||
result.status,
|
||||
result.error_message,
|
||||
)
|
||||
|
||||
def summary(self) -> dict[str, str]:
|
||||
"""Return ``{source: status}`` for all recorded integrations."""
|
||||
|
||||
@@ -1,10 +1,7 @@
|
||||
import httpx
|
||||
import logging
|
||||
from typing import Optional
|
||||
from core.config import Settings, get_settings
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
def _get_user_agent(settings: Optional[Settings] = None) -> str:
|
||||
if settings:
|
||||
|
||||
@@ -1,12 +1,9 @@
|
||||
import asyncio
|
||||
import logging
|
||||
from typing import TypeVar, Awaitable, Callable, Any
|
||||
from functools import wraps
|
||||
|
||||
from core.exceptions import ClientDisconnectedError
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
T = TypeVar("T")
|
||||
|
||||
_MAX_DEDUP_RETRIES = 1
|
||||
|
||||
@@ -1,12 +1,9 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
from collections.abc import Awaitable, Callable
|
||||
|
||||
from core.exceptions import ClientDisconnectedError
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
DisconnectCallable = Callable[[], Awaitable[bool]]
|
||||
|
||||
|
||||
@@ -14,5 +11,4 @@ async def check_disconnected(
|
||||
is_disconnected: DisconnectCallable | None,
|
||||
) -> None:
|
||||
if is_disconnected is not None and await is_disconnected():
|
||||
logger.debug("Client disconnected — aborting cover fetch")
|
||||
raise ClientDisconnectedError("Client disconnected")
|
||||
|
||||
@@ -1,43 +0,0 @@
|
||||
import logging
|
||||
from typing import Optional
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
def format_mbid(mbid: str) -> str:
|
||||
return f"{mbid[:8]}..." if len(mbid) >= 8 else mbid
|
||||
|
||||
|
||||
def log_cache_hit(entity_type: str, mbid: str, source: Optional[str] = None) -> None:
|
||||
source_info = f" from {source}" if source else ""
|
||||
logger.info(f"Cache hit: {entity_type} {format_mbid(mbid)}{source_info}")
|
||||
|
||||
|
||||
def log_cache_miss(entity_type: str, mbid: str, source: Optional[str] = None) -> None:
|
||||
source_info = f" in {source}" if source else ""
|
||||
logger.debug(f"Cache miss: {entity_type} {format_mbid(mbid)}{source_info}")
|
||||
|
||||
|
||||
def log_fetch_start(entity_type: str, mbid: str, source: str) -> None:
|
||||
logger.info(f"Fetching {entity_type} {format_mbid(mbid)} from {source}")
|
||||
|
||||
|
||||
def log_fetch_success(entity_type: str, mbid: str, source: str) -> None:
|
||||
logger.info(f"Fetch success: {entity_type} {format_mbid(mbid)} from {source}")
|
||||
|
||||
|
||||
def log_fetch_failed(entity_type: str, mbid: str, source: str, reason: Optional[str] = None) -> None:
|
||||
reason_info = f": {reason}" if reason else ""
|
||||
logger.warning(f"Fetch failed: {entity_type} {format_mbid(mbid)} from {source}{reason_info}")
|
||||
|
||||
|
||||
def log_image_fetch(action: str, entity_type: str, mbid: str, source: str) -> None:
|
||||
logger.info(f"Image {action}: {entity_type} {format_mbid(mbid)} from {source}")
|
||||
|
||||
|
||||
def log_http_error(entity_type: str, mbid: str, source: str, status_code: int) -> None:
|
||||
logger.warning(f"HTTP {status_code}: {entity_type} {format_mbid(mbid)} from {source}")
|
||||
|
||||
|
||||
def log_exception(entity_type: str, mbid: str, operation: str, error: Exception) -> None:
|
||||
logger.error(f"Exception in {operation} for {entity_type} {format_mbid(mbid)}: {error}")
|
||||
|
||||
@@ -2,14 +2,11 @@
|
||||
|
||||
import asyncio
|
||||
import json
|
||||
import logging
|
||||
import sqlite3
|
||||
import threading
|
||||
from pathlib import Path
|
||||
from typing import Any, TypeVar
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
T = TypeVar("T")
|
||||
|
||||
|
||||
|
||||
@@ -1,6 +1,5 @@
|
||||
"""Domain 2 — Genre indexing persistence."""
|
||||
"""Domain 2 - Genre indexing persistence."""
|
||||
|
||||
import logging
|
||||
import sqlite3
|
||||
from typing import Any
|
||||
|
||||
@@ -12,8 +11,6 @@ from infrastructure.persistence._database import (
|
||||
_normalize,
|
||||
)
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
LIBRARY_ARTISTS_TABLE = "library_artists"
|
||||
LIBRARY_ALBUMS_TABLE = "library_albums"
|
||||
|
||||
|
||||
@@ -42,9 +42,7 @@ def _safe_delete(conn: sqlite3.Connection, table: str) -> None:
|
||||
try:
|
||||
conn.execute(f'DELETE FROM "{table}"')
|
||||
except sqlite3.OperationalError as exc:
|
||||
if "no such table" in str(exc):
|
||||
logger.debug("Cross-domain table %s not yet created, skipping clear", table)
|
||||
else:
|
||||
if "no such table" not in str(exc):
|
||||
logger.warning("Unexpected error clearing cross-domain table %s: %s", table, exc)
|
||||
|
||||
|
||||
|
||||
@@ -1,6 +1,5 @@
|
||||
"""Domain 5: Sync lifecycle persistence."""
|
||||
|
||||
import logging
|
||||
import sqlite3
|
||||
import time
|
||||
from typing import Any
|
||||
@@ -13,8 +12,6 @@ from infrastructure.persistence._database import (
|
||||
)
|
||||
from infrastructure.serialization import to_jsonable
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class SyncStateStore(PersistenceBase):
|
||||
"""Owns tables: ``sync_state``, ``processed_items``."""
|
||||
|
||||
@@ -1,14 +1,11 @@
|
||||
"""Domain 3 — YouTube link persistence."""
|
||||
"""Domain 3 - YouTube link persistence."""
|
||||
|
||||
import logging
|
||||
import sqlite3
|
||||
from typing import Any
|
||||
|
||||
from infrastructure.persistence._database import PersistenceBase
|
||||
from infrastructure.serialization import to_jsonable
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class YouTubeStore(PersistenceBase):
|
||||
"""Owns tables: ``youtube_links``, ``youtube_track_links``."""
|
||||
|
||||
@@ -1,11 +1,8 @@
|
||||
import asyncio
|
||||
import logging
|
||||
from enum import IntEnum
|
||||
from typing import Optional
|
||||
from datetime import datetime
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class RequestPriority(IntEnum):
|
||||
USER_INITIATED = 0
|
||||
@@ -37,8 +34,6 @@ class PriorityQueueManager:
|
||||
self._user_activity_event = asyncio.Event()
|
||||
self._background_waiters = 0
|
||||
self._initialized = True
|
||||
|
||||
logger.info("PriorityQueueManager initialized: user=20, image=10, background=5")
|
||||
|
||||
async def acquire_slot(self, priority: RequestPriority) -> asyncio.Semaphore:
|
||||
if priority == RequestPriority.USER_INITIATED:
|
||||
|
||||
@@ -1,10 +1,7 @@
|
||||
import logging
|
||||
import sqlite3
|
||||
import threading
|
||||
from pathlib import Path
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class QueueStore:
|
||||
def __init__(self, db_path: Path | None = None) -> None:
|
||||
|
||||
@@ -75,7 +75,7 @@ class RequestQueue(QueueInterface):
|
||||
self._on_import_callback = on_import_callback
|
||||
|
||||
async def add(self, album_mbid: str) -> dict:
|
||||
"""Blocking enqueue — waits for the result."""
|
||||
"""Blocking enqueue that waits for the result."""
|
||||
await self.start()
|
||||
|
||||
request = QueuedRequest(album_mbid)
|
||||
@@ -90,7 +90,6 @@ class RequestQueue(QueueInterface):
|
||||
"""Fire-and-forget enqueue. Returns True if enqueued, False if duplicate."""
|
||||
async with self._enqueue_lock:
|
||||
if self._store and self._store.has_active_mbid(album_mbid):
|
||||
logger.info("Duplicate request rejected for %s — already active", album_mbid[:8])
|
||||
return False
|
||||
|
||||
# Clear any prior cancellation so re-requests aren't silently dropped
|
||||
@@ -101,7 +100,6 @@ class RequestQueue(QueueInterface):
|
||||
if self._store:
|
||||
self._store.enqueue(request.job_id, album_mbid)
|
||||
await self._queue.put(request)
|
||||
logger.info("Enqueued request for album %s (job %s)", album_mbid[:8], request.job_id[:8])
|
||||
return True
|
||||
|
||||
async def cancel(self, album_mbid: str) -> bool:
|
||||
@@ -112,8 +110,6 @@ class RequestQueue(QueueInterface):
|
||||
# Mark for skip - items already in the asyncio.Queue can't be removed,
|
||||
# so workers check this set before processing.
|
||||
self._cancelled_mbids.add(album_mbid.lower())
|
||||
if removed:
|
||||
logger.info("Cancelled pending queue job for %s", album_mbid[:8])
|
||||
return removed
|
||||
|
||||
async def start(self) -> None:
|
||||
@@ -122,7 +118,6 @@ class RequestQueue(QueueInterface):
|
||||
for _ in range(self._concurrency - len(alive)):
|
||||
task = asyncio.create_task(self._process_queue())
|
||||
self._worker_tasks.append(task)
|
||||
logger.info("Queue processor started (%d workers)", self._concurrency)
|
||||
if not self._recovered:
|
||||
self._recovered = True
|
||||
self._recover_pending()
|
||||
@@ -135,12 +130,10 @@ class RequestQueue(QueueInterface):
|
||||
t.cancel()
|
||||
await asyncio.gather(*alive, return_exceptions=True)
|
||||
self._worker_tasks.clear()
|
||||
logger.info("Queue processor stopped")
|
||||
|
||||
async def drain(self, timeout: float = 30.0) -> None:
|
||||
try:
|
||||
await asyncio.wait_for(self._queue.join(), timeout=timeout)
|
||||
logger.info("Queue drained successfully")
|
||||
except asyncio.TimeoutError:
|
||||
remaining = self._queue.qsize()
|
||||
logger.warning("Queue drain timeout: %d items remaining", remaining)
|
||||
@@ -183,9 +176,6 @@ class RequestQueue(QueueInterface):
|
||||
logger.warning("Queue full during recovery, %d items deferred to next restart",
|
||||
len(pending) - recovered)
|
||||
break
|
||||
if recovered:
|
||||
logger.info("Recovered %d pending jobs from store", recovered)
|
||||
|
||||
self._retry_dead_letters()
|
||||
|
||||
async def _backfill_history(self, album_mbid: str) -> None:
|
||||
@@ -200,7 +190,6 @@ class RequestQueue(QueueInterface):
|
||||
artist_name="Unknown",
|
||||
album_title="Unknown",
|
||||
)
|
||||
logger.info("Backfilled history record for recovered job %s", album_mbid[:8])
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning("Failed to backfill history for %s: %s", album_mbid[:8], e)
|
||||
|
||||
@@ -213,7 +202,6 @@ class RequestQueue(QueueInterface):
|
||||
# Don't overwrite a user-initiated cancellation
|
||||
existing = await self._request_history.async_get_record(album_mbid)
|
||||
if existing and existing.status == "cancelled":
|
||||
logger.info("Skipping history update for %s — already cancelled", album_mbid[:8])
|
||||
return
|
||||
|
||||
payload = result.get("payload", {})
|
||||
@@ -294,8 +282,6 @@ class RequestQueue(QueueInterface):
|
||||
self._store.remove_dead_letter(row["id"])
|
||||
self._store.enqueue(row["id"], row["album_mbid"])
|
||||
enqueued += 1
|
||||
if enqueued:
|
||||
logger.info("Re-enqueued %d dead-letter jobs for retry", enqueued)
|
||||
|
||||
async def _process_queue(self) -> None:
|
||||
while True:
|
||||
@@ -305,7 +291,6 @@ class RequestQueue(QueueInterface):
|
||||
# Skip items cancelled while sitting in the asyncio.Queue
|
||||
if request.album_mbid.lower() in self._cancelled_mbids:
|
||||
self._cancelled_mbids.discard(request.album_mbid.lower())
|
||||
logger.info("Skipping cancelled request %s", request.album_mbid[:8])
|
||||
if not request.future.done():
|
||||
request.future.cancel()
|
||||
self._queue.task_done()
|
||||
@@ -319,14 +304,7 @@ class RequestQueue(QueueInterface):
|
||||
if self._store:
|
||||
self._store.mark_processing(request.job_id)
|
||||
|
||||
queue_wait_ms = int((time.monotonic() - request.enqueued_at) * 1000)
|
||||
logger.info(
|
||||
"Processing request %s (queue_wait=%dms)", request.album_mbid[:8], queue_wait_ms
|
||||
)
|
||||
|
||||
try:
|
||||
if request.recovered:
|
||||
logger.info("Processing recovered job %s for album %s", request.job_id[:8], request.album_mbid[:8])
|
||||
result = await self._processor(request.album_mbid)
|
||||
if not request.future.done():
|
||||
request.future.set_result(result)
|
||||
@@ -353,7 +331,6 @@ class RequestQueue(QueueInterface):
|
||||
self._queue.task_done()
|
||||
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Queue worker cancelled")
|
||||
break
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Queue worker error: %s", e)
|
||||
|
||||
@@ -63,10 +63,6 @@ class CircuitBreaker:
|
||||
def is_open(self) -> bool:
|
||||
if self.state == CircuitState.OPEN:
|
||||
if time.time() - self.last_failure_time > self.timeout:
|
||||
logger.info(
|
||||
"Circuit breaker '%s' transitioning to HALF_OPEN",
|
||||
self.name,
|
||||
)
|
||||
previous_state = self.state
|
||||
self.state = CircuitState.HALF_OPEN
|
||||
self.success_count = 0
|
||||
@@ -79,11 +75,6 @@ class CircuitBreaker:
|
||||
if self.state == CircuitState.HALF_OPEN:
|
||||
self.success_count += 1
|
||||
if self.success_count >= self.success_threshold:
|
||||
logger.info(
|
||||
"Circuit breaker '%s' closing after %d successes",
|
||||
self.name,
|
||||
self.success_count,
|
||||
)
|
||||
previous_state = self.state
|
||||
self.state = CircuitState.CLOSED
|
||||
self.failure_count = 0
|
||||
@@ -127,7 +118,6 @@ class CircuitBreaker:
|
||||
}
|
||||
|
||||
def reset(self):
|
||||
logger.info("Circuit breaker '%s' manually reset", self.name)
|
||||
previous_state = self.state
|
||||
self.state = CircuitState.CLOSED
|
||||
self.failure_count = 0
|
||||
@@ -144,15 +134,11 @@ class CircuitBreaker:
|
||||
self.record_failure()
|
||||
|
||||
async def atry_transition(self):
|
||||
"""Acquire lock and attempt OPEN→HALF_OPEN transition if timeout elapsed."""
|
||||
"""Acquire the lock and attempt an OPEN -> HALF_OPEN transition if the timeout has elapsed."""
|
||||
if self.state != CircuitState.OPEN:
|
||||
return
|
||||
async with self._lock:
|
||||
if self.state == CircuitState.OPEN and time.time() - self.last_failure_time > self.timeout:
|
||||
logger.info(
|
||||
"Circuit breaker '%s' transitioning to HALF_OPEN (locked)",
|
||||
self.name,
|
||||
)
|
||||
previous_state = self.state
|
||||
self.state = CircuitState.HALF_OPEN
|
||||
self.success_count = 0
|
||||
@@ -196,7 +182,6 @@ def with_retry(
|
||||
async def wrapper(*args: P.args, **kwargs: P.kwargs) -> T:
|
||||
service_name = circuit_breaker.name if circuit_breaker else "unknown"
|
||||
func_name = func.__name__
|
||||
start_time = time.time()
|
||||
|
||||
if circuit_breaker:
|
||||
await circuit_breaker.atry_transition()
|
||||
@@ -215,54 +200,23 @@ def with_retry(
|
||||
last_exception = None
|
||||
|
||||
for attempt in range(1, max_attempts + 1):
|
||||
attempt_start = time.time()
|
||||
try:
|
||||
result = await func(*args, **kwargs)
|
||||
|
||||
elapsed_ms = int((time.time() - attempt_start) * 1000)
|
||||
|
||||
if circuit_breaker:
|
||||
await circuit_breaker.arecord_success()
|
||||
|
||||
if attempt > 1:
|
||||
total_elapsed_ms = int((time.time() - start_time) * 1000)
|
||||
logger.info(
|
||||
"%s succeeded on attempt %d/%d",
|
||||
func_name,
|
||||
attempt,
|
||||
max_attempts,
|
||||
extra={
|
||||
"service_name": service_name,
|
||||
"function": func_name,
|
||||
"attempt": attempt,
|
||||
"max_attempts": max_attempts,
|
||||
"elapsed_ms": elapsed_ms,
|
||||
"total_elapsed_ms": total_elapsed_ms,
|
||||
}
|
||||
)
|
||||
|
||||
return result
|
||||
|
||||
except retriable_exceptions as e:
|
||||
last_exception = e
|
||||
elapsed_ms = int((time.time() - attempt_start) * 1000)
|
||||
|
||||
if attempt >= max_attempts:
|
||||
total_elapsed_ms = int((time.time() - start_time) * 1000)
|
||||
logger.error(
|
||||
"%s failed after %d attempts: %s",
|
||||
func_name,
|
||||
max_attempts,
|
||||
e,
|
||||
extra={
|
||||
"service_name": service_name,
|
||||
"function": func_name,
|
||||
"attempt": attempt,
|
||||
"max_attempts": max_attempts,
|
||||
"elapsed_ms": elapsed_ms,
|
||||
"total_elapsed_ms": total_elapsed_ms,
|
||||
"error": str(e),
|
||||
}
|
||||
)
|
||||
break
|
||||
|
||||
@@ -274,24 +228,6 @@ def with_retry(
|
||||
if jitter:
|
||||
delay *= (0.5 + random.random())
|
||||
|
||||
logger.warning(
|
||||
"%s attempt %d/%d failed: %s. Retrying in %.2fs...",
|
||||
func_name,
|
||||
attempt,
|
||||
max_attempts,
|
||||
e,
|
||||
delay,
|
||||
extra={
|
||||
"service_name": service_name,
|
||||
"function": func_name,
|
||||
"attempt": attempt,
|
||||
"max_attempts": max_attempts,
|
||||
"elapsed_ms": elapsed_ms,
|
||||
"retry_delay_s": f"{delay:.2f}",
|
||||
"error": str(e),
|
||||
}
|
||||
)
|
||||
|
||||
await asyncio.sleep(delay)
|
||||
|
||||
if circuit_breaker and last_exception:
|
||||
|
||||
+2
-5
@@ -62,7 +62,6 @@ async def lifespan(app: FastAPI):
|
||||
settings = get_settings()
|
||||
configured_level = getattr(logging, settings.log_level, logging.INFO)
|
||||
logging.getLogger().setLevel(configured_level)
|
||||
logger.info("Log level set to %s", settings.log_level)
|
||||
|
||||
await init_app_state(app)
|
||||
|
||||
@@ -94,14 +93,13 @@ async def lifespan(app: FastAPI):
|
||||
def handle_cache_warming_error(task: asyncio.Task):
|
||||
try:
|
||||
if task.cancelled():
|
||||
logger.info("Cache warming was cancelled")
|
||||
return
|
||||
|
||||
exc = task.exception()
|
||||
if exc:
|
||||
logger.error("Cache warming failed: %s", exc, exc_info=exc)
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Cache warming was cancelled")
|
||||
pass
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Error checking cache warming task: %s", e)
|
||||
|
||||
@@ -118,7 +116,6 @@ async def lifespan(app: FastAPI):
|
||||
|
||||
interrupted_state = await status_service.restore_from_persistence()
|
||||
if interrupted_state:
|
||||
logger.info("Found interrupted library sync, scheduling resume...")
|
||||
|
||||
async def resume_sync():
|
||||
try:
|
||||
@@ -138,7 +135,7 @@ async def lifespan(app: FastAPI):
|
||||
await status_service.complete_sync(str(e))
|
||||
|
||||
resume_task = asyncio.create_task(resume_sync())
|
||||
resume_task.add_done_callback(lambda t: logger.info("Resume sync task completed") if not t.exception() else logger.error("Resume sync failed: %s", t.exception()))
|
||||
resume_task.add_done_callback(lambda t: logger.error("Resume sync failed: %s", t.exception()) if t.exception() else None)
|
||||
TaskRegistry.get_instance().register("library-sync-resume", resume_task)
|
||||
|
||||
from core.dependencies import get_home_service
|
||||
|
||||
@@ -126,7 +126,6 @@ class AudioDBRepository:
|
||||
raise RateLimitedError("AudioDB rate limit exceeded", retry_after_seconds=60)
|
||||
|
||||
if response.status_code == 404:
|
||||
logger.debug("audiodb.request endpoint=%s status=404 elapsed_ms=%.1f", endpoint, elapsed_ms)
|
||||
return None
|
||||
|
||||
if response.status_code != 200:
|
||||
@@ -139,7 +138,6 @@ class AudioDBRepository:
|
||||
except (msgspec.DecodeError, ValueError, TypeError):
|
||||
raise ExternalServiceError("AudioDB returned invalid JSON")
|
||||
|
||||
logger.debug("audiodb.request endpoint=%s status=200 elapsed_ms=%.1f", endpoint, elapsed_ms)
|
||||
return data
|
||||
|
||||
except (ExternalServiceError, RateLimitedError):
|
||||
@@ -164,12 +162,10 @@ class AudioDBRepository:
|
||||
elapsed_ms = (time.monotonic() - t0) * 1000
|
||||
|
||||
if data is None:
|
||||
logger.debug("audiodb.lookup entity=artist lookup_type=mbid mbid=%s found=false elapsed_ms=%.1f", mbid, elapsed_ms)
|
||||
return None
|
||||
|
||||
item = _extract_first(data, "artists")
|
||||
if item is None:
|
||||
logger.debug("audiodb.lookup entity=artist lookup_type=mbid mbid=%s found=false elapsed_ms=%.1f", mbid, elapsed_ms)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -178,7 +174,6 @@ class AudioDBRepository:
|
||||
logger.warning("audiodb.schema_error entity=artist lookup_type=mbid mbid=%s error=%s", mbid, exc)
|
||||
_record_degradation(f"Schema error for artist mbid {mbid}: {exc}")
|
||||
return None
|
||||
logger.debug("audiodb.lookup entity=artist lookup_type=mbid mbid=%s found=true elapsed_ms=%.1f", mbid, elapsed_ms)
|
||||
return result
|
||||
|
||||
async def get_album_by_mbid(self, mbid: str) -> AudioDBAlbumResponse | None:
|
||||
@@ -198,12 +193,10 @@ class AudioDBRepository:
|
||||
elapsed_ms = (time.monotonic() - t0) * 1000
|
||||
|
||||
if data is None:
|
||||
logger.debug("audiodb.lookup entity=album lookup_type=mbid mbid=%s found=false elapsed_ms=%.1f", mbid, elapsed_ms)
|
||||
return None
|
||||
|
||||
item = _extract_first(data, "album")
|
||||
if item is None:
|
||||
logger.debug("audiodb.lookup entity=album lookup_type=mbid mbid=%s found=false elapsed_ms=%.1f", mbid, elapsed_ms)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -212,7 +205,6 @@ class AudioDBRepository:
|
||||
logger.warning("audiodb.schema_error entity=album lookup_type=mbid mbid=%s error=%s", mbid, exc)
|
||||
_record_degradation(f"Schema error for album mbid {mbid}: {exc}")
|
||||
return None
|
||||
logger.debug("audiodb.lookup entity=album lookup_type=mbid mbid=%s found=true elapsed_ms=%.1f", mbid, elapsed_ms)
|
||||
return result
|
||||
|
||||
async def search_artist_by_name(self, name: str) -> AudioDBArtistResponse | None:
|
||||
@@ -232,12 +224,10 @@ class AudioDBRepository:
|
||||
elapsed_ms = (time.monotonic() - t0) * 1000
|
||||
|
||||
if data is None:
|
||||
logger.debug("audiodb.lookup entity=artist lookup_type=name name=%s found=false elapsed_ms=%.1f", name, elapsed_ms)
|
||||
return None
|
||||
|
||||
item = _extract_first(data, "artists")
|
||||
if item is None:
|
||||
logger.debug("audiodb.lookup entity=artist lookup_type=name name=%s found=false elapsed_ms=%.1f", name, elapsed_ms)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -246,7 +236,6 @@ class AudioDBRepository:
|
||||
logger.warning("audiodb.schema_error entity=artist lookup_type=name name=%s error=%s", name, exc)
|
||||
_record_degradation(f"Schema error for artist name search: {exc}")
|
||||
return None
|
||||
logger.debug("audiodb.lookup entity=artist lookup_type=name name=%s found=true elapsed_ms=%.1f", name, elapsed_ms)
|
||||
return result
|
||||
|
||||
async def search_album_by_name(self, artist: str, album: str) -> AudioDBAlbumResponse | None:
|
||||
@@ -266,18 +255,10 @@ class AudioDBRepository:
|
||||
elapsed_ms = (time.monotonic() - t0) * 1000
|
||||
|
||||
if data is None:
|
||||
logger.debug(
|
||||
"audiodb.lookup entity=album lookup_type=name artist=%s album=%s found=false elapsed_ms=%.1f",
|
||||
artist, album, elapsed_ms,
|
||||
)
|
||||
return None
|
||||
|
||||
item = _extract_first(data, "album")
|
||||
if item is None:
|
||||
logger.debug(
|
||||
"audiodb.lookup entity=album lookup_type=name artist=%s album=%s found=false elapsed_ms=%.1f",
|
||||
artist, album, elapsed_ms,
|
||||
)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -291,8 +272,4 @@ class AudioDBRepository:
|
||||
)
|
||||
_record_degradation(f"Schema error for album name search: {exc}")
|
||||
return None
|
||||
logger.debug(
|
||||
"audiodb.lookup entity=album lookup_type=name artist=%s album=%s found=true elapsed_ms=%.1f",
|
||||
artist, album, elapsed_ms,
|
||||
)
|
||||
return result
|
||||
|
||||
@@ -91,7 +91,7 @@ class AlbumCoverFetcher:
|
||||
timeout=LOCAL_SOURCE_TIMEOUT_SECONDS,
|
||||
)
|
||||
except TimeoutError:
|
||||
logger.debug(f"Timed out local source lookup for release group {release_group_id[:8]}...")
|
||||
pass
|
||||
if result:
|
||||
return result
|
||||
size_suffix = f"-{size}" if size else ""
|
||||
@@ -146,7 +146,6 @@ class AlbumCoverFetcher:
|
||||
) -> tuple[bytes, str, str] | None:
|
||||
if self._audiodb_service is None:
|
||||
return None
|
||||
logger.debug(f"[IMG:AudioDB] Fetching album image for {release_group_id[:8]}...")
|
||||
try:
|
||||
cached_images = await self._audiodb_service.fetch_and_cache_album_images(release_group_id)
|
||||
if cached_images is None or cached_images.is_negative or not cached_images.album_thumb_url:
|
||||
@@ -174,8 +173,8 @@ class AlbumCoverFetcher:
|
||||
except ClientDisconnectedError:
|
||||
raise
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"[IMG:AudioDB] Exception for {release_group_id[:8]}: {e}")
|
||||
return None
|
||||
|
||||
async def _get_cover_from_best_release(
|
||||
self,
|
||||
release_group_id: str,
|
||||
@@ -231,7 +230,7 @@ class AlbumCoverFetcher:
|
||||
except ClientDisconnectedError:
|
||||
raise
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to fetch cover from best release: {e}")
|
||||
return None
|
||||
return None
|
||||
|
||||
async def _fetch_from_lidarr(
|
||||
@@ -249,7 +248,6 @@ class AlbumCoverFetcher:
|
||||
image_url = await self._lidarr_repo.get_album_image_url(release_group_id, size=size)
|
||||
if not image_url:
|
||||
return None
|
||||
logger.debug(f"Fetching album cover from Lidarr: {release_group_id[:8]}...")
|
||||
response = await self._http_get(
|
||||
image_url,
|
||||
priority,
|
||||
@@ -266,7 +264,6 @@ class AlbumCoverFetcher:
|
||||
task.add_done_callback(_log_task_error)
|
||||
return (content, content_type, "lidarr")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Failed to fetch album cover from Lidarr for {release_group_id}: {e}")
|
||||
return None
|
||||
|
||||
async def _fetch_from_jellyfin(
|
||||
@@ -303,7 +300,6 @@ class AlbumCoverFetcher:
|
||||
task.add_done_callback(_log_task_error)
|
||||
return (content, content_type, "jellyfin")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Failed to fetch album cover from Jellyfin for {musicbrainz_id}: {e}")
|
||||
return None
|
||||
|
||||
async def fetch_release_cover(
|
||||
@@ -322,9 +318,7 @@ class AlbumCoverFetcher:
|
||||
except ClientDisconnectedError:
|
||||
raise
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(
|
||||
f"[IMG:AudioDB] Failed resolving release group for release {release_id[:8]}: {e}"
|
||||
)
|
||||
pass
|
||||
result = None
|
||||
try:
|
||||
await check_disconnected(is_disconnected)
|
||||
@@ -333,7 +327,7 @@ class AlbumCoverFetcher:
|
||||
timeout=LOCAL_SOURCE_TIMEOUT_SECONDS,
|
||||
)
|
||||
except TimeoutError:
|
||||
logger.debug(f"Timed out local source lookup for release {release_id[:8]}...")
|
||||
pass
|
||||
if result:
|
||||
return result
|
||||
if release_group_id:
|
||||
@@ -366,7 +360,7 @@ class AlbumCoverFetcher:
|
||||
except ClientDisconnectedError:
|
||||
raise
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to fetch release cover for {release_id}: {e}")
|
||||
pass
|
||||
return None
|
||||
|
||||
async def _fetch_release_local_sources(
|
||||
|
||||
@@ -130,7 +130,6 @@ class ArtistImageFetcher:
|
||||
priority: RequestPriority = RequestPriority.IMAGE_FETCH,
|
||||
is_disconnected: DisconnectCallable | None = None,
|
||||
) -> tuple[bytes, str, str] | None:
|
||||
logger.info(f"[IMG] Fetching artist image for {artist_id[:8]}... (size={size})")
|
||||
result = None
|
||||
had_transient_failure = False
|
||||
last_transient_error: Exception | None = None
|
||||
@@ -140,12 +139,9 @@ class ArtistImageFetcher:
|
||||
except TRANSIENT_FETCH_EXCEPTIONS as exc:
|
||||
had_transient_failure = True
|
||||
last_transient_error = exc
|
||||
logger.warning(f"[IMG:AudioDB] Transient fetch failure for {artist_id[:8]}...: {exc}")
|
||||
result = None
|
||||
if result:
|
||||
logger.info(f"[IMG] SUCCESS from AudioDB for {artist_id[:8]}...")
|
||||
return result
|
||||
logger.info(f"[IMG] AudioDB failed for {artist_id[:8]}..., trying local sources")
|
||||
try:
|
||||
await check_disconnected(is_disconnected)
|
||||
local_result, local_transient = await asyncio.wait_for(
|
||||
@@ -156,27 +152,21 @@ class ArtistImageFetcher:
|
||||
had_transient_failure = True
|
||||
result = local_result
|
||||
except TimeoutError:
|
||||
logger.debug(f"[IMG] Timed out local source lookup for {artist_id[:8]}...")
|
||||
had_transient_failure = True
|
||||
last_transient_error = TimeoutError(
|
||||
f"Timed out local source lookup for {artist_id}"
|
||||
)
|
||||
if result:
|
||||
logger.info(f"[IMG] SUCCESS from local source for {artist_id[:8]}...")
|
||||
return result
|
||||
logger.info(f"[IMG] Local sources missed for {artist_id[:8]}..., trying Wikidata")
|
||||
try:
|
||||
await check_disconnected(is_disconnected)
|
||||
result = await self._fetch_from_wikidata(artist_id, size, file_path, priority=priority)
|
||||
except TRANSIENT_FETCH_EXCEPTIONS as exc:
|
||||
had_transient_failure = True
|
||||
last_transient_error = exc
|
||||
logger.warning(f"[IMG] Transient Wikidata fetch failure for {artist_id[:8]}...: {exc}")
|
||||
result = None
|
||||
if result:
|
||||
logger.info(f"[IMG] SUCCESS from Wikidata for {artist_id[:8]}...")
|
||||
return result
|
||||
logger.info(f"[IMG] FAILED: No image found for {artist_id[:8]}... from any source")
|
||||
if had_transient_failure:
|
||||
raise TransientImageFetchError(
|
||||
f"Transient failure while fetching artist image for {artist_id}"
|
||||
@@ -196,7 +186,6 @@ class ArtistImageFetcher:
|
||||
result = await self._fetch_from_lidarr(artist_id, size, file_path, priority=priority)
|
||||
except TRANSIENT_FETCH_EXCEPTIONS as exc:
|
||||
had_transient_failure = True
|
||||
logger.warning(f"[IMG:Lidarr] Transient failure for {artist_id[:8]}: {exc}")
|
||||
result = None
|
||||
|
||||
if result:
|
||||
@@ -206,7 +195,6 @@ class ArtistImageFetcher:
|
||||
result = await self._fetch_from_jellyfin(artist_id, file_path, priority=priority)
|
||||
except TRANSIENT_FETCH_EXCEPTIONS as exc:
|
||||
had_transient_failure = True
|
||||
logger.warning(f"[IMG:Jellyfin] Transient failure for {artist_id[:8]}: {exc}")
|
||||
result = None
|
||||
|
||||
return result, had_transient_failure
|
||||
@@ -219,7 +207,6 @@ class ArtistImageFetcher:
|
||||
) -> tuple[bytes, str, str] | None:
|
||||
if self._audiodb_service is None:
|
||||
return None
|
||||
logger.debug(f"[IMG:AudioDB] Fetching artist image for {artist_id[:8]}...")
|
||||
try:
|
||||
images = await self._audiodb_service.fetch_and_cache_artist_images(artist_id)
|
||||
if images is None or images.is_negative or not images.thumb_url:
|
||||
@@ -248,7 +235,6 @@ class ArtistImageFetcher:
|
||||
except TRANSIENT_FETCH_EXCEPTIONS:
|
||||
raise
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"[IMG:AudioDB] Exception for {artist_id[:8]}: {e}")
|
||||
return None
|
||||
|
||||
async def _fetch_from_lidarr(
|
||||
@@ -259,23 +245,19 @@ class ArtistImageFetcher:
|
||||
priority: RequestPriority = RequestPriority.IMAGE_FETCH,
|
||||
) -> tuple[bytes, str, str] | None:
|
||||
if not self._lidarr_repo:
|
||||
logger.debug(f"[IMG:Lidarr] No Lidarr repo configured for {artist_id[:8]}")
|
||||
return None
|
||||
if not self._lidarr_repo.is_configured():
|
||||
return None
|
||||
try:
|
||||
image_url = await self._lidarr_repo.get_artist_image_url(artist_id, size=size or 250)
|
||||
if not image_url:
|
||||
logger.info(f"[IMG:Lidarr] No image URL returned for {artist_id[:8]}")
|
||||
return None
|
||||
logger.info(f"[IMG:Lidarr] Fetching from URL for {artist_id[:8]}...")
|
||||
response = await self._http_get(
|
||||
image_url,
|
||||
priority,
|
||||
source="lidarr",
|
||||
)
|
||||
if response.status_code != 200:
|
||||
logger.warning(f"[IMG:Lidarr] HTTP {response.status_code} for {artist_id[:8]}")
|
||||
return None
|
||||
content_type = response.headers.get("content-type", "")
|
||||
if not _is_valid_image_content_type(content_type):
|
||||
@@ -288,7 +270,6 @@ class ArtistImageFetcher:
|
||||
except TRANSIENT_FETCH_EXCEPTIONS:
|
||||
raise
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"[IMG:Lidarr] Exception for {artist_id[:8]}: {e}")
|
||||
return None
|
||||
|
||||
async def _fetch_from_jellyfin(
|
||||
@@ -327,7 +308,6 @@ class ArtistImageFetcher:
|
||||
except TRANSIENT_FETCH_EXCEPTIONS:
|
||||
raise
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"[IMG:Jellyfin] Exception for {artist_id[:8]}: {e}")
|
||||
return None
|
||||
|
||||
async def _fetch_from_wikidata(
|
||||
@@ -349,7 +329,6 @@ class ArtistImageFetcher:
|
||||
match = re.search(r'/(?:wiki|entity)/(Q\d+)', wikidata_url)
|
||||
wikidata_id = match.group(1) if match else None
|
||||
if not wikidata_id:
|
||||
logger.debug(f"Could not parse Wikidata Q-id from URL: {wikidata_url}")
|
||||
return None
|
||||
api_url = (
|
||||
f"https://www.wikidata.org/w/api.php"
|
||||
@@ -432,14 +411,11 @@ class ArtistImageFetcher:
|
||||
return None
|
||||
|
||||
async def _lookup_wikidata_url(self, artist_id: str) -> str | None:
|
||||
logger.info(f"[IMG:Wikidata] Looking up wikidata URL for {artist_id[:8]}...")
|
||||
if not self._mb_repo:
|
||||
logger.warning(f"[IMG:Wikidata] MusicBrainz repository not available for {artist_id}")
|
||||
return None
|
||||
try:
|
||||
artist_data = await self._mb_repo.get_artist_relations(artist_id)
|
||||
if not artist_data:
|
||||
logger.info(f"[IMG:Wikidata] No artist data from MB for {artist_id[:8]}")
|
||||
return None
|
||||
url_relations = artist_data.get("relations", [])
|
||||
if url_relations:
|
||||
@@ -449,7 +425,6 @@ class ArtistImageFetcher:
|
||||
url_obj = url_rel.get("url", {})
|
||||
target = url_obj.get("resource", "") if isinstance(url_obj, dict) else ""
|
||||
if typ == "wikidata" and target:
|
||||
logger.info(f"[IMG:Wikidata] Found URL for {artist_id[:8]}: {target}")
|
||||
return target
|
||||
external_links = artist_data.get("external_links") or artist_data.get("external_links_list")
|
||||
if external_links:
|
||||
@@ -462,7 +437,6 @@ class ArtistImageFetcher:
|
||||
ext_url = None
|
||||
if ext_type == "wikidata" and ext_url:
|
||||
return ext_url
|
||||
logger.info(f"[IMG:Wikidata] No wikidata link found for {artist_id[:8]}")
|
||||
return None
|
||||
except TRANSIENT_FETCH_EXCEPTIONS:
|
||||
raise
|
||||
|
||||
@@ -101,8 +101,8 @@ class CoverDiskCache:
|
||||
|
||||
await asyncio.gather(write_content(), write_meta(), write_wikidata())
|
||||
await self.enforce_size_limit()
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to write disk cache: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
async def write_negative(
|
||||
self,
|
||||
@@ -121,8 +121,8 @@ class CoverDiskCache:
|
||||
meta_path = file_path.with_suffix(".meta.json")
|
||||
async with aiofiles.open(meta_path, "w") as f:
|
||||
await f.write(_encode_json(meta))
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to write negative disk cache: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
async def is_negative(self, file_path: Path) -> bool:
|
||||
meta_path = file_path.with_suffix(".meta.json")
|
||||
@@ -147,8 +147,7 @@ class CoverDiskCache:
|
||||
task = asyncio.create_task(self._update_meta_access(meta_path, meta))
|
||||
task.add_done_callback(_log_task_error)
|
||||
return True
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to read negative disk cache: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
return False
|
||||
|
||||
async def read(
|
||||
@@ -199,8 +198,7 @@ class CoverDiskCache:
|
||||
task = asyncio.create_task(self._update_meta_access(file_path.with_suffix('.meta.json'), meta))
|
||||
task.add_done_callback(_log_task_error)
|
||||
return content, content_type, extra_data if extra_data else None
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to read disk cache: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
return None
|
||||
|
||||
async def _update_meta_access(self, meta_file: Path, meta: dict) -> None:
|
||||
@@ -210,8 +208,8 @@ class CoverDiskCache:
|
||||
meta['last_accessed'] = datetime.now().timestamp()
|
||||
async with aiofiles.open(meta_file, 'w') as f:
|
||||
await f.write(_encode_json(meta))
|
||||
except OSError as exc:
|
||||
logger.debug("Failed to update coverart disk cache meta %s: %s", meta_file, exc)
|
||||
except OSError:
|
||||
pass
|
||||
|
||||
async def get_content_hash(self, file_path: Path) -> Optional[str]:
|
||||
meta_path = file_path.with_suffix('.meta.json')
|
||||
@@ -249,8 +247,7 @@ class CoverDiskCache:
|
||||
meta['content_sha1'] = content_hash
|
||||
await self._update_meta_access(meta_path, meta)
|
||||
return content_hash
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to get disk cache content hash: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
return None
|
||||
|
||||
async def enforce_size_limit(self, force: bool = False) -> int:
|
||||
@@ -311,13 +308,6 @@ class CoverDiskCache:
|
||||
if bytes_freed >= bytes_to_free:
|
||||
break
|
||||
|
||||
if bytes_freed > 0:
|
||||
logger.info(
|
||||
"Evicted %d bytes from cover cache (target max=%d bytes)",
|
||||
bytes_freed,
|
||||
self.max_size_bytes,
|
||||
)
|
||||
|
||||
return bytes_freed
|
||||
|
||||
async def delete_by_identifiers(self, identifiers: list[tuple[str, str]]) -> int:
|
||||
@@ -334,7 +324,7 @@ class CoverDiskCache:
|
||||
return count
|
||||
|
||||
def cleanup_expired(self) -> int:
|
||||
"""Sync — call via asyncio.to_thread() from background tasks."""
|
||||
"""Synchronous helper for background tasks via asyncio.to_thread()."""
|
||||
count = 0
|
||||
now = datetime.now().timestamp()
|
||||
if not self.cache_dir.exists():
|
||||
@@ -350,12 +340,10 @@ class CoverDiskCache:
|
||||
meta_path.unlink(missing_ok=True)
|
||||
(self.cache_dir / f"{stem}.wikidata").unlink(missing_ok=True)
|
||||
count += 1
|
||||
if count:
|
||||
logger.info("Expired cover cache cleanup: removed %d entries", count)
|
||||
return count
|
||||
|
||||
def demote_orphaned(self, valid_hashes: set[str]) -> int:
|
||||
"""Sync — call via asyncio.to_thread() from background tasks."""
|
||||
"""Synchronous helper for background tasks via asyncio.to_thread()."""
|
||||
count = 0
|
||||
now = datetime.now().timestamp()
|
||||
if not self.cache_dir.exists():
|
||||
@@ -377,8 +365,6 @@ class CoverDiskCache:
|
||||
except Exception: # noqa: BLE001
|
||||
continue
|
||||
count += 1
|
||||
if count:
|
||||
logger.info("Demoted %d orphaned monitored covers to expiring", count)
|
||||
return count
|
||||
|
||||
def get_file_path(self, identifier: str, suffix: str) -> Path:
|
||||
@@ -412,8 +398,6 @@ class CoverDiskCache:
|
||||
meta.pop('expires_at', None)
|
||||
async with aiofiles.open(meta_path, 'w') as f:
|
||||
await f.write(_encode_json(meta))
|
||||
logger.debug(f"Promoted cover cache to persistent: {identifier_type}={identifier}, size={size}")
|
||||
return True
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to promote cover cache to persistent: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
return False
|
||||
|
||||
@@ -224,7 +224,7 @@ class CoverArtRepository:
|
||||
task = asyncio.create_task(self._disk_cache.enforce_size_limit(force=True))
|
||||
task.add_done_callback(_log_task_error)
|
||||
except RuntimeError:
|
||||
logger.debug("No running event loop to enforce cover cache size at initialization")
|
||||
pass
|
||||
|
||||
@property
|
||||
def disk_cache(self) -> CoverDiskCache:
|
||||
@@ -497,11 +497,9 @@ class CoverArtRepository:
|
||||
file_path = self._disk_cache.get_file_path(identifier, "img")
|
||||
|
||||
if cached_memory := await self._memory_get(identifier, "img"):
|
||||
logger.debug(f"Cache HIT (memory): Artist image {artist_id[:8]}...")
|
||||
return cached_memory
|
||||
|
||||
if cached := await self._disk_cache.read(file_path, ["source", "wikidata_id"]):
|
||||
logger.debug(f"Cache HIT (disk): Artist image {artist_id[:8]}...")
|
||||
source = "wikidata"
|
||||
if cached[2] and isinstance(cached[2], dict):
|
||||
source = cached[2].get("source") or source
|
||||
@@ -512,12 +510,10 @@ class CoverArtRepository:
|
||||
if size and size != 250:
|
||||
fallback_identifier = f"artist_{artist_id}_250"
|
||||
if cached_memory := await self._memory_get(fallback_identifier, "img"):
|
||||
logger.debug(f"Cache HIT (memory - fallback 250px): Artist image {artist_id[:8]}...")
|
||||
return cached_memory
|
||||
|
||||
fallback_path = self._disk_cache.get_file_path(fallback_identifier, "img")
|
||||
if cached := await self._disk_cache.read(fallback_path, ["source", "wikidata_id"]):
|
||||
logger.debug(f"Cache HIT (disk - fallback 250px): Artist image {artist_id[:8]}...")
|
||||
source = "wikidata"
|
||||
if cached[2] and isinstance(cached[2], dict):
|
||||
source = cached[2].get("source") or source
|
||||
@@ -526,11 +522,8 @@ class CoverArtRepository:
|
||||
return result
|
||||
|
||||
if await self._disk_cache.is_negative(file_path):
|
||||
logger.debug(f"Cache HIT (disk-negative): Artist image {artist_id[:8]}...")
|
||||
return None
|
||||
|
||||
logger.debug(f"Cache MISS (disk): Artist image {artist_id[:8]}... - fetching from Wikidata")
|
||||
|
||||
dedupe_key = f"artist:img:{artist_id}:{size}"
|
||||
try:
|
||||
result = await _deduplicator.dedupe(
|
||||
@@ -540,11 +533,6 @@ class CoverArtRepository:
|
||||
except ClientDisconnectedError:
|
||||
raise
|
||||
except (TransientImageFetchError, CircuitOpenError, httpx.HTTPError, ExternalServiceError, RateLimitedError) as e:
|
||||
logger.warning(
|
||||
"Transient artist image fetch failure for %s: %s",
|
||||
artist_id[:8],
|
||||
e,
|
||||
)
|
||||
_record_degradation(f"Artist image fetch failed for {artist_id[:8]}: {e}")
|
||||
return None
|
||||
|
||||
@@ -572,11 +560,9 @@ class CoverArtRepository:
|
||||
file_path = self._disk_cache.get_file_path(identifier, suffix)
|
||||
|
||||
if cached_memory := await self._memory_get(identifier, suffix):
|
||||
logger.debug(f"Cache HIT (memory): Album cover {release_group_id[:8]}...")
|
||||
return cached_memory
|
||||
|
||||
if cached := await self._disk_cache.read(file_path, ["source"]):
|
||||
logger.debug(f"Cache HIT (disk): Album cover {release_group_id[:8]}...")
|
||||
source = "cover-art-archive"
|
||||
if cached[2] and isinstance(cached[2], dict):
|
||||
source = cached[2].get("source") or source
|
||||
@@ -585,11 +571,8 @@ class CoverArtRepository:
|
||||
return result
|
||||
|
||||
if await self._disk_cache.is_negative(file_path):
|
||||
logger.debug(f"Cache HIT (disk-negative): Album cover {release_group_id[:8]}...")
|
||||
return None
|
||||
|
||||
logger.debug(f"Cache MISS (disk): Album cover {release_group_id[:8]}... - fetching from CoverArtArchive")
|
||||
|
||||
dedupe_key = f"cover:rg:{release_group_id}:{size}"
|
||||
result = await _deduplicator.dedupe(
|
||||
dedupe_key,
|
||||
@@ -619,7 +602,6 @@ class CoverArtRepository:
|
||||
file_path = self._disk_cache.get_file_path(identifier, suffix)
|
||||
|
||||
if cached_memory := await self._memory_get(identifier, suffix):
|
||||
logger.debug(f"Cache HIT (memory): Release cover {release_id[:8]}...")
|
||||
return cached_memory
|
||||
|
||||
if cached := await self._disk_cache.read(file_path, ["source"]):
|
||||
@@ -631,7 +613,6 @@ class CoverArtRepository:
|
||||
return result
|
||||
|
||||
if await self._disk_cache.is_negative(file_path):
|
||||
logger.debug(f"Cache HIT (disk-negative): Release cover {release_id[:8]}...")
|
||||
return None
|
||||
|
||||
dedupe_key = f"cover:rel:{release_id}:{size}"
|
||||
@@ -678,16 +659,10 @@ class CoverArtRepository:
|
||||
async with semaphore:
|
||||
try:
|
||||
await self.get_release_group_cover(album_id, size)
|
||||
except Exception as e: # noqa: BLE001
|
||||
error_msg = str(e)
|
||||
if "Invalid" in error_msg or "MBID" in error_msg:
|
||||
logger.warning(f"Invalid MBID in batch prefetch: {album_id} - {e}")
|
||||
else:
|
||||
logger.debug(f"Failed to prefetch cover for {album_id}: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
logger.info(f"Batch prefetching {len(valid_album_ids)} covers with max {max_concurrent} concurrent requests")
|
||||
await asyncio.gather(*[fetch_with_limit(aid) for aid in valid_album_ids], return_exceptions=True)
|
||||
logger.debug(f"Completed batch prefetch of {len(valid_album_ids)} covers")
|
||||
|
||||
async def promote_cover_to_persistent(self, identifier: str, identifier_type: str = "album") -> bool:
|
||||
return await self._disk_cache.promote_to_persistent(identifier, identifier_type)
|
||||
|
||||
@@ -549,7 +549,6 @@ class JellyfinRepository:
|
||||
):
|
||||
return item
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"MBID search fallback failed for {musicbrainz_id}: {e}")
|
||||
_record_degradation(f"Album MBID search fallback failed: {e}")
|
||||
|
||||
return None
|
||||
@@ -563,7 +562,6 @@ class JellyfinRepository:
|
||||
if item.provider_ids.get("MusicBrainzArtist") == musicbrainz_id:
|
||||
return item
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Artist MBID search fallback failed for {musicbrainz_id}: {e}")
|
||||
_record_degradation(f"Artist MBID search fallback failed: {e}")
|
||||
|
||||
return None
|
||||
@@ -665,9 +663,6 @@ class JellyfinRepository:
|
||||
)
|
||||
if sqlite_index:
|
||||
await self._cache.set(cache_key, sqlite_index, ttl_seconds=3600)
|
||||
logger.info(
|
||||
f"Loaded MBID index from SQLite with {len(sqlite_index)} entries"
|
||||
)
|
||||
return sqlite_index
|
||||
|
||||
index: dict[str, str] = {}
|
||||
@@ -714,7 +709,6 @@ class JellyfinRepository:
|
||||
await self._cache.set(cache_key, index, ttl_seconds=3600)
|
||||
if self._mbid_store:
|
||||
await self._mbid_store.save_jellyfin_mbid_index(index)
|
||||
logger.info(f"Built Jellyfin MBID index with {len(index)} entries")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to build MBID index: {e}")
|
||||
_record_degradation(f"Failed to build MBID index: {e}")
|
||||
@@ -1056,11 +1050,9 @@ class JellyfinRepository:
|
||||
|
||||
raw_play_session_id = result.get("PlaySessionId")
|
||||
if not raw_play_session_id:
|
||||
logger.warning(
|
||||
"PlaybackInfo returned null PlaySessionId",
|
||||
extra={"item_id": item_id},
|
||||
)
|
||||
play_session_id = raw_play_session_id or ""
|
||||
play_session_id = ""
|
||||
else:
|
||||
play_session_id = raw_play_session_id
|
||||
media_sources = result.get("MediaSources") or []
|
||||
if not media_sources:
|
||||
raise ExternalServiceError(f"Playback info missing media sources for {item_id}")
|
||||
|
||||
@@ -274,10 +274,6 @@ class LastFmRepository:
|
||||
signed=True,
|
||||
http_method="POST",
|
||||
)
|
||||
logger.info(
|
||||
"Now playing reported to Last.fm",
|
||||
extra={"artist": artist, "track": track},
|
||||
)
|
||||
return True
|
||||
|
||||
async def scrobble(
|
||||
@@ -306,10 +302,6 @@ class LastFmRepository:
|
||||
signed=True,
|
||||
http_method="POST",
|
||||
)
|
||||
logger.info(
|
||||
"Scrobble submitted to Last.fm",
|
||||
extra={"artist": artist, "track": track, "timestamp": timestamp},
|
||||
)
|
||||
return True
|
||||
|
||||
|
||||
|
||||
@@ -102,7 +102,6 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
cover_url = constructed_url
|
||||
|
||||
if cover_url:
|
||||
logger.debug(f"[Lidarr:Album] Found cover for {album_mbid[:8]}: {cover_url[:60]}...")
|
||||
await self._cache.set(cache_key, cover_url, ttl_seconds=3600)
|
||||
return cover_url
|
||||
|
||||
@@ -110,7 +109,6 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
return None
|
||||
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Failed to get album image from Lidarr for {album_mbid}: {e}")
|
||||
return None
|
||||
|
||||
async def get_album_details(self, album_mbid: str) -> Optional[dict[str, Any]]:
|
||||
@@ -193,11 +191,9 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
}
|
||||
|
||||
await self._cache.set(cache_key, result, ttl_seconds=300)
|
||||
logger.debug(f"[Lidarr] Fetched album details for {album_mbid[:8]}")
|
||||
return result
|
||||
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Failed to get album details from Lidarr for {album_mbid}: {e}")
|
||||
return None
|
||||
|
||||
async def get_album_tracks(self, album_id: int) -> list[dict[str, Any]]:
|
||||
@@ -231,11 +227,9 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
tracks.sort(key=lambda t: (t["disc_number"], t["track_number"]))
|
||||
|
||||
await self._cache.set(cache_key, tracks, ttl_seconds=300)
|
||||
logger.debug(f"[Lidarr] Fetched {len(tracks)} tracks for album ID {album_id}")
|
||||
return tracks
|
||||
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Failed to get tracks from Lidarr for album ID {album_id}: {e}")
|
||||
return []
|
||||
|
||||
async def get_track_file(self, track_file_id: int) -> dict[str, Any] | None:
|
||||
@@ -277,7 +271,6 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
items = await self._get("/api/v1/album", params={"foreignAlbumId": album_mbid})
|
||||
return items[0] if items else None
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Error getting album by foreign ID {album_mbid}: {e}")
|
||||
return None
|
||||
|
||||
_ALBUM_MUTABLE_FIELDS = frozenset({"monitored"})
|
||||
@@ -298,7 +291,6 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
params = {"deleteFiles": str(delete_files).lower(), "addImportListExclusion": "false"}
|
||||
await self._delete(f"/api/v1/album/{album_id}", params=params)
|
||||
await self._invalidate_album_list_caches()
|
||||
logger.info(f"Deleted album ID {album_id} (deleteFiles={delete_files})")
|
||||
return True
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to delete album {album_id}: {e}")
|
||||
@@ -380,11 +372,6 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
is_monitored = album_obj.get("monitored", False)
|
||||
|
||||
if has_files and is_monitored:
|
||||
total_ms = int((time.monotonic() - t0) * 1000)
|
||||
logger.info(
|
||||
"add_album timing: album=%s artist_ensure=%dms total=%dms (already downloaded)",
|
||||
musicbrainz_id[:8], artist_ensure_ms, total_ms,
|
||||
)
|
||||
await self._invalidate_album_list_caches()
|
||||
return {
|
||||
"message": f"Album already downloaded: {album_title}",
|
||||
@@ -396,8 +383,8 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
|
||||
try:
|
||||
await self._post_command({"name": "AlbumSearch", "albumIds": [album_id]})
|
||||
except ExternalServiceError as exc:
|
||||
logger.warning("Failed to queue AlbumSearch for %s: %s", musicbrainz_id, exc)
|
||||
except ExternalServiceError:
|
||||
pass
|
||||
|
||||
await self._unmonitor_auto_monitored_albums(
|
||||
artist_id, musicbrainz_id, album_id, pre_add_monitored_ids
|
||||
@@ -405,19 +392,13 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
await self._invalidate_album_list_caches()
|
||||
await self._cache.clear_prefix(f"{LIDARR_PREFIX}artists:mbids")
|
||||
|
||||
total_ms = int((time.monotonic() - t0) * 1000)
|
||||
logger.info(
|
||||
"add_album timing: album=%s artist_ensure=%dms total=%dms (existing album, monitor+search)",
|
||||
musicbrainz_id[:8], artist_ensure_ms, total_ms,
|
||||
)
|
||||
|
||||
return {
|
||||
"message": f"Album monitored & search triggered: {album_title}",
|
||||
"monitored": True,
|
||||
"payload": album_obj,
|
||||
}
|
||||
|
||||
# Album doesn't exist yet — wait for indexing after artist add/refresh
|
||||
# The album does not exist yet, so wait for indexing after the artist add or refresh.
|
||||
if artist_created:
|
||||
await self._wait_for_artist_commands_to_complete(artist_id, timeout=120.0)
|
||||
|
||||
@@ -469,7 +450,6 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
except ExternalServiceError as e:
|
||||
err_str = str(e).lower()
|
||||
if "already exists" in err_str:
|
||||
logger.info("Album %s already exists per Lidarr, fetching", musicbrainz_id)
|
||||
album_obj = await self._get_album_by_foreign_id(musicbrainz_id)
|
||||
if album_obj:
|
||||
if not album_obj.get("monitored"):
|
||||
@@ -483,7 +463,7 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
elif "post failed" in err_str or "405" in err_str or "metadata" in err_str:
|
||||
raise ExternalServiceError(
|
||||
f"Lidarr rejected '{album_title}' ({album_type}"
|
||||
f"{' — ' + ', '.join(secondary_types) if secondary_types else ''}). "
|
||||
f"{': ' + ', '.join(secondary_types) if secondary_types else ''}). "
|
||||
f"Your Metadata Profile probably excludes {album_type}s. "
|
||||
f"Go to Lidarr > Settings > Profiles > Metadata Profiles and enable '{album_type}'."
|
||||
)
|
||||
@@ -508,8 +488,8 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
|
||||
try:
|
||||
await self._post_command({"name": "AlbumSearch", "albumIds": [album_id]})
|
||||
except ExternalServiceError as exc:
|
||||
logger.warning("Failed to queue AlbumSearch for %s: %s", musicbrainz_id, exc)
|
||||
except ExternalServiceError:
|
||||
pass
|
||||
|
||||
# Unmonitor albums that Lidarr auto-monitored during the add
|
||||
await self._unmonitor_auto_monitored_albums(
|
||||
@@ -521,12 +501,6 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
await self._invalidate_album_list_caches()
|
||||
await self._cache.clear_prefix(f"{LIDARR_PREFIX}artists:mbids")
|
||||
|
||||
total_ms = int((time.monotonic() - t0) * 1000)
|
||||
logger.info(
|
||||
"add_album timing: album=%s artist_ensure=%dms total=%dms (new album, created=%s)",
|
||||
musicbrainz_id[:8], artist_ensure_ms, total_ms, artist_created,
|
||||
)
|
||||
|
||||
return {
|
||||
"message": f"Album added & monitored: {album_title}",
|
||||
"monitored": True,
|
||||
@@ -560,8 +534,8 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
if not has_running_commands:
|
||||
break
|
||||
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Error checking command status: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
await asyncio.sleep(5.0)
|
||||
|
||||
@@ -627,9 +601,5 @@ class LidarrAlbumRepository(LidarrHistoryRepository):
|
||||
"/api/v1/album/monitor",
|
||||
{"albumIds": to_unmonitor, "monitored": False},
|
||||
)
|
||||
logger.info(
|
||||
"Unmonitored %d auto-monitored albums for artist %d (kept requested %s)",
|
||||
len(to_unmonitor), artist_id, requested_mbid[:8],
|
||||
)
|
||||
except ExternalServiceError as exc:
|
||||
logger.warning("Failed to unmonitor auto-monitored albums: %s", exc)
|
||||
except ExternalServiceError:
|
||||
pass
|
||||
|
||||
@@ -16,17 +16,11 @@ class LidarrArtistRepository(LidarrBase):
|
||||
cache_key = f"{LIDARR_ARTIST_IMAGE_PREFIX}{artist_mbid}:{size or 'orig'}"
|
||||
cached_url = await self._cache.get(cache_key)
|
||||
if cached_url is not None:
|
||||
if cached_url:
|
||||
logger.debug(f"[Lidarr:Image] Cache HIT for {artist_mbid[:8]}")
|
||||
else:
|
||||
logger.debug(f"[Lidarr:Image] Cache HIT (negative) for {artist_mbid[:8]}")
|
||||
return cached_url if cached_url else None
|
||||
|
||||
logger.info(f"[Lidarr:Image] Cache MISS - querying Lidarr for {artist_mbid[:8]}")
|
||||
try:
|
||||
data = await self._get("/api/v1/artist", params={"mbId": artist_mbid})
|
||||
if not data or not isinstance(data, list) or len(data) == 0:
|
||||
logger.info(f"[Lidarr:Image] Artist not found in Lidarr for {artist_mbid[:8]}")
|
||||
await self._cache.set(cache_key, "", ttl_seconds=300)
|
||||
return None
|
||||
|
||||
@@ -34,10 +28,8 @@ class LidarrArtistRepository(LidarrBase):
|
||||
artist_id = artist.get("id")
|
||||
artist_name = artist.get("artistName", "Unknown")
|
||||
images = artist.get("images", [])
|
||||
logger.debug(f"[Lidarr:Image] Found artist '{artist_name}' (id={artist_id}) with {len(images)} images")
|
||||
|
||||
if not artist_id or not images:
|
||||
logger.info(f"[Lidarr:Image] No images for {artist_mbid[:8]} ({artist_name})")
|
||||
await self._cache.set(cache_key, "", ttl_seconds=300)
|
||||
return None
|
||||
|
||||
@@ -63,7 +55,6 @@ class LidarrArtistRepository(LidarrBase):
|
||||
|
||||
image_url = poster_url or fanart_url
|
||||
if image_url:
|
||||
logger.info(f"[Lidarr:Image] Found image for {artist_mbid[:8]} ({artist_name}): {image_url[:60]}...")
|
||||
await self._cache.set(cache_key, image_url, ttl_seconds=3600)
|
||||
return image_url
|
||||
|
||||
@@ -72,7 +63,6 @@ class LidarrArtistRepository(LidarrBase):
|
||||
return None
|
||||
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"[Lidarr:Image] Exception for {artist_mbid[:8]}: {e}")
|
||||
return None
|
||||
|
||||
async def get_artist_details(self, artist_mbid: str) -> Optional[dict[str, Any]]:
|
||||
@@ -119,11 +109,9 @@ class LidarrArtistRepository(LidarrBase):
|
||||
}
|
||||
|
||||
await self._cache.set(cache_key, result, ttl_seconds=300)
|
||||
logger.debug(f"[Lidarr] Fetched artist details for {artist_mbid[:8]}")
|
||||
return result
|
||||
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Failed to get artist details from Lidarr for {artist_mbid}: {e}")
|
||||
return None
|
||||
|
||||
async def get_artist_albums(self, artist_mbid: str) -> list[dict[str, Any]]:
|
||||
@@ -193,25 +181,21 @@ class LidarrArtistRepository(LidarrBase):
|
||||
albums.sort(key=lambda a: a.get("release_date") or "", reverse=True)
|
||||
|
||||
await self._cache.set(cache_key, albums, ttl_seconds=300)
|
||||
logger.debug(f"[Lidarr] Fetched {len(albums)} albums for artist {artist_mbid[:8]}")
|
||||
return albums
|
||||
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Failed to get artist albums from Lidarr for {artist_mbid}: {e}")
|
||||
return []
|
||||
|
||||
async def _get_artist_by_id(self, artist_id: int) -> Optional[dict[str, Any]]:
|
||||
try:
|
||||
return await self._get(f"/api/v1/artist/{artist_id}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Error getting artist {artist_id}: {e}")
|
||||
return None
|
||||
|
||||
async def delete_artist(self, artist_id: int, delete_files: bool = False) -> bool:
|
||||
try:
|
||||
params = {"deleteFiles": str(delete_files).lower(), "addImportListExclusion": "false"}
|
||||
await self._delete(f"/api/v1/artist/{artist_id}", params=params)
|
||||
logger.info(f"Deleted artist ID {artist_id} (deleteFiles={delete_files})")
|
||||
return True
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to delete artist {artist_id}: {e}")
|
||||
@@ -243,10 +227,6 @@ class LidarrArtistRepository(LidarrBase):
|
||||
cache_key = f"{LIDARR_ARTIST_DETAILS_PREFIX}{artist_mbid}"
|
||||
await self._cache.delete(cache_key)
|
||||
|
||||
logger.info(
|
||||
"Updated artist %s monitoring: monitored=%s, monitorNewItems=%s",
|
||||
artist_mbid[:8], monitored, monitor_new_items,
|
||||
)
|
||||
return {"monitored": monitored, "auto_download": monitor_new_items == "all"}
|
||||
|
||||
async def _ensure_artist_exists(
|
||||
@@ -256,10 +236,9 @@ class LidarrArtistRepository(LidarrBase):
|
||||
try:
|
||||
items = await self._get("/api/v1/artist", params={"mbId": artist_mbid})
|
||||
if items:
|
||||
logger.info("Artist already exists: %s", items[0].get("artistName"))
|
||||
return items[0], False
|
||||
except ExternalServiceError as exc:
|
||||
logger.debug("Failed to query existing Lidarr artist %s: %s", artist_mbid, exc)
|
||||
pass
|
||||
|
||||
try:
|
||||
roots = await self._get("/api/v1/rootfolder")
|
||||
@@ -300,19 +279,16 @@ class LidarrArtistRepository(LidarrBase):
|
||||
try:
|
||||
created = await self._post("/api/v1/artist", payload)
|
||||
artist_id = created["id"]
|
||||
logger.info("Created artist %s (ID: %s), triggering refresh", artist_name, artist_id)
|
||||
|
||||
await self._await_command(
|
||||
{"name": "RefreshArtist", "artistId": artist_id},
|
||||
timeout=180.0,
|
||||
)
|
||||
|
||||
logger.info("Artist %s refresh complete", artist_name)
|
||||
return created, True
|
||||
except ExternalServiceError as exc:
|
||||
err_str = str(exc).lower()
|
||||
if "already exists" in err_str or "409" in err_str:
|
||||
logger.info("Artist %s was added concurrently, retrying GET", artist_mbid)
|
||||
items = await self._get("/api/v1/artist", params={"mbId": artist_mbid})
|
||||
if items:
|
||||
return items[0], False
|
||||
|
||||
@@ -1,6 +1,5 @@
|
||||
import asyncio
|
||||
import httpx
|
||||
import logging
|
||||
import msgspec
|
||||
import time
|
||||
from typing import Any, Optional
|
||||
@@ -11,8 +10,6 @@ from infrastructure.cache.memory_cache import CacheInterface
|
||||
from infrastructure.http.deduplication import get_deduplicator
|
||||
from infrastructure.resilience.retry import with_retry, CircuitBreaker
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
_lidarr_circuit_breaker = CircuitBreaker(
|
||||
failure_threshold=5,
|
||||
success_threshold=2,
|
||||
@@ -157,8 +154,7 @@ class LidarrBase:
|
||||
async def _post_command(self, body: dict[str, Any]) -> Any:
|
||||
try:
|
||||
return await self._post("/api/v1/command", body)
|
||||
except ExternalServiceError as exc:
|
||||
logger.warning("Failed to post Lidarr command %s: %s", body.get("name"), exc)
|
||||
except ExternalServiceError:
|
||||
return None
|
||||
|
||||
async def _get_command(self, cmd_id: int) -> Any:
|
||||
@@ -180,8 +176,7 @@ class LidarrBase:
|
||||
try:
|
||||
status = await self._get_command(cmd_id)
|
||||
last_status = status
|
||||
except ExternalServiceError as exc:
|
||||
logger.debug("Lidarr command %s status poll failed: %s", cmd_id, exc)
|
||||
except ExternalServiceError:
|
||||
continue
|
||||
|
||||
state = (status or {}).get("status") or (status or {}).get("state")
|
||||
@@ -189,8 +184,7 @@ class LidarrBase:
|
||||
return status
|
||||
|
||||
return last_status
|
||||
except ExternalServiceError as exc:
|
||||
logger.warning("Failed to await Lidarr command %s: %s", body.get("name"), exc)
|
||||
except ExternalServiceError:
|
||||
return None
|
||||
|
||||
async def _wait_for(
|
||||
@@ -207,8 +201,8 @@ class LidarrBase:
|
||||
last = await fetch_coro_factory()
|
||||
if stop(last):
|
||||
return last
|
||||
except ExternalServiceError as exc:
|
||||
logger.debug("Lidarr wait_for poll failed: %s", exc)
|
||||
except ExternalServiceError:
|
||||
pass
|
||||
await asyncio.sleep(poll)
|
||||
return last
|
||||
|
||||
|
||||
@@ -1,12 +1,9 @@
|
||||
import logging
|
||||
from typing import Any
|
||||
from models.common import ServiceStatus
|
||||
from models.request import QueueItem
|
||||
from infrastructure.cache.cache_keys import LIDARR_PREFIX
|
||||
from .base import LidarrBase
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
LIDARR_QUEUE_KEY = f"{LIDARR_PREFIX}queue"
|
||||
LIDARR_QUEUE_TTL = 30
|
||||
|
||||
|
||||
@@ -12,7 +12,6 @@ class LidarrHistoryRepository(LidarrBase):
|
||||
async def get_recently_imported(self, limit: int = 20) -> list[LibraryAlbum]:
|
||||
try:
|
||||
album_dates: dict[str, tuple[int, dict]] = {}
|
||||
|
||||
try:
|
||||
params = {
|
||||
"page": 1,
|
||||
@@ -52,16 +51,13 @@ class LidarrHistoryRepository(LidarrBase):
|
||||
'album_data': album_data,
|
||||
'artist_data': record.get("artist", {})
|
||||
})
|
||||
|
||||
logger.info(f"Found {len(album_dates)} unique albums from {len(history_data.get('records', []))} history records")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to get history data: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
if len(album_dates) < limit * 2:
|
||||
album_dates = await self._supplement_with_album_dates(album_dates, limit)
|
||||
|
||||
if not album_dates:
|
||||
logger.warning("No albums found with dates from either history or track files")
|
||||
return []
|
||||
|
||||
sorted_albums = sorted(album_dates.items(), key=lambda x: x[1][0], reverse=True)
|
||||
@@ -111,10 +107,8 @@ class LidarrHistoryRepository(LidarrBase):
|
||||
'album_data': album,
|
||||
'artist_data': album.get("artist", {})
|
||||
})
|
||||
|
||||
logger.info(f"Total {len(album_dates)} unique albums after supplementing with album dates")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to supplement with album data: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
return album_dates
|
||||
|
||||
@@ -153,7 +147,6 @@ class LidarrHistoryRepository(LidarrBase):
|
||||
artist_mbid=artist_mbid,
|
||||
date_added=date_added,
|
||||
)
|
||||
)
|
||||
)
|
||||
|
||||
logger.info(f"Retrieved {len(out)} recently added albums (merged from history and track files)")
|
||||
return out
|
||||
return out
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
from datetime import datetime
|
||||
from typing import Any, TYPE_CHECKING
|
||||
from models.library import LibraryAlbum, LibraryGroupedAlbum, LibraryGroupedArtist
|
||||
@@ -16,8 +15,6 @@ from .base import LidarrBase
|
||||
if TYPE_CHECKING:
|
||||
from infrastructure.persistence.request_history import RequestHistoryStore
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class LidarrLibraryRepository(LidarrBase):
|
||||
_request_history_store: "RequestHistoryStore | None" = None
|
||||
@@ -63,8 +60,8 @@ class LidarrLibraryRepository(LidarrBase):
|
||||
try:
|
||||
dt = datetime.fromisoformat(added_str.replace('Z', '+00:00'))
|
||||
date_added = int(dt.timestamp())
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to parse date_added '{added_str}' for album '{item.get('title')}': {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
out.append(
|
||||
LibraryAlbum(
|
||||
@@ -80,9 +77,6 @@ class LidarrLibraryRepository(LidarrBase):
|
||||
)
|
||||
)
|
||||
|
||||
if filtered_count > 0:
|
||||
logger.info(f"Filtered out {filtered_count} unmonitored albums from library")
|
||||
|
||||
await self._cache.set(cache_key, out, ttl_seconds=300)
|
||||
return out
|
||||
|
||||
@@ -115,8 +109,8 @@ class LidarrLibraryRepository(LidarrBase):
|
||||
try:
|
||||
dt = datetime.fromisoformat(added_str.replace('Z', '+00:00'))
|
||||
date_added = int(dt.timestamp())
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to parse date_added '{added_str}' for artist '{artist_name}': {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
if artist_mbid not in artists_dict:
|
||||
artists_dict[artist_mbid] = {
|
||||
@@ -131,9 +125,6 @@ class LidarrLibraryRepository(LidarrBase):
|
||||
date_added < artists_dict[artist_mbid]['date_added']):
|
||||
artists_dict[artist_mbid]['date_added'] = date_added
|
||||
|
||||
if filtered_count > 0:
|
||||
logger.info(f"Filtered out {filtered_count} unmonitored albums from artist extraction")
|
||||
|
||||
result = list(artists_dict.values())
|
||||
await self._cache.set(cache_key, result, ttl_seconds=300)
|
||||
return result
|
||||
@@ -235,8 +226,7 @@ class LidarrLibraryRepository(LidarrBase):
|
||||
if self._request_history_store is not None:
|
||||
try:
|
||||
return await self._request_history_store.async_get_active_mbids()
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning("RequestHistoryStore unavailable, falling back to empty set: %s", e)
|
||||
except Exception: # noqa: BLE001
|
||||
return set()
|
||||
return set()
|
||||
|
||||
|
||||
@@ -1,6 +1,5 @@
|
||||
import asyncio
|
||||
import httpx
|
||||
import logging
|
||||
from typing import Any
|
||||
|
||||
import msgspec
|
||||
@@ -22,8 +21,6 @@ from repositories.listenbrainz_models import (
|
||||
from infrastructure.degradation import try_get_degradation_context
|
||||
from infrastructure.integration_result import IntegrationResult
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
_SOURCE = "listenbrainz"
|
||||
|
||||
|
||||
@@ -590,11 +587,6 @@ class ListenBrainzRepository:
|
||||
|
||||
result = await self._get(f"/1/popularity/top-release-groups-for-artist/{artist_mbid}")
|
||||
if not result or not isinstance(result, list):
|
||||
logger.info(
|
||||
"LB top-release-groups returned empty/non-list for %s (type=%s)",
|
||||
artist_mbid[:8],
|
||||
type(result).__name__,
|
||||
)
|
||||
return []
|
||||
|
||||
release_groups = []
|
||||
@@ -663,10 +655,6 @@ class ListenBrainzRepository:
|
||||
"payload": [{"track_metadata": track_metadata}],
|
||||
}
|
||||
await self._post("/1/submit-listens", payload, require_auth=True)
|
||||
logger.info(
|
||||
"Now playing reported to ListenBrainz",
|
||||
extra={"artist": artist_name, "track": track_name},
|
||||
)
|
||||
return True
|
||||
|
||||
async def submit_single_listen(
|
||||
@@ -696,14 +684,6 @@ class ListenBrainzRepository:
|
||||
],
|
||||
}
|
||||
await self._post("/1/submit-listens", payload, require_auth=True)
|
||||
logger.info(
|
||||
"Scrobble submitted to ListenBrainz",
|
||||
extra={
|
||||
"artist": artist_name,
|
||||
"track": track_name,
|
||||
"listened_at": listened_at,
|
||||
},
|
||||
)
|
||||
return True
|
||||
|
||||
async def get_recommendation_playlists(
|
||||
@@ -790,9 +770,4 @@ class ListenBrainzRepository:
|
||||
if tracks:
|
||||
await self._cache.set(cache_key, playlist, ttl_seconds=21600)
|
||||
|
||||
logger.info(
|
||||
"Fetched recommendation playlist: %s (%d tracks)",
|
||||
playlist.title,
|
||||
len(tracks),
|
||||
)
|
||||
return playlist
|
||||
|
||||
@@ -288,7 +288,6 @@ class MusicBrainzAlbumMixin:
|
||||
cache_key = f"{MB_RELEASE_TO_RG_PREFIX}{release_id}"
|
||||
cached = await self._cache.get(cache_key)
|
||||
if cached is not None:
|
||||
logger.debug(f"[MB] Cache hit for release {release_id[:8]}: '{cached[:8] if cached else 'empty'}'")
|
||||
return cached if cached != "" else None
|
||||
|
||||
dedupe_key = f"{MB_RELEASE_TO_RG_PREFIX}{release_id}"
|
||||
@@ -303,7 +302,6 @@ class MusicBrainzAlbumMixin:
|
||||
cache_key: str,
|
||||
) -> str | None:
|
||||
try:
|
||||
logger.debug(f"[MB] Fetching release group for release {release_id[:8]}")
|
||||
result = await mb_api_get(
|
||||
f"/release/{release_id}",
|
||||
params={"inc": "release-groups+recordings"},
|
||||
@@ -312,7 +310,6 @@ class MusicBrainzAlbumMixin:
|
||||
)
|
||||
rg = result.release_group
|
||||
rg_id = rg.get("id")
|
||||
logger.debug(f"[MB] Resolved release {release_id[:8]} -> release_group {rg_id}")
|
||||
await self._cache.set(cache_key, rg_id or "", ttl_seconds=86400)
|
||||
|
||||
positions: dict[str, list[int]] = {}
|
||||
@@ -330,7 +327,6 @@ class MusicBrainzAlbumMixin:
|
||||
|
||||
return rg_id
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"[MB] Failed to get release group for release {release_id[:8]}: {e}")
|
||||
_record_mb_degradation(f"release-to-rg lookup failed: {e}")
|
||||
await self._cache.set(cache_key, "", ttl_seconds=3600)
|
||||
return None
|
||||
|
||||
@@ -255,7 +255,7 @@ class MusicBrainzArtistMixin:
|
||||
try:
|
||||
await self.get_release_group_by_id(rg_id, priority=RequestPriority.BACKGROUND_SYNC)
|
||||
except (CircuitOpenError, ExternalServiceError, httpx.HTTPError) as exc:
|
||||
logger.debug("Failed to warm release group cache for %s: %s", rg_id, exc)
|
||||
pass
|
||||
|
||||
async def get_artist_release_groups(
|
||||
self,
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
from typing import Any, TypeVar
|
||||
|
||||
import httpx
|
||||
@@ -10,8 +9,6 @@ from infrastructure.resilience.rate_limiter import TokenBucketRateLimiter
|
||||
from infrastructure.queue.priority_queue import RequestPriority, get_priority_queue
|
||||
from infrastructure.http.deduplication import RequestDeduplicator
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
MB_API_BASE = "https://musicbrainz.org/ws/2"
|
||||
|
||||
mb_circuit_breaker = CircuitBreaker(
|
||||
|
||||
@@ -1,6 +1,5 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
from collections.abc import AsyncIterator
|
||||
from typing import Any
|
||||
|
||||
@@ -8,8 +7,6 @@ import msgspec
|
||||
|
||||
from core.exceptions import NavidromeApiError, NavidromeAuthError, NavidromeSubsonicError
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class SubsonicArtist(msgspec.Struct):
|
||||
id: str
|
||||
|
||||
@@ -264,7 +264,6 @@ class NavidromeRepository:
|
||||
await self._request("/rest/ping")
|
||||
return True
|
||||
except Exception: # noqa: BLE001
|
||||
logger.debug("Navidrome ping failed", exc_info=True)
|
||||
_record_degradation("Navidrome ping failed")
|
||||
return False
|
||||
|
||||
@@ -537,7 +536,6 @@ class NavidromeRepository:
|
||||
await self._request("/rest/scrobble", params)
|
||||
return True
|
||||
except Exception: # noqa: BLE001
|
||||
logger.warning("Navidrome scrobble failed", exc_info=True)
|
||||
_record_degradation("Navidrome scrobble failed")
|
||||
return False
|
||||
|
||||
@@ -547,7 +545,6 @@ class NavidromeRepository:
|
||||
await self._request("/rest/scrobble", params)
|
||||
return True
|
||||
except Exception: # noqa: BLE001
|
||||
logger.warning("Navidrome now-playing report failed", exc_info=True)
|
||||
_record_degradation("Navidrome now-playing report failed")
|
||||
return False
|
||||
|
||||
|
||||
@@ -1,5 +1,4 @@
|
||||
import json
|
||||
import logging
|
||||
import sqlite3
|
||||
import threading
|
||||
from datetime import datetime, timezone
|
||||
@@ -7,8 +6,6 @@ from pathlib import Path
|
||||
from typing import Optional
|
||||
from uuid import uuid4
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
_UNSET = object()
|
||||
|
||||
@@ -694,8 +691,8 @@ class PlaylistRepository:
|
||||
if conn is not None:
|
||||
try:
|
||||
conn.close()
|
||||
except sqlite3.Error as exc:
|
||||
logger.warning("Failed to close playlist repository connection: %s", exc)
|
||||
except sqlite3.Error:
|
||||
pass
|
||||
self._local.conn = None
|
||||
|
||||
|
||||
|
||||
@@ -71,16 +71,16 @@ class YouTubeRepository:
|
||||
self._daily_count = 0
|
||||
self._quota_date = today
|
||||
self._save_quota()
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to load YouTube quota state: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
def _save_quota(self) -> None:
|
||||
quota_file = get_quota_file_path()
|
||||
try:
|
||||
quota_file.parent.mkdir(parents=True, exist_ok=True)
|
||||
quota_file.write_bytes(msgspec.json.encode(YouTubeQuotaState(date=self._quota_date, count=self._daily_count)))
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"Failed to save YouTube quota state: {e}")
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
def configure(self, api_key: str) -> None:
|
||||
self._api_key = api_key
|
||||
|
||||
@@ -125,14 +125,10 @@ class AlbumService:
|
||||
async def _get_cached_album_info(self, release_group_id: str, cache_key: str) -> Optional[AlbumInfo]:
|
||||
cached_info = await self._cache.get(cache_key)
|
||||
if cached_info:
|
||||
logger.info(f"Cache HIT (RAM): Album {release_group_id[:8]}... - instant load")
|
||||
return await self._revalidate_library_status(release_group_id, cached_info)
|
||||
|
||||
logger.debug(f"Cache MISS (RAM): Album {release_group_id[:8]}...")
|
||||
|
||||
disk_data = await self._disk_cache.get_album(release_group_id)
|
||||
if disk_data:
|
||||
logger.info(f"Cache HIT (Disk): Album {release_group_id[:8]}... - loading from persistent cache")
|
||||
album_info = msgspec.convert(disk_data, AlbumInfo, strict=False)
|
||||
album_info = await self._revalidate_library_status(release_group_id, album_info)
|
||||
advanced_settings = self._preferences_service.get_advanced_settings()
|
||||
@@ -140,7 +136,6 @@ class AlbumService:
|
||||
await self._cache.set(cache_key, album_info, ttl_seconds=ttl)
|
||||
return album_info
|
||||
|
||||
logger.debug(f"Cache MISS (Disk): Album {release_group_id[:8]}...")
|
||||
return None
|
||||
|
||||
async def _revalidate_library_status(self, release_group_id: str, album_info: AlbumInfo) -> AlbumInfo:
|
||||
@@ -159,10 +154,6 @@ class AlbumService:
|
||||
self._revalidation_timestamps[release_group_id] = time.monotonic()
|
||||
current_in_library = self._check_lidarr_in_library(lidarr_album)
|
||||
if current_in_library != album_info.in_library:
|
||||
logger.info(
|
||||
f"Library status changed for album {release_group_id[:8]}...: "
|
||||
f"{album_info.in_library} -> {current_in_library}, updating caches"
|
||||
)
|
||||
album_info.in_library = current_in_library
|
||||
await self._save_album_to_cache(release_group_id, album_info)
|
||||
return album_info
|
||||
@@ -173,7 +164,6 @@ class AlbumService:
|
||||
ttl = advanced_settings.cache_ttl_album_library if album_info.in_library else advanced_settings.cache_ttl_album_non_library
|
||||
await self._cache.set(cache_key, album_info, ttl_seconds=ttl)
|
||||
await self._disk_cache.set_album(release_group_id, album_info, is_monitored=album_info.in_library, ttl_seconds=ttl if not album_info.in_library else None)
|
||||
logger.info(f"Cached {'library' if album_info.in_library else 'non-library'} album {release_group_id[:8]}... for {ttl // 3600}h")
|
||||
|
||||
def _check_lidarr_in_library(self, lidarr_album: dict | None) -> bool:
|
||||
if lidarr_album and lidarr_album.get("monitored", False):
|
||||
@@ -189,7 +179,7 @@ class AlbumService:
|
||||
return
|
||||
await self.get_album_info(release_group_id)
|
||||
except Exception: # noqa: BLE001
|
||||
logger.debug(f"Background album cache warm failed for {release_group_id[:8]}")
|
||||
pass
|
||||
|
||||
async def refresh_album(self, release_group_id: str) -> AlbumInfo:
|
||||
release_group_id = validate_mbid(release_group_id, "album")
|
||||
@@ -200,7 +190,6 @@ class AlbumService:
|
||||
self._revalidation_timestamps.pop(release_group_id, None)
|
||||
self._album_in_flight.pop(release_group_id, None)
|
||||
|
||||
logger.info("Cleared all caches for album %s", release_group_id[:8])
|
||||
return await self.get_album_info(release_group_id)
|
||||
|
||||
async def get_album_info(self, release_group_id: str, monitored_mbids: set[str] = None) -> AlbumInfo:
|
||||
@@ -248,10 +237,8 @@ class AlbumService:
|
||||
lidarr_album = await self._lidarr_repo.get_album_details(release_group_id) if self._lidarr_repo.is_configured() else None
|
||||
in_library = self._check_lidarr_in_library(lidarr_album)
|
||||
if in_library and lidarr_album:
|
||||
logger.info(f"Using Lidarr as primary source for album {release_group_id[:8]}")
|
||||
album_info = await self._build_album_from_lidarr(release_group_id, lidarr_album)
|
||||
else:
|
||||
logger.info(f"Using MusicBrainz as primary source for album {release_group_id[:8]}")
|
||||
album_info = await self._build_album_from_musicbrainz(release_group_id, monitored_mbids)
|
||||
album_info = await self._apply_audiodb_album_images(
|
||||
album_info, release_group_id, album_info.artist_name, album_info.title,
|
||||
@@ -306,7 +293,6 @@ class AlbumService:
|
||||
lidarr_album = await self._lidarr_repo.get_album_details(release_group_id) if self._lidarr_repo.is_configured() else None
|
||||
in_library = self._check_lidarr_in_library(lidarr_album)
|
||||
if lidarr_album and lidarr_album.get("monitored", False):
|
||||
logger.info(f"[BASIC] Using Lidarr for album {release_group_id[:8]}")
|
||||
basic = AlbumBasicInfo(**lidarr_to_basic_info(lidarr_album, release_group_id, in_library, is_requested=is_requested))
|
||||
if not basic.album_thumb_url:
|
||||
basic.album_thumb_url = await self._get_audiodb_album_thumb(
|
||||
@@ -314,7 +300,6 @@ class AlbumService:
|
||||
allow_fetch=False,
|
||||
)
|
||||
return basic
|
||||
logger.info(f"[BASIC] Using MusicBrainz for album {release_group_id[:8]}")
|
||||
release_group = await self._fetch_release_group(release_group_id)
|
||||
if lidarr_album is None:
|
||||
cached_album = await self._library_db.get_album_by_mbid(release_group_id)
|
||||
@@ -356,7 +341,6 @@ class AlbumService:
|
||||
in_library = lidarr_album is not None and lidarr_album.get("monitored", False)
|
||||
|
||||
if in_library and lidarr_album:
|
||||
logger.info(f"[TRACKS] Using Lidarr for album {release_group_id[:8]}")
|
||||
album_id = lidarr_album.get("id")
|
||||
tracks = []
|
||||
total_length = 0
|
||||
@@ -384,7 +368,6 @@ class AlbumService:
|
||||
country=None,
|
||||
)
|
||||
|
||||
logger.info(f"[TRACKS] Using MusicBrainz for album {release_group_id[:8]}")
|
||||
release_group = await self._fetch_release_group(release_group_id)
|
||||
ranked_releases = get_ranked_releases(release_group)
|
||||
|
||||
@@ -519,7 +502,6 @@ class AlbumService:
|
||||
country = None
|
||||
|
||||
if not tracks:
|
||||
logger.debug(f"No tracks from Lidarr for album {release_group_id[:8]}, falling back to MusicBrainz")
|
||||
try:
|
||||
release_group = await self._fetch_release_group(release_group_id)
|
||||
ranked_releases = get_ranked_releases(release_group)
|
||||
@@ -586,12 +568,6 @@ class AlbumService:
|
||||
cached_album = await self._library_db.get_album_by_mbid(release_group_id)
|
||||
in_library = cached_album is not None
|
||||
|
||||
if in_library:
|
||||
logger.info(f"Cache HIT (library DB): Album {release_group_id[:8]}... is in library")
|
||||
else:
|
||||
logger.debug(f"Cache MISS (library DB): Album {release_group_id[:8]}... not in library")
|
||||
|
||||
logger.info(f"API CALL (MusicBrainz): Fetching album {release_group_id[:8]}...")
|
||||
release_group = await self._fetch_release_group(release_group_id)
|
||||
primary_release = find_primary_release(release_group)
|
||||
artist_name, artist_id = extract_artist_info(release_group)
|
||||
|
||||
@@ -165,10 +165,8 @@ class ArtistDiscoveryService:
|
||||
recordings = await self._lb_repo.get_artist_top_recordings(artist_mbid, count=count)
|
||||
|
||||
release_ids = [r.release_mbid for r in recordings if r.release_mbid]
|
||||
logger.info(f"Top songs for {artist_mbid}: {len(recordings)} recordings, {len(release_ids)} with release_mbid")
|
||||
|
||||
rg_map = await self._resolve_release_groups(release_ids)
|
||||
logger.info(f"Resolved {len(rg_map)} release groups from {len(release_ids)} releases")
|
||||
|
||||
songs = []
|
||||
for r in recordings[:count]:
|
||||
@@ -235,7 +233,6 @@ class ArtistDiscoveryService:
|
||||
try:
|
||||
release_groups = await self._lb_repo.get_artist_top_release_groups(artist_mbid, count=count)
|
||||
if not release_groups:
|
||||
logger.info("ListenBrainz returned no release groups for %s", artist_mbid[:8])
|
||||
fallback_albums = await self._get_top_albums_from_recordings_fallback(
|
||||
artist_mbid, count
|
||||
)
|
||||
@@ -414,7 +411,6 @@ class ArtistDiscoveryService:
|
||||
) -> int:
|
||||
global _discovery_precache_running
|
||||
if _discovery_precache_running:
|
||||
logger.info("Discovery precache already running, skipping duplicate invocation")
|
||||
return 0
|
||||
|
||||
_discovery_precache_running = True
|
||||
@@ -511,9 +507,6 @@ class ArtistDiscoveryService:
|
||||
artist_name = (mbid_to_name or {}).get(mbid, mbid[:8])
|
||||
await status_service.update_progress(local_progress, current_item=artist_name, generation=generation)
|
||||
|
||||
if local_progress % 10 == 0:
|
||||
logger.info("Discovery precache progress: %d/%d artists", local_progress, len(artist_mbids))
|
||||
|
||||
return True
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning("Failed to precache discovery for %s: %s", mbid[:8], e)
|
||||
@@ -550,19 +543,12 @@ class ArtistDiscoveryService:
|
||||
chunk = max(discovery_concurrency * 4, 20)
|
||||
for i in range(0, len(artist_mbids), chunk):
|
||||
if status_service and status_service.is_cancelled():
|
||||
logger.info("Discovery precache cancelled by user")
|
||||
break
|
||||
batch = artist_mbids[i:i + chunk]
|
||||
batch_tasks = [asyncio.create_task(process_artist_with_timeout(i + j, mbid)) for j, mbid in enumerate(batch)]
|
||||
if batch_tasks:
|
||||
await asyncio.gather(*batch_tasks, return_exceptions=True)
|
||||
|
||||
logger.info(
|
||||
"Discovery precache complete: %d/%d artists refreshed (%d source fetches)",
|
||||
cached_count,
|
||||
len(artist_mbids),
|
||||
source_fetches,
|
||||
)
|
||||
return cached_count
|
||||
|
||||
async def _resolve_release_groups(self, release_ids: list[str]) -> dict[str, str]:
|
||||
@@ -570,7 +556,6 @@ class ArtistDiscoveryService:
|
||||
return {}
|
||||
|
||||
unique_ids = list(dict.fromkeys(release_ids))
|
||||
logger.info(f"Resolving {len(unique_ids)} unique release IDs to release groups (from {len(release_ids)} total)")
|
||||
tasks = [self._mb_repo.get_release_group_id_from_release(rid) for rid in unique_ids]
|
||||
results = await asyncio.gather(*tasks, return_exceptions=True)
|
||||
|
||||
@@ -586,7 +571,6 @@ class ArtistDiscoveryService:
|
||||
errors += 1
|
||||
logger.warning(f"Resolution returned None/empty for {rid}")
|
||||
|
||||
logger.info(f"Release group resolution: {len(rg_map)} succeeded, {errors} failed")
|
||||
return rg_map
|
||||
|
||||
async def _get_similar_artists_lastfm(
|
||||
|
||||
@@ -106,10 +106,7 @@ class ArtistService:
|
||||
new_artist_in_library = result.musicbrainz_id and result.musicbrainz_id.lower() in artist_mbids
|
||||
if new_artist_in_library != result.in_library:
|
||||
result.in_library = new_artist_in_library
|
||||
changed = True
|
||||
|
||||
if changed:
|
||||
logger.info("Revalidated library status for cached artist %s", (result.musicbrainz_id or "")[:8])
|
||||
return result
|
||||
|
||||
async def _get_library_artist_mbids(self) -> set[str]:
|
||||
@@ -223,10 +220,8 @@ class ArtistService:
|
||||
lidarr_artist = await self._lidarr_repo.get_artist_details(artist_id) if self._lidarr_repo.is_configured() else None
|
||||
in_library = lidarr_artist is not None and lidarr_artist.get("monitored", False)
|
||||
if in_library and lidarr_artist:
|
||||
logger.info(f"Using Lidarr as primary source for artist {artist_id[:8]}")
|
||||
artist_info = await self._build_artist_from_lidarr(artist_id, lidarr_artist, library_album_mbids)
|
||||
else:
|
||||
logger.info(f"Using MusicBrainz as primary source for artist {artist_id[:8]}")
|
||||
artist_info = await self._build_artist_from_musicbrainz(artist_id, library_artist_mbids, library_album_mbids)
|
||||
if lidarr_artist is not None:
|
||||
artist_info.in_lidarr = True
|
||||
@@ -327,7 +322,6 @@ class ArtistService:
|
||||
release_group_count = len(lidarr_albums)
|
||||
|
||||
if need_musicbrainz:
|
||||
logger.debug(f"Fetching supplementary data from MusicBrainz for artist {artist_id[:8]}")
|
||||
try:
|
||||
mb_artist = result_map.get("mb_artist")
|
||||
if isinstance(mb_artist, Exception):
|
||||
@@ -426,7 +420,6 @@ class ArtistService:
|
||||
future: asyncio.Future[ArtistInfo] = loop.create_future()
|
||||
self._artist_basic_in_flight[artist_id] = future
|
||||
try:
|
||||
logger.debug(f"Cache MISS (Disk): Artist {artist_id[:8]}... - fetching from API")
|
||||
artist_info = await self._build_artist_from_musicbrainz(artist_id, include_extended=False, include_releases=False)
|
||||
artist_info = await self._apply_audiodb_artist_images(
|
||||
artist_info, artist_id, artist_info.name, allow_fetch=False,
|
||||
@@ -481,9 +474,7 @@ class ArtistService:
|
||||
cache_key = f"{ARTIST_INFO_PREFIX}{artist_id}"
|
||||
cached_info = await self._cache.get(cache_key)
|
||||
if cached_info:
|
||||
logger.debug(f"Cache HIT (RAM): Artist {artist_id[:8]}...")
|
||||
return cached_info
|
||||
logger.debug(f"Cache MISS (RAM): Artist {artist_id[:8]}...")
|
||||
disk_data = await self._disk_cache.get_artist(artist_id)
|
||||
if disk_data:
|
||||
try:
|
||||
@@ -492,7 +483,6 @@ class ArtistService:
|
||||
logger.warning(f"Corrupt disk cache for artist {artist_id[:8]}, clearing: {e}")
|
||||
await self._disk_cache.delete_artist(artist_id)
|
||||
return None
|
||||
logger.debug(f"Cache HIT (Disk): Artist {artist_id[:8]}...")
|
||||
ttl = self._get_artist_ttl(artist_info.in_library)
|
||||
await self._cache.set(cache_key, artist_info, ttl_seconds=ttl)
|
||||
return artist_info
|
||||
@@ -518,7 +508,6 @@ class ArtistService:
|
||||
cache_key = f"{ARTIST_INFO_PREFIX}{artist_id}"
|
||||
cached_info = await self._cache.get(cache_key)
|
||||
if cached_info and cached_info.description is not None:
|
||||
logger.debug(f"Extended info cache HIT: Artist {artist_id[:8]}...")
|
||||
return ArtistExtendedInfo(description=cached_info.description, image=cached_info.image)
|
||||
mb_artist = await self._mb_repo.get_artist_by_id(artist_id)
|
||||
if not mb_artist:
|
||||
@@ -555,7 +544,6 @@ class ArtistService:
|
||||
included_secondary_types = set(t.lower() for t in prefs.secondary_types)
|
||||
|
||||
if in_library and offset == 0:
|
||||
logger.debug(f"Using Lidarr for artist releases {artist_id[:8]}")
|
||||
lidarr_albums = await self._lidarr_repo.get_artist_albums(artist_id)
|
||||
albums, singles, eps = self._categorize_lidarr_albums(lidarr_albums, album_mbids, requested_mbids=requested_mbids)
|
||||
|
||||
@@ -569,7 +557,6 @@ class ArtistService:
|
||||
has_more=False
|
||||
)
|
||||
|
||||
logger.debug(f"Using MusicBrainz for artist releases {artist_id[:8]}")
|
||||
release_groups, total_count = await self._mb_repo.get_artist_release_groups(
|
||||
artist_id, offset, limit
|
||||
)
|
||||
|
||||
@@ -102,15 +102,6 @@ class AudioDBBrowseQueue:
|
||||
)
|
||||
|
||||
processed += 1
|
||||
logger.debug(
|
||||
"audiodb.browse_queue action=processed entity_type=%s mbid=%s",
|
||||
item.entity_type, item.mbid[:8],
|
||||
)
|
||||
if processed % _BROWSE_QUEUE_LOG_INTERVAL == 0:
|
||||
logger.info(
|
||||
"audiodb.browse_queue processed=%d queue_depth=%d",
|
||||
processed, self._queue.qsize(),
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
"audiodb.browse_queue action=item_error entity_type=%s mbid=%s error=%s",
|
||||
@@ -124,4 +115,4 @@ class AudioDBBrowseQueue:
|
||||
|
||||
await asyncio.sleep(_BROWSE_QUEUE_INTER_ITEM_DELAY)
|
||||
except asyncio.CancelledError:
|
||||
logger.info("AudioDB browse queue consumer cancelled (processed=%d)", processed)
|
||||
pass
|
||||
|
||||
@@ -63,7 +63,6 @@ class AudioDBImageService:
|
||||
|
||||
raw = await self._disk_cache.get_audiodb_artist(mbid)
|
||||
if raw is None:
|
||||
logger.debug("audiodb.cache action=miss entity_type=artist mbid=%s lookup_source=mbid", mbid)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -73,10 +72,6 @@ class AudioDBImageService:
|
||||
await self._disk_cache.delete_entity("audiodb_artist", mbid)
|
||||
return None
|
||||
|
||||
logger.debug(
|
||||
"audiodb.cache action=hit entity_type=artist mbid=%s lookup_source=%s is_negative=%s",
|
||||
mbid, images.lookup_source, images.is_negative,
|
||||
)
|
||||
await self._mem_set("artist", mbid, images)
|
||||
return images
|
||||
|
||||
@@ -92,7 +87,6 @@ class AudioDBImageService:
|
||||
|
||||
raw = await self._disk_cache.get_audiodb_album(mbid)
|
||||
if raw is None:
|
||||
logger.debug("audiodb.cache action=miss entity_type=album mbid=%s lookup_source=mbid", mbid)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -102,10 +96,6 @@ class AudioDBImageService:
|
||||
await self._disk_cache.delete_entity("audiodb_album", mbid)
|
||||
return None
|
||||
|
||||
logger.debug(
|
||||
"audiodb.cache action=hit entity_type=album mbid=%s lookup_source=%s is_negative=%s",
|
||||
mbid, images.lookup_source, images.is_negative,
|
||||
)
|
||||
await self._mem_set("album", mbid, images)
|
||||
return images
|
||||
|
||||
@@ -151,10 +141,6 @@ class AudioDBImageService:
|
||||
mbid, images, is_monitored=is_monitored, ttl_seconds=ttl,
|
||||
)
|
||||
await self._mem_set("artist", mbid, images)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=artist mbid=%s lookup_source=mbid is_negative=false ttl=%d",
|
||||
mbid, ttl,
|
||||
)
|
||||
return images
|
||||
|
||||
negative = AudioDBArtistImages.negative(lookup_source="mbid")
|
||||
@@ -162,10 +148,6 @@ class AudioDBImageService:
|
||||
mbid, negative, is_monitored=False, ttl_seconds=ttl_not_found,
|
||||
)
|
||||
await self._mem_set("artist", mbid, negative)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=artist mbid=%s lookup_source=mbid is_negative=true ttl=%d",
|
||||
mbid, ttl_not_found,
|
||||
)
|
||||
else:
|
||||
negative = cached
|
||||
|
||||
@@ -183,10 +165,6 @@ class AudioDBImageService:
|
||||
mbid, images, is_monitored=is_monitored, ttl_seconds=ttl,
|
||||
)
|
||||
await self._mem_set("artist", mbid, images)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=artist mbid=%s is_negative=false lookup_source=name ttl=%d",
|
||||
mbid, ttl,
|
||||
)
|
||||
return images
|
||||
|
||||
negative_name = AudioDBArtistImages.negative(lookup_source="name")
|
||||
@@ -194,10 +172,6 @@ class AudioDBImageService:
|
||||
mbid, negative_name, is_monitored=False, ttl_seconds=ttl_not_found,
|
||||
)
|
||||
await self._mem_set("artist", mbid, negative_name)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=artist mbid=%s is_negative=true lookup_source=name ttl=%d",
|
||||
mbid, ttl_not_found,
|
||||
)
|
||||
return negative_name
|
||||
|
||||
return negative
|
||||
@@ -249,10 +223,6 @@ class AudioDBImageService:
|
||||
mbid, images, is_monitored=is_monitored, ttl_seconds=ttl,
|
||||
)
|
||||
await self._mem_set("album", mbid, images)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=album mbid=%s lookup_source=mbid is_negative=false ttl=%d",
|
||||
mbid, ttl,
|
||||
)
|
||||
return images
|
||||
|
||||
negative = AudioDBAlbumImages.negative(lookup_source="mbid")
|
||||
@@ -260,10 +230,6 @@ class AudioDBImageService:
|
||||
mbid, negative, is_monitored=False, ttl_seconds=ttl_not_found,
|
||||
)
|
||||
await self._mem_set("album", mbid, negative)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=album mbid=%s lookup_source=mbid is_negative=true ttl=%d",
|
||||
mbid, ttl_not_found,
|
||||
)
|
||||
else:
|
||||
negative = cached
|
||||
|
||||
@@ -292,10 +258,6 @@ class AudioDBImageService:
|
||||
mbid, images, is_monitored=is_monitored, ttl_seconds=ttl,
|
||||
)
|
||||
await self._mem_set("album", mbid, images)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=album mbid=%s is_negative=false lookup_source=name ttl=%d",
|
||||
mbid, ttl,
|
||||
)
|
||||
return images
|
||||
|
||||
negative_name = AudioDBAlbumImages.negative(lookup_source="name")
|
||||
@@ -303,10 +265,6 @@ class AudioDBImageService:
|
||||
mbid, negative_name, is_monitored=False, ttl_seconds=ttl_not_found,
|
||||
)
|
||||
await self._mem_set("album", mbid, negative_name)
|
||||
logger.debug(
|
||||
"audiodb.cache action=write entity_type=album mbid=%s is_negative=true lookup_source=name ttl=%d",
|
||||
mbid, ttl_not_found,
|
||||
)
|
||||
return negative_name
|
||||
|
||||
return negative
|
||||
|
||||
@@ -78,7 +78,6 @@ class CacheService:
|
||||
if result.returncode == 0:
|
||||
lines = result.stdout.strip()
|
||||
disk_count = len(lines.split('\n')) if lines else 0
|
||||
logger.debug(f"Disk cache stats calculated via subprocess: {disk_count} files, {disk_bytes} bytes")
|
||||
else:
|
||||
du_available = False
|
||||
except (subprocess.TimeoutExpired, subprocess.SubprocessError, ValueError) as e:
|
||||
@@ -138,8 +137,6 @@ class CacheService:
|
||||
|
||||
self._cached_stats = None
|
||||
|
||||
logger.info(f"Cleared {entries_before} memory cache entries")
|
||||
|
||||
return CacheClearResponse(
|
||||
success=True,
|
||||
message=f"Successfully cleared {entries_before} memory cache entries",
|
||||
@@ -168,8 +165,6 @@ class CacheService:
|
||||
if file_path.is_file():
|
||||
file_path.unlink()
|
||||
files_cleared += 1
|
||||
|
||||
logger.info(f"Cleared {metadata_count} metadata files and {files_cleared} cover image files from disk")
|
||||
|
||||
files_cleared += self._clear_genre_disk_cache()
|
||||
self._cached_stats = None
|
||||
@@ -209,8 +204,6 @@ class CacheService:
|
||||
disk_files += self._clear_genre_disk_cache()
|
||||
self._cached_stats = None
|
||||
|
||||
logger.info(f"Cleared all cache: {memory_entries} memory entries, {metadata_count} metadata files, {disk_files} cover files (library DB preserved)")
|
||||
|
||||
return CacheClearResponse(
|
||||
success=True,
|
||||
message=f"Successfully cleared {memory_entries} memory entries, {metadata_count} metadata files, and {disk_files} cover files (library database preserved)",
|
||||
@@ -238,8 +231,6 @@ class CacheService:
|
||||
|
||||
self._cached_stats = None
|
||||
|
||||
logger.info(f"Cleared {files_cleared} cover image files from disk")
|
||||
|
||||
return CacheClearResponse(
|
||||
success=True,
|
||||
message=f"Successfully cleared {files_cleared} cover images",
|
||||
@@ -265,8 +256,6 @@ class CacheService:
|
||||
|
||||
self._cached_stats = None
|
||||
|
||||
logger.info(f"Cleared library cache: {artists_before} artists, {albums_before} albums")
|
||||
|
||||
return CacheClearResponse(
|
||||
success=True,
|
||||
message=f"Successfully cleared library database: {artists_before} artists, {albums_before} albums",
|
||||
@@ -294,8 +283,6 @@ class CacheService:
|
||||
|
||||
self._cached_stats = None
|
||||
|
||||
logger.info(f"Cleared AudioDB cache: {count_before} disk entries, {memory_cleared} memory entries")
|
||||
|
||||
return CacheClearResponse(
|
||||
success=True,
|
||||
message=f"Successfully cleared {count_before} AudioDB cache entries and {memory_cleared} memory entries",
|
||||
|
||||
@@ -139,7 +139,6 @@ class CacheStatusService:
|
||||
total_albums=total_albums,
|
||||
processed_albums=0
|
||||
)
|
||||
logger.info(f"Cache sync started: {phase} ({total_items} items)")
|
||||
|
||||
if self._sync_state_store:
|
||||
try:
|
||||
@@ -220,7 +219,6 @@ class CacheStatusService:
|
||||
self._progress.processed_items = 0
|
||||
self._progress.current_item = None
|
||||
await self.broadcast_progress()
|
||||
logger.info(f"Phase skipped (already cached): {phase}")
|
||||
await asyncio.sleep(0.5)
|
||||
|
||||
def get_last_progress_at(self) -> float:
|
||||
@@ -270,7 +268,6 @@ class CacheStatusService:
|
||||
return
|
||||
is_success = error_message is None
|
||||
status = 'completed' if is_success else 'failed'
|
||||
logger.info(f"Cache sync {status}: {self._progress.phase}")
|
||||
|
||||
if self._sync_state_store:
|
||||
try:
|
||||
@@ -375,9 +372,6 @@ class CacheStatusService:
|
||||
try:
|
||||
state = await self._sync_state_store.get_sync_state()
|
||||
if state and state.get('status') == 'running':
|
||||
logger.info(f"Found interrupted sync: phase={state.get('phase')}, "
|
||||
f"artists={state.get('processed_artists')}/{state.get('total_artists')}, "
|
||||
f"albums={state.get('processed_albums')}/{state.get('total_albums')}")
|
||||
|
||||
phase = state.get('phase')
|
||||
if phase == 'albums':
|
||||
|
||||
@@ -134,7 +134,6 @@ class DiscoverHomepageService:
|
||||
if self._memory_cache and self._has_meaningful_content(response):
|
||||
cache_key = self._integration.get_discover_cache_key(resolved)
|
||||
await self._memory_cache.set(cache_key, response, DISCOVER_CACHE_TTL)
|
||||
logger.info("Discover data built and cached for source=%s", resolved)
|
||||
elif not self._has_meaningful_content(response):
|
||||
logger.warning("Discover build produced no meaningful content, keeping existing cache")
|
||||
except Exception as e: # noqa: BLE001
|
||||
@@ -220,11 +219,6 @@ class DiscoverHomepageService:
|
||||
|
||||
results = await self._execute_tasks(tasks)
|
||||
|
||||
logger.info(
|
||||
"Discover data fetch results: %s",
|
||||
{k: "ok" if v is not None else "empty" for k, v in results.items()},
|
||||
)
|
||||
|
||||
response = DiscoverResponse(
|
||||
integration_status=self._integration.get_integration_status(),
|
||||
)
|
||||
@@ -236,7 +230,6 @@ class DiscoverHomepageService:
|
||||
resolved_source=resolved_source,
|
||||
)
|
||||
await self._enrich_because_sections_audiodb(response.because_you_listen_to)
|
||||
logger.info("because_you_listen_to: %d sections", len(response.because_you_listen_to))
|
||||
|
||||
response.fresh_releases = self._build_fresh_releases(results, library_mbids)
|
||||
|
||||
@@ -313,22 +306,6 @@ class DiscoverHomepageService:
|
||||
|
||||
response.service_prompts = self._build_service_prompts()
|
||||
|
||||
sections_status = {
|
||||
"because": len(response.because_you_listen_to),
|
||||
"fresh_releases": response.fresh_releases is not None,
|
||||
"missing_essentials": response.missing_essentials is not None,
|
||||
"rediscover": response.rediscover is not None,
|
||||
"artists_you_might_like": response.artists_you_might_like is not None,
|
||||
"popular_in_genres": response.popular_in_your_genres is not None,
|
||||
"genre_list": response.genre_list is not None,
|
||||
"globally_trending": response.globally_trending is not None,
|
||||
"weekly_exploration": response.weekly_exploration is not None,
|
||||
"lastfm_weekly_artist_chart": getattr(response, "lastfm_weekly_artist_chart", None) is not None,
|
||||
"lastfm_weekly_album_chart": getattr(response, "lastfm_weekly_album_chart", None) is not None,
|
||||
"lastfm_recent_scrobbles": getattr(response, "lastfm_recent_scrobbles", None) is not None,
|
||||
}
|
||||
logger.info("Discover build complete (source=%s): %s", resolved_source, sections_status)
|
||||
|
||||
return response
|
||||
|
||||
async def _get_seed_artists(
|
||||
@@ -406,11 +383,6 @@ class DiscoverHomepageService:
|
||||
logger.warning(f"Failed to get Jellyfin seed artists: {e}")
|
||||
continue
|
||||
|
||||
logger.info(
|
||||
"Seed artists found: %d — %s",
|
||||
len(seeds),
|
||||
[(s.artist_name, s.artist_mbids[0][:8] if s.artist_mbids else "?") for s in seeds],
|
||||
)
|
||||
return seeds
|
||||
|
||||
async def _enrich_because_sections_audiodb(
|
||||
@@ -1053,7 +1025,7 @@ class DiscoverHomepageService:
|
||||
service="listenbrainz",
|
||||
title="Connect ListenBrainz",
|
||||
description="Get recommendations from your listening history, find similar artists, and keep an eye on your top genres. Connect Last.fm too if you want global listener stats.",
|
||||
icon="🎵",
|
||||
icon="LB",
|
||||
color="primary",
|
||||
features=["Personalized recommendations", "Similar artists", "Listening stats", "Genre insights"],
|
||||
))
|
||||
@@ -1062,7 +1034,7 @@ class DiscoverHomepageService:
|
||||
service="jellyfin",
|
||||
title="Connect Jellyfin",
|
||||
description="Use your play history to surface favorites and sharpen recommendations.",
|
||||
icon="📺",
|
||||
icon="JF",
|
||||
color="secondary",
|
||||
features=["Rediscover favorites", "Play statistics", "Listening history", "Better recommendations"],
|
||||
))
|
||||
@@ -1071,7 +1043,7 @@ class DiscoverHomepageService:
|
||||
service="lidarr-connection",
|
||||
title="Connect Lidarr",
|
||||
description="Spot gaps in your collection and keep your library in sync.",
|
||||
icon="🎶",
|
||||
icon="LD",
|
||||
color="accent",
|
||||
features=["Missing essentials", "Library management", "Album requests", "Collection tracking"],
|
||||
))
|
||||
@@ -1080,7 +1052,7 @@ class DiscoverHomepageService:
|
||||
service="lastfm",
|
||||
title="Connect Last.fm",
|
||||
description="Track your listening, compare stats, and discover music that matches your taste.",
|
||||
icon="🎸",
|
||||
icon="FM",
|
||||
color="primary",
|
||||
features=["Scrobbling", "Global listener stats", "Artist recommendations", "Play history"],
|
||||
))
|
||||
|
||||
@@ -52,7 +52,6 @@ class DiscoverQueueService:
|
||||
if count is None:
|
||||
count = qs.queue_size
|
||||
resolved_source = self._integration.resolve_source(source)
|
||||
logger.info("Building discover queue: requested_source=%s, resolved_source=%s", source, resolved_source)
|
||||
lb_enabled = self._integration.is_listenbrainz_enabled()
|
||||
jf_enabled = self._integration.is_jellyfin_enabled()
|
||||
lidarr_configured = self._integration.is_lidarr_configured()
|
||||
@@ -168,11 +167,6 @@ class DiscoverQueueService:
|
||||
logger.warning(f"Failed to get Jellyfin seed artists: {e}")
|
||||
continue
|
||||
|
||||
logger.info(
|
||||
"Seed artists found: %d — %s",
|
||||
len(seeds),
|
||||
[(s.artist_name, s.artist_mbids[0][:8] if s.artist_mbids else "?") for s in seeds],
|
||||
)
|
||||
return seeds
|
||||
|
||||
async def validate_queue_mbids(self, mbids: list[str]) -> list[str]:
|
||||
@@ -608,8 +602,6 @@ class DiscoverQueueService:
|
||||
similar_seed_pools = strategy_results[0]
|
||||
if isinstance(similar_seed_pools, list):
|
||||
candidate_pools.extend(similar_seed_pools)
|
||||
pool_counts = [len(p) for p in similar_seed_pools]
|
||||
logger.info("Strategy similar_seeds: %d pools, items per pool: %s", len(similar_seed_pools), pool_counts)
|
||||
elif isinstance(similar_seed_pools, Exception):
|
||||
logger.warning("Strategy similar_seeds FAILED: %s", similar_seed_pools)
|
||||
|
||||
@@ -620,15 +612,8 @@ class DiscoverQueueService:
|
||||
continue
|
||||
if strategy_result:
|
||||
candidate_pools.append(strategy_result)
|
||||
logger.info("Strategy %s: %d items", name, len(strategy_result))
|
||||
else:
|
||||
logger.info("Strategy %s: 0 items", name)
|
||||
|
||||
personalized = self._round_robin_select(candidate_pools, personalized_target)
|
||||
logger.info(
|
||||
"Personalized queue: %d items from %d pools (target=%d, wildcard_slots=%d)",
|
||||
len(personalized), len(candidate_pools), personalized_target, wildcard_slots,
|
||||
)
|
||||
seen_mbids = {item.release_group_mbid.lower() for item in personalized}
|
||||
|
||||
wildcard_count = max(wildcard_slots, count - len(personalized))
|
||||
|
||||
@@ -174,17 +174,10 @@ class DiscoverQueueManager:
|
||||
async def _do_build(self, source: str) -> None:
|
||||
state = self._get_state(source)
|
||||
try:
|
||||
logger.info("Background queue build started (source=%s)", source)
|
||||
queue = await self.build_hydrated_queue(source)
|
||||
state.queue = queue
|
||||
state.built_at = time.time()
|
||||
state.status = QueueBuildStatus.READY
|
||||
logger.info(
|
||||
"Background queue build complete (source=%s, items=%d, queue_id=%s)",
|
||||
source,
|
||||
len(queue.items),
|
||||
queue.queue_id,
|
||||
)
|
||||
task = asyncio.create_task(self._prewarm_covers(queue, source))
|
||||
from core.task_registry import TaskRegistry
|
||||
try:
|
||||
@@ -192,7 +185,6 @@ class DiscoverQueueManager:
|
||||
except RuntimeError:
|
||||
pass
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Background queue build cancelled (source=%s)", source)
|
||||
if state.status == QueueBuildStatus.BUILDING:
|
||||
state.status = QueueBuildStatus.IDLE
|
||||
raise
|
||||
@@ -229,20 +221,12 @@ class DiscoverQueueManager:
|
||||
return False
|
||||
|
||||
results = await asyncio.gather(*(warm_one(m) for m in mbids), return_exceptions=True)
|
||||
warmed = sum(1 for r in results if r is True)
|
||||
logger.info(
|
||||
"Pre-warmed %d/%d discover queue covers (source=%s)",
|
||||
warmed,
|
||||
len(mbids),
|
||||
source,
|
||||
)
|
||||
|
||||
async def consume_queue(self, source: str) -> DiscoverQueueResponse | None:
|
||||
state = self._get_state(source)
|
||||
if state.status != QueueBuildStatus.READY or state.queue is None:
|
||||
return None
|
||||
if self._is_stale(state):
|
||||
logger.info("Discarding stale pre-built queue (source=%s)", source)
|
||||
state.queue = None
|
||||
state.status = QueueBuildStatus.IDLE
|
||||
state.built_at = 0.0
|
||||
|
||||
@@ -59,7 +59,6 @@ class GenreCoverPrewarmService:
|
||||
t.cancel()
|
||||
await asyncio.gather(*tasks, return_exceptions=True)
|
||||
self._active_genres.clear()
|
||||
logger.info("GenreCoverPrewarmService shutdown complete (%d tasks cancelled)", len(tasks))
|
||||
|
||||
async def _prewarm(
|
||||
self,
|
||||
@@ -96,6 +95,5 @@ class GenreCoverPrewarmService:
|
||||
if i < len(all_album) - 1:
|
||||
await asyncio.sleep(_PREWARM_INTER_ITEM_DELAY)
|
||||
|
||||
logger.info("Pre-warmed %d/%d genre covers for '%s'", warmed, total, genre_name)
|
||||
except Exception as exc: # noqa: BLE001
|
||||
logger.error("Genre cover pre-warm failed for '%s': %s", genre_name, exc)
|
||||
|
||||
@@ -285,7 +285,6 @@ class HomeService:
|
||||
items=preview_items,
|
||||
)
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.debug(f"Could not build discover preview: {e}")
|
||||
return None
|
||||
|
||||
async def _resolve_release_mbids(self, release_ids: list[str]) -> dict[str, str]:
|
||||
|
||||
@@ -73,7 +73,7 @@ class GenreService:
|
||||
await self._memory_cache.set(cache_key, result, remaining)
|
||||
return result
|
||||
except Exception: # noqa: BLE001
|
||||
logger.debug("Failed to read genre section from disk for %s", source_key)
|
||||
pass
|
||||
|
||||
return None
|
||||
|
||||
@@ -109,19 +109,12 @@ class GenreService:
|
||||
self._genre_build_locks[source_key] = asyncio.Lock()
|
||||
lock = self._genre_build_locks[source_key]
|
||||
if lock.locked():
|
||||
logger.debug("Genre section build already in progress for source=%s, skipping", source_key)
|
||||
return
|
||||
async with lock:
|
||||
try:
|
||||
logger.debug(
|
||||
"Building genre section for source=%s (%d genres)",
|
||||
source_key,
|
||||
len(genre_names),
|
||||
)
|
||||
genre_artists = await self.get_genre_artists_batch(genre_names)
|
||||
genre_artist_images = await self.resolve_genre_artist_images(genre_artists)
|
||||
await self.save_genre_section(source_key, genre_artists, genre_artist_images)
|
||||
logger.debug("Genre section build complete for source=%s", source_key)
|
||||
except Exception as exc: # noqa: BLE001
|
||||
logger.error("Genre section build failed for source=%s: %s", source_key, exc)
|
||||
|
||||
@@ -185,8 +178,6 @@ class GenreService:
|
||||
for f in self._genre_section_dir.glob("*.json"):
|
||||
f.unlink(missing_ok=True)
|
||||
count += 1
|
||||
if count:
|
||||
logger.info("Cleared %d genre section files from disk", count)
|
||||
return count
|
||||
|
||||
async def resolve_genre_artist_images(
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
import time
|
||||
|
||||
import msgspec
|
||||
@@ -6,8 +5,6 @@ import msgspec
|
||||
from core.exceptions import ConfigurationError
|
||||
from repositories.protocols import LastFmRepositoryProtocol
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
MAX_PENDING_TOKENS = 5
|
||||
TOKEN_TTL_SECONDS = 600
|
||||
|
||||
|
||||
@@ -105,7 +105,6 @@ class LibraryService:
|
||||
albums_data = await self._library_db.get_albums()
|
||||
|
||||
if not albums_data:
|
||||
logger.info("Library cache is empty, syncing from Lidarr")
|
||||
await self.sync_library()
|
||||
albums_data = await self._library_db.get_albums()
|
||||
|
||||
@@ -174,7 +173,6 @@ class LibraryService:
|
||||
artists_data = await self._library_db.get_artists(limit=limit)
|
||||
|
||||
if not artists_data:
|
||||
logger.info("Artists cache is empty, syncing from Lidarr")
|
||||
await self.sync_library()
|
||||
artists_data = await self._library_db.get_artists(limit=limit)
|
||||
|
||||
@@ -207,7 +205,6 @@ class LibraryService:
|
||||
)
|
||||
|
||||
if not albums_data and offset == 0 and not search:
|
||||
logger.info("Library cache is empty, syncing from Lidarr")
|
||||
await self.sync_library()
|
||||
albums_data, total = await self._library_db.get_albums_paginated(
|
||||
limit=limit, offset=offset, sort_by=sort_by, sort_order=sort_order, search=search,
|
||||
@@ -248,7 +245,6 @@ class LibraryService:
|
||||
)
|
||||
|
||||
if not artists_data and offset == 0 and not search:
|
||||
logger.info("Artists cache is empty, syncing from Lidarr")
|
||||
await self.sync_library()
|
||||
artists_data, total = await self._library_db.get_artists_paginated(
|
||||
limit=limit, offset=offset, sort_by=sort_by, sort_order=sort_order, search=search,
|
||||
@@ -279,7 +275,6 @@ class LibraryService:
|
||||
albums = []
|
||||
|
||||
if not albums:
|
||||
logger.info("No recent imports from history, falling back to cache")
|
||||
albums_data = await self._library_db.get_recently_added(limit=limit)
|
||||
|
||||
albums = [
|
||||
@@ -320,7 +315,6 @@ class LibraryService:
|
||||
time_since_last_sync = current_time - self._last_sync_time
|
||||
if time_since_last_sync < self._global_sync_cooldown:
|
||||
remaining = int(self._global_sync_cooldown - time_since_last_sync)
|
||||
logger.info(f"Global sync cooldown active ({remaining}s remaining). Skipping sync.")
|
||||
raise ExternalServiceError(
|
||||
f"Sync cooldown active. Please wait {remaining} seconds before syncing again."
|
||||
)
|
||||
@@ -339,7 +333,6 @@ class LibraryService:
|
||||
await status_service.cancel_current_sync()
|
||||
await status_service.wait_for_completion()
|
||||
else:
|
||||
logger.info("Library sync already in progress - skipping auto-sync")
|
||||
return SyncLibraryResponse(status="skipped", artists=0, albums=0)
|
||||
|
||||
if self._sync_future is not None and not self._sync_future.done():
|
||||
@@ -355,8 +348,6 @@ class LibraryService:
|
||||
|
||||
sync_succeeded = False
|
||||
try:
|
||||
logger.info("Starting library sync from Lidarr")
|
||||
|
||||
albums = await self._lidarr_repo.get_library()
|
||||
artists = await self._lidarr_repo.get_artists_from_library()
|
||||
|
||||
@@ -378,7 +369,6 @@ class LibraryService:
|
||||
]
|
||||
|
||||
await self._library_db.save_library(artists, albums_data)
|
||||
logger.info("Library cache updated - unmonitored items removed")
|
||||
|
||||
now = time.time()
|
||||
self._last_sync_time = now
|
||||
@@ -398,7 +388,6 @@ class LibraryService:
|
||||
last_state = await self._sync_state_store.get_sync_state()
|
||||
if last_state and last_state.get('status') == 'failed':
|
||||
resume = True
|
||||
logger.info("Previous sync failed, resuming from checkpoint")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning("Failed to check sync state for resume: %s", e)
|
||||
|
||||
@@ -406,7 +395,6 @@ class LibraryService:
|
||||
try:
|
||||
await self._sync_state_store.clear_processed_items()
|
||||
await self._sync_state_store.clear_sync_state()
|
||||
logger.info("Force full sync: cleared previous progress")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning("Failed to clear sync state for force_full: %s", e)
|
||||
|
||||
@@ -421,7 +409,6 @@ class LibraryService:
|
||||
else:
|
||||
task_success = not t.cancelled()
|
||||
except asyncio.CancelledError:
|
||||
logger.info("Precache task was cancelled")
|
||||
task_success = False
|
||||
finally:
|
||||
status_service.set_current_task(None)
|
||||
@@ -438,8 +425,6 @@ class LibraryService:
|
||||
task.add_done_callback(on_task_done)
|
||||
status_service.set_current_task(task)
|
||||
|
||||
logger.info(f"Library sync complete: {len(artists)} artists, {len(albums)} albums")
|
||||
|
||||
self._update_last_sync_timestamp()
|
||||
sync_started_at = self._preferences_service.get_lidarr_settings().last_sync or 0
|
||||
|
||||
@@ -489,7 +474,6 @@ class LibraryService:
|
||||
async def clear_cache(self) -> None:
|
||||
try:
|
||||
await self._library_db.clear()
|
||||
logger.info("Library cache cleared")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to clear library cache: {e}")
|
||||
raise ExternalServiceError(f"Failed to clear library cache: {e}")
|
||||
@@ -557,7 +541,6 @@ class LibraryService:
|
||||
artist_details["id"], delete_files=delete_files
|
||||
)
|
||||
artist_removed = True
|
||||
logger.info(f"Auto-removed artist '{artist_name}' (no remaining albums)")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(
|
||||
f"Album '{album_mbid}' removed but artist cleanup failed for '{artist_mbid}': {e}"
|
||||
@@ -628,7 +611,7 @@ class LibraryService:
|
||||
) -> dict[str, tuple[str, str, str | None, float | None]]:
|
||||
"""Resolve album MBID to {disc:track: (source, source_id, format, duration)}.
|
||||
|
||||
Priority: local → navidrome → jellyfin.
|
||||
Priority: local -> navidrome -> jellyfin.
|
||||
Uses source_resolution cache (1h TTL).
|
||||
"""
|
||||
if self._memory_cache is None:
|
||||
|
||||
@@ -100,19 +100,18 @@ class LocalFilesService:
|
||||
try:
|
||||
data = await self._lidarr.get_all_albums()
|
||||
except (ExternalServiceError, CircuitOpenError, ConnectionError, OSError):
|
||||
# Stale-while-error: serve last-known data if Lidarr is down
|
||||
# Serve the last cached data if Lidarr is unavailable.
|
||||
try:
|
||||
stale = await self._cache.get(f"{cache_key}:stale")
|
||||
except Exception: # noqa: BLE001
|
||||
stale = None
|
||||
if stale is not None:
|
||||
logger.warning("Lidarr unavailable — serving stale local album data")
|
||||
return stale
|
||||
raise
|
||||
result = data or []
|
||||
if result:
|
||||
await self._cache.set(cache_key, result, ttl_seconds=self._ALBUM_LIST_TTL)
|
||||
# Keep a long-lived stale copy for fallback (24h)
|
||||
# Keep a longer-lived fallback copy for 24 hours.
|
||||
await self._cache.set(f"{cache_key}:stale", result, ttl_seconds=86400)
|
||||
return result
|
||||
|
||||
@@ -636,6 +635,6 @@ class LocalFilesService:
|
||||
|
||||
return LocalFilesVerifyResponse(
|
||||
success=True,
|
||||
message=f"Connected — {track_count:,} audio files found",
|
||||
message=f"Connected, found {track_count:,} audio files",
|
||||
track_count=track_count,
|
||||
)
|
||||
|
||||
@@ -106,7 +106,6 @@ class NavidromeLibraryService:
|
||||
del self._album_mbid_cache[key]
|
||||
if stale_keys:
|
||||
self._dirty = True
|
||||
logger.debug("navidrome.cache action=invalidate mbid=%s cleared_keys=%d", album_mbid[:8], len(stale_keys))
|
||||
|
||||
async def _resolve_album_mbid(self, name: str, artist: str) -> str | None:
|
||||
"""Resolve a release-group MBID for an album via Lidarr library matching."""
|
||||
@@ -180,7 +179,6 @@ class NavidromeLibraryService:
|
||||
await self._mbid_store.save_navidrome_album_mbid_index(serializable_albums)
|
||||
await self._mbid_store.save_navidrome_artist_mbid_index(serializable_artists)
|
||||
self._dirty = False
|
||||
logger.debug("Persisted dirty Navidrome MBID cache to disk")
|
||||
except Exception: # noqa: BLE001
|
||||
logger.warning("Failed to persist dirty Navidrome MBID cache", exc_info=True)
|
||||
|
||||
@@ -763,10 +761,6 @@ class NavidromeLibraryService:
|
||||
norm_artist = _normalize(artist_name)
|
||||
if norm_artist and artist_mbid:
|
||||
self._lidarr_artist_index[norm_artist] = artist_mbid
|
||||
logger.info(
|
||||
"Built Lidarr matching indices: %d album entries, %d artist entries",
|
||||
len(self._lidarr_album_index), len(self._lidarr_artist_index),
|
||||
)
|
||||
except Exception: # noqa: BLE001
|
||||
logger.warning("Failed to build Lidarr matching indices", exc_info=True)
|
||||
|
||||
@@ -779,10 +773,6 @@ class NavidromeLibraryService:
|
||||
self._album_mbid_cache.update(disk_albums)
|
||||
self._artist_mbid_cache.update(disk_artists)
|
||||
loaded_from_disk = True
|
||||
logger.info(
|
||||
"Loaded Navidrome MBID cache from disk: %d albums, %d artists",
|
||||
len(disk_albums), len(disk_artists),
|
||||
)
|
||||
except Exception: # noqa: BLE001
|
||||
logger.warning("Failed to load Navidrome MBID cache from disk", exc_info=True)
|
||||
|
||||
@@ -821,11 +811,6 @@ class NavidromeLibraryService:
|
||||
del self._album_mbid_cache[key]
|
||||
for key in stale_artist_keys:
|
||||
del self._artist_mbid_cache[key]
|
||||
if stale_album_keys or stale_artist_keys:
|
||||
logger.info(
|
||||
"Removed %d stale album and %d stale artist MBID entries",
|
||||
len(stale_album_keys), len(stale_artist_keys),
|
||||
)
|
||||
|
||||
resolved_albums = 0
|
||||
resolved_artists = 0
|
||||
@@ -881,11 +866,6 @@ class NavidromeLibraryService:
|
||||
if mbid:
|
||||
resolved_artists += 1
|
||||
|
||||
logger.info(
|
||||
"Navidrome MBID enrichment complete: %d new albums resolved, %d new artists resolved (loaded_from_disk=%s, lidarr_available=%s)",
|
||||
resolved_albums, resolved_artists, loaded_from_disk, bool(self._lidarr_album_index),
|
||||
)
|
||||
|
||||
if self._mbid_store and (self._dirty or stale_album_keys or stale_artist_keys):
|
||||
try:
|
||||
serializable_albums = {k: (v if isinstance(v, str) else None) for k, v in self._album_mbid_cache.items()}
|
||||
@@ -893,10 +873,6 @@ class NavidromeLibraryService:
|
||||
await self._mbid_store.save_navidrome_album_mbid_index(serializable_albums)
|
||||
await self._mbid_store.save_navidrome_artist_mbid_index(serializable_artists)
|
||||
self._dirty = False
|
||||
logger.info(
|
||||
"Persisted Navidrome MBID cache to disk: %d albums, %d artists",
|
||||
len(self._album_mbid_cache), len(self._artist_mbid_cache),
|
||||
)
|
||||
except Exception: # noqa: BLE001
|
||||
logger.warning("Failed to persist Navidrome MBID cache to disk", exc_info=True)
|
||||
|
||||
|
||||
@@ -88,7 +88,6 @@ class PlaylistService:
|
||||
if len(stripped) > MAX_NAME_LENGTH:
|
||||
raise InvalidPlaylistDataError(f"Playlist name must not exceed {MAX_NAME_LENGTH} characters")
|
||||
result = await self._repo.create_playlist(stripped, source_ref=source_ref)
|
||||
logger.info("Playlist created: id=%s name=%s source_ref=%s", result.id, result.name, source_ref)
|
||||
return result
|
||||
|
||||
async def get_by_source_ref(self, source_ref: str) -> PlaylistRecord | None:
|
||||
@@ -127,7 +126,6 @@ class PlaylistService:
|
||||
result = await self._repo.update_playlist(playlist_id, name=name)
|
||||
if result is None:
|
||||
raise PlaylistNotFoundError(f"Playlist {playlist_id} not found")
|
||||
logger.info("Playlist updated: id=%s", playlist_id)
|
||||
return result
|
||||
|
||||
async def update_playlist_with_detail(
|
||||
@@ -142,7 +140,6 @@ class PlaylistService:
|
||||
if not deleted:
|
||||
raise PlaylistNotFoundError(f"Playlist {playlist_id} not found")
|
||||
await asyncio.to_thread(self._delete_cover_file, playlist_id)
|
||||
logger.info("Playlist deleted: id=%s", playlist_id)
|
||||
|
||||
|
||||
async def add_tracks(
|
||||
@@ -177,14 +174,12 @@ class PlaylistService:
|
||||
normalized_tracks.append(normalized)
|
||||
await self.get_playlist(playlist_id)
|
||||
result = await self._repo.add_tracks(playlist_id, normalized_tracks, position)
|
||||
logger.info("Added %d tracks to playlist %s", len(result), playlist_id)
|
||||
return result
|
||||
|
||||
async def remove_track(self, playlist_id: str, track_id: str) -> None:
|
||||
removed = await self._repo.remove_track(playlist_id, track_id)
|
||||
if not removed:
|
||||
raise PlaylistNotFoundError(f"Track {track_id} not found in playlist {playlist_id}")
|
||||
logger.info("Removed track %s from playlist %s", track_id, playlist_id)
|
||||
|
||||
async def remove_tracks(self, playlist_id: str, track_ids: list[str]) -> int:
|
||||
if not track_ids:
|
||||
@@ -192,7 +187,6 @@ class PlaylistService:
|
||||
removed = await self._repo.remove_tracks(playlist_id, track_ids)
|
||||
if not removed:
|
||||
raise PlaylistNotFoundError(f"No matching tracks found in playlist {playlist_id}")
|
||||
logger.info("Removed %d tracks from playlist %s", removed, playlist_id)
|
||||
return removed
|
||||
|
||||
async def reorder_track(
|
||||
@@ -203,7 +197,6 @@ class PlaylistService:
|
||||
result = await self._repo.reorder_track(playlist_id, track_id, new_position)
|
||||
if result is None:
|
||||
raise PlaylistNotFoundError(f"Track {track_id} not found in playlist {playlist_id}")
|
||||
logger.info("Reordered track %s to position %d in playlist %s", track_id, result, playlist_id)
|
||||
return result
|
||||
|
||||
async def update_track_source(
|
||||
@@ -259,7 +252,6 @@ class PlaylistService:
|
||||
)
|
||||
if result is None:
|
||||
raise PlaylistNotFoundError(f"Track {track_id} not found in playlist {playlist_id}")
|
||||
logger.info("Updated track source: track=%s playlist=%s", track_id, playlist_id)
|
||||
return result
|
||||
|
||||
async def get_tracks(self, playlist_id: str) -> list[PlaylistTrackRecord]:
|
||||
|
||||
@@ -36,7 +36,6 @@ class AlbumPhase:
|
||||
generation: int = 0,
|
||||
) -> None:
|
||||
from core.dependencies import get_album_service
|
||||
logger.info(f"Pre-caching {len(release_group_ids)} new/missing release-groups")
|
||||
album_service = get_album_service()
|
||||
|
||||
async def cache_rg(rgid: str, index: int) -> tuple[str, bool, bool]:
|
||||
@@ -77,7 +76,6 @@ class AlbumPhase:
|
||||
i = 0
|
||||
while i < len(release_group_ids):
|
||||
if status_service.is_cancelled():
|
||||
logger.info("Album pre-caching cancelled by user")
|
||||
break
|
||||
batch_start = time.time()
|
||||
batch = release_group_ids[i:i + batch_size]
|
||||
@@ -117,10 +115,6 @@ class AlbumPhase:
|
||||
batch_size = min(batch_size + 1, max_batch)
|
||||
logger.debug(f"Increasing batch size to {batch_size} (fast: {avg_time_per_item:.2f}s/item)")
|
||||
next_i = i + len(batch)
|
||||
if next_i % 30 == 0 or next_i >= len(release_group_ids):
|
||||
percent = int((min(next_i, len(release_group_ids)) / len(release_group_ids)) * 100)
|
||||
logger.info(f"Album progress: {min(next_i, len(release_group_ids))}/{len(release_group_ids)} ({percent}%) - metadata: {metadata_fetched}, covers: {covers_fetched} [batch: {batch_size}]")
|
||||
i = next_i
|
||||
await asyncio.sleep(advanced_settings.delay_albums)
|
||||
await status_service.persist_progress(force=True, generation=generation)
|
||||
logger.info(f"Album pre-caching complete: metadata fetched={metadata_fetched}, covers fetched={covers_fetched}, total processed={len(release_group_ids)}")
|
||||
|
||||
@@ -38,7 +38,6 @@ class ArtistPhase:
|
||||
offset: int = 0,
|
||||
generation: int = 0,
|
||||
) -> None:
|
||||
logger.info(f"Pre-caching metadata+images for {len(artists)} artists")
|
||||
from core.dependencies import get_artist_service
|
||||
from infrastructure.validators import is_unknown_mbid
|
||||
artist_service = get_artist_service()
|
||||
@@ -52,8 +51,6 @@ class ArtistPhase:
|
||||
elif mbid.lower() not in seen_mbids:
|
||||
seen_mbids.add(mbid.lower())
|
||||
unique_artists.append(a)
|
||||
if len(unique_artists) < len(artists):
|
||||
logger.info("Deduplicated %d artists to %d unique", len(artists), len(unique_artists))
|
||||
artists = unique_artists
|
||||
|
||||
async def cache_artist(artist: dict, index: int) -> str:
|
||||
@@ -96,7 +93,6 @@ class ArtistPhase:
|
||||
batch_size = advanced_settings.batch_artist_images
|
||||
for i in range(0, len(artists), batch_size):
|
||||
if status_service.is_cancelled():
|
||||
logger.info("Artist pre-caching cancelled by user")
|
||||
break
|
||||
batch = artists[i:i + batch_size]
|
||||
tasks = [cache_artist(artist, i + idx) for idx, artist in enumerate(batch)]
|
||||
@@ -114,14 +110,12 @@ class ArtistPhase:
|
||||
await status_service.persist_progress(generation=generation)
|
||||
await asyncio.sleep(advanced_settings.delay_artist)
|
||||
await status_service.persist_progress(force=True, generation=generation)
|
||||
logger.info("Artist metadata+image pre-caching complete")
|
||||
await self._cache_artist_genres(artists)
|
||||
|
||||
async def _cache_artist_genres(self, artists: list[dict]) -> None:
|
||||
from core.dependencies import get_artist_service
|
||||
artist_service = get_artist_service()
|
||||
artist_genres: dict[str, list[str]] = {}
|
||||
logger.info(f"Extracting genre tags for {len(artists)} library artists")
|
||||
for artist in artists:
|
||||
mbid = artist.get('mbid')
|
||||
if not mbid:
|
||||
@@ -132,6 +126,3 @@ class ArtistPhase:
|
||||
artist_genres[mbid] = cached_info.tags[:10]
|
||||
if artist_genres:
|
||||
await self._genre_index.save_artist_genres(artist_genres)
|
||||
logger.info(f"Cached genres for {len(artist_genres)} artists")
|
||||
else:
|
||||
logger.info("No artist genres found to cache")
|
||||
|
||||
@@ -187,7 +187,6 @@ class AudioDBPhase:
|
||||
|
||||
settings = self._preferences_service.get_advanced_settings()
|
||||
if not settings.audiodb_enabled:
|
||||
logger.info("AudioDB pre-warming skipped (audiodb_enabled=false)")
|
||||
await status_service.skip_phase('audiodb_prewarm', generation=generation)
|
||||
return
|
||||
|
||||
@@ -197,16 +196,11 @@ class AudioDBPhase:
|
||||
needed_artists, needed_albums = await self.check_cache_needs(artists, albums)
|
||||
total = len(needed_artists) + len(needed_albums)
|
||||
if total == 0:
|
||||
logger.info("AudioDB prewarm: all items already cached")
|
||||
await status_service.skip_phase('audiodb_prewarm', generation=generation)
|
||||
return
|
||||
|
||||
original_total = len(artists) + len(albums)
|
||||
initial_hit_rate = ((original_total - total) / original_total * 100) if original_total > 0 else 100
|
||||
logger.info(
|
||||
"Phase 5 (AudioDB): Pre-warming %d items (%d artists, %d albums), %.0f%% already cached, concurrency=%d delay=%.1fs",
|
||||
total, len(needed_artists), len(needed_albums), initial_hit_rate, concurrency, inter_item_delay,
|
||||
)
|
||||
await status_service.update_phase('audiodb_prewarm', total, generation=generation)
|
||||
|
||||
needed_artists = self.sort_by_cover_priority(needed_artists, "artist")
|
||||
@@ -252,12 +246,6 @@ class AudioDBPhase:
|
||||
snap_ok, snap_fail = bytes_ok, bytes_fail
|
||||
await status_service.update_progress(local_processed, f"AudioDB: {name}", generation=generation)
|
||||
|
||||
if local_processed % _AUDIODB_PREWARM_LOG_INTERVAL == 0:
|
||||
logger.info(
|
||||
"audiodb.prewarm processed=%d total=%d initial_hit=%.0f%% bytes_ok=%d bytes_fail=%d remaining=%d",
|
||||
local_processed, total, initial_hit_rate, snap_ok, snap_fail, total - local_processed,
|
||||
)
|
||||
|
||||
async def process_album(album: Any) -> None:
|
||||
nonlocal processed, bytes_ok, bytes_fail
|
||||
if status_service.is_cancelled():
|
||||
@@ -294,12 +282,6 @@ class AudioDBPhase:
|
||||
snap_ok, snap_fail = bytes_ok, bytes_fail
|
||||
await status_service.update_progress(local_processed, f"AudioDB: {album_name or 'Unknown'}", generation=generation)
|
||||
|
||||
if local_processed % _AUDIODB_PREWARM_LOG_INTERVAL == 0:
|
||||
logger.info(
|
||||
"audiodb.prewarm processed=%d total=%d initial_hit=%.0f%% bytes_ok=%d bytes_fail=%d remaining=%d",
|
||||
local_processed, total, initial_hit_rate, snap_ok, snap_fail, total - local_processed,
|
||||
)
|
||||
|
||||
chunk = max(concurrency * 4, 20)
|
||||
for i in range(0, len(needed_artists), chunk):
|
||||
if status_service.is_cancelled():
|
||||
@@ -312,8 +294,3 @@ class AudioDBPhase:
|
||||
break
|
||||
batch = needed_albums[i:i + chunk]
|
||||
await asyncio.gather(*(process_album(a) for a in batch), return_exceptions=True)
|
||||
|
||||
logger.info(
|
||||
"audiodb.prewarm action=complete processed=%d total=%d bytes_ok=%d bytes_fail=%d",
|
||||
processed, total, bytes_ok, bytes_fail,
|
||||
)
|
||||
|
||||
@@ -152,30 +152,24 @@ class LibraryPrecacheService:
|
||||
skip_artists = False
|
||||
|
||||
if resume:
|
||||
logger.info("Resuming interrupted sync...")
|
||||
processed_artists = await self._sync_state_store.get_processed_items('artist')
|
||||
processed_albums = await self._sync_state_store.get_processed_items('album')
|
||||
|
||||
state = await self._sync_state_store.get_sync_state()
|
||||
if state and state.get('phase') in ('albums', 'audiodb_prewarm'):
|
||||
skip_artists = True
|
||||
logger.info(f"Resuming from {state.get('phase')} phase, {len(processed_albums)} albums already processed")
|
||||
else:
|
||||
logger.info(f"Resuming from artists phase, {len(processed_artists)} artists already processed")
|
||||
pass
|
||||
|
||||
total_artists = len(artists)
|
||||
total_albums = len(albums)
|
||||
|
||||
logger.info(f"Starting pre-cache for {total_artists} monitored artists and {total_albums} monitored albums")
|
||||
logger.info("Pre-fetching Lidarr library data...")
|
||||
album_service = get_album_service()
|
||||
library_artist_mbids = await self._lidarr_repo.get_artist_mbids()
|
||||
library_album_mbids = await self._lidarr_repo.get_library_mbids(include_release_ids=True)
|
||||
logger.info(f"Lidarr data cached: {len(library_artist_mbids)} artists, {len(library_album_mbids)} albums")
|
||||
|
||||
if not skip_artists:
|
||||
remaining_artists = [a for a in artists if a.get('mbid') not in processed_artists]
|
||||
logger.info(f"Phase 1: Caching {len(remaining_artists)} artist metadata + images ({len(processed_artists)} already done)")
|
||||
if remaining_artists:
|
||||
generation = await status_service.start_sync('artists', len(remaining_artists), total_artists=total_artists, total_albums=total_albums)
|
||||
await self._artist_phase.precache_artist_images(remaining_artists, status_service, library_artist_mbids, library_album_mbids, len(processed_artists), generation=generation)
|
||||
@@ -184,9 +178,7 @@ class LibraryPrecacheService:
|
||||
await status_service.skip_phase('artists', generation=generation)
|
||||
else:
|
||||
generation = await status_service.start_sync('albums', 0, total_artists=total_artists, total_albums=total_albums)
|
||||
logger.info("Resuming sync, skipping artists/discovery phases")
|
||||
if status_service.is_cancelled():
|
||||
logger.info("Pre-cache cancelled after Phase 1")
|
||||
return
|
||||
|
||||
if self._artist_discovery_service and not skip_artists:
|
||||
@@ -195,7 +187,6 @@ class LibraryPrecacheService:
|
||||
if a.get('mbid') and not a.get('mbid', '').startswith('unknown_')
|
||||
))
|
||||
if artist_mbids:
|
||||
logger.info(f"Phase 1.5: Pre-caching discovery data (popular albums/songs/similar) for {len(artist_mbids)} library artists")
|
||||
await status_service.update_phase('discovery', len(artist_mbids), generation=generation)
|
||||
mbid_to_name = {
|
||||
a.get('mbid'): a.get('name', a.get('mbid', '')[:8])
|
||||
@@ -217,7 +208,6 @@ class LibraryPrecacheService:
|
||||
await status_service.skip_phase('discovery', generation=generation)
|
||||
|
||||
if status_service.is_cancelled():
|
||||
logger.info("Pre-cache cancelled after Phase 1.5")
|
||||
return
|
||||
|
||||
monitored_mbids: set[str] = set()
|
||||
@@ -225,12 +215,9 @@ class LibraryPrecacheService:
|
||||
mbid = getattr(a, 'musicbrainz_id', None) if hasattr(a, 'musicbrainz_id') else a.get('mbid') if isinstance(a, dict) else None
|
||||
if not is_unknown_mbid(mbid):
|
||||
monitored_mbids.add(mbid.lower())
|
||||
logger.info(f"Phase 2: Collecting {len(monitored_mbids)} monitored album MBIDs (unmonitored albums will NOT be pre-cached)")
|
||||
deduped_release_groups = list(monitored_mbids)
|
||||
if status_service.is_cancelled():
|
||||
logger.info("Pre-cache cancelled after Phase 2")
|
||||
return
|
||||
logger.info(f"Phase 3: Batch-checking which of {len(deduped_release_groups)} release-groups need caching...")
|
||||
items_needing_metadata = []
|
||||
cache_checks = []
|
||||
for rgid in deduped_release_groups:
|
||||
@@ -256,11 +243,6 @@ class LibraryPrecacheService:
|
||||
items_needing_covers.append(rgid)
|
||||
items_to_process = list(set(items_needing_metadata + items_needing_covers))
|
||||
already_cached = len(deduped_release_groups) - len(items_to_process) - len(processed_albums)
|
||||
logger.info(
|
||||
f"Phase 3: {len(items_to_process)} items need caching "
|
||||
f"({len(items_needing_metadata)} metadata, {len(items_needing_covers)} covers) - "
|
||||
f"{already_cached} already cached, {len(processed_albums)} from previous run"
|
||||
)
|
||||
if items_to_process:
|
||||
await status_service.update_phase('albums', len(items_to_process), generation=generation)
|
||||
await self._album_phase.precache_album_data(items_to_process, monitored_mbids, status_service, library_album_mbids, len(processed_albums), generation=generation)
|
||||
@@ -268,21 +250,15 @@ class LibraryPrecacheService:
|
||||
await status_service.skip_phase('albums', generation=generation)
|
||||
|
||||
if status_service.is_cancelled():
|
||||
logger.info("Pre-cache cancelled after albums phase")
|
||||
return
|
||||
|
||||
try:
|
||||
logger.info("Starting AudioDB image prewarm...")
|
||||
await self._audiodb_phase.precache_audiodb_data(artists, albums, status_service, generation=generation)
|
||||
logger.info("AudioDB image prewarm complete")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.warning(f"AudioDB pre-warming failed (non-fatal): {e}")
|
||||
|
||||
if not status_service.is_cancelled():
|
||||
await status_service.complete_sync(generation=generation)
|
||||
logger.info("Library resource pre-caching complete")
|
||||
else:
|
||||
logger.info("Library resource pre-caching complete (cancelled)")
|
||||
except Exception as e:
|
||||
logger.error(f"Error during pre-cache: {e}")
|
||||
raise
|
||||
|
||||
@@ -90,7 +90,6 @@ class PreferencesService:
|
||||
def save_preferences(self, preferences: UserPreferences) -> None:
|
||||
try:
|
||||
self._save_section("user_preferences", preferences)
|
||||
logger.info(f"Saved preferences to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save preferences: {e}")
|
||||
raise ConfigurationError(f"Failed to save preferences: {e}")
|
||||
@@ -101,7 +100,6 @@ class PreferencesService:
|
||||
def save_lidarr_settings(self, lidarr_settings: LidarrSettings) -> None:
|
||||
try:
|
||||
self._save_section("lidarr_settings", lidarr_settings)
|
||||
logger.info(f"Saved Lidarr settings to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save Lidarr settings: {e}")
|
||||
raise ConfigurationError(f"Failed to save Lidarr settings: {e}")
|
||||
@@ -112,7 +110,6 @@ class PreferencesService:
|
||||
def save_advanced_settings(self, advanced_settings: AdvancedSettings) -> None:
|
||||
try:
|
||||
self._save_section("advanced_settings", advanced_settings)
|
||||
logger.info(f"Saved advanced settings to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save advanced settings: {e}")
|
||||
raise ConfigurationError(f"Failed to save advanced settings: {e}")
|
||||
@@ -144,8 +141,6 @@ class PreferencesService:
|
||||
self._settings.quality_profile_id = settings.quality_profile_id
|
||||
self._settings.metadata_profile_id = settings.metadata_profile_id
|
||||
self._settings.root_folder_path = settings.root_folder_path
|
||||
|
||||
logger.info(f"Saved Lidarr connection settings to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save Lidarr connection settings: {e}")
|
||||
raise ConfigurationError(f"Failed to save Lidarr connection settings: {e}")
|
||||
@@ -173,8 +168,6 @@ class PreferencesService:
|
||||
self._save_config(config)
|
||||
|
||||
self._settings.jellyfin_url = settings.jellyfin_url
|
||||
|
||||
logger.info(f"Saved Jellyfin connection settings to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save Jellyfin connection settings: {e}")
|
||||
raise ConfigurationError(f"Failed to save Jellyfin connection settings: {e}")
|
||||
@@ -216,7 +209,6 @@ class PreferencesService:
|
||||
"enabled": settings.enabled,
|
||||
}
|
||||
self._save_config(config)
|
||||
logger.info("Saved Navidrome connection settings to %s", self._config_path)
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Failed to save Navidrome connection settings: %s", e)
|
||||
raise ConfigurationError(f"Failed to save Navidrome connection settings: {e}")
|
||||
@@ -286,8 +278,6 @@ class PreferencesService:
|
||||
"enabled": settings.enabled,
|
||||
}
|
||||
self._save_config(config)
|
||||
|
||||
logger.info(f"Saved ListenBrainz connection settings to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save ListenBrainz connection settings: {e}")
|
||||
raise ConfigurationError(f"Failed to save ListenBrainz connection settings: {e}")
|
||||
@@ -319,7 +309,6 @@ class PreferencesService:
|
||||
"daily_quota_limit": settings.daily_quota_limit,
|
||||
}
|
||||
self._save_config(config)
|
||||
logger.info(f"Saved YouTube connection settings to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save YouTube connection settings: {e}")
|
||||
raise ConfigurationError(f"Failed to save YouTube connection settings: {e}")
|
||||
@@ -330,7 +319,6 @@ class PreferencesService:
|
||||
def save_home_settings(self, settings: HomeSettings) -> None:
|
||||
try:
|
||||
self._save_section("home_settings", settings)
|
||||
logger.info(f"Saved home settings to {self._config_path}")
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error(f"Failed to save home settings: {e}")
|
||||
raise ConfigurationError(f"Failed to save home settings: {e}")
|
||||
@@ -341,7 +329,6 @@ class PreferencesService:
|
||||
def save_local_files_connection(self, settings: LocalFilesConnectionSettings) -> None:
|
||||
try:
|
||||
self._save_section("local_files_settings", settings)
|
||||
logger.info("Saved local files settings to %s", self._config_path)
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Failed to save local files settings: %s", e)
|
||||
raise ConfigurationError(f"Failed to save local files settings: {e}")
|
||||
@@ -381,7 +368,6 @@ class PreferencesService:
|
||||
enabled=enabled,
|
||||
)
|
||||
self._save_section("lastfm_settings", resolved)
|
||||
logger.info("Saved Last.fm connection settings to %s", self._config_path)
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Failed to save Last.fm connection settings: %s", e)
|
||||
raise ConfigurationError(f"Failed to save Last.fm connection settings: {e}")
|
||||
@@ -396,7 +382,6 @@ class PreferencesService:
|
||||
def save_scrobble_settings(self, settings: ScrobbleSettings) -> None:
|
||||
try:
|
||||
self._save_section("scrobble_settings", settings)
|
||||
logger.info("Saved scrobble settings to %s", self._config_path)
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Failed to save scrobble settings: %s", e)
|
||||
raise ConfigurationError(f"Failed to save scrobble settings: {e}")
|
||||
@@ -407,7 +392,6 @@ class PreferencesService:
|
||||
def save_primary_music_source(self, settings: PrimaryMusicSourceSettings) -> None:
|
||||
try:
|
||||
self._save_section("primary_music_source", settings)
|
||||
logger.info("Saved primary music source to %s", self._config_path)
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Failed to save primary music source: %s", e)
|
||||
raise ConfigurationError(f"Failed to save primary music source: {e}")
|
||||
@@ -418,7 +402,6 @@ class PreferencesService:
|
||||
def save_profile_settings(self, settings: ProfileSettings) -> None:
|
||||
try:
|
||||
self._save_section("profile_settings", settings)
|
||||
logger.info("Saved profile settings to %s", self._config_path)
|
||||
except Exception as e: # noqa: BLE001
|
||||
logger.error("Failed to save profile settings: %s", e)
|
||||
raise ConfigurationError(f"Failed to save profile settings: {e}")
|
||||
|
||||
@@ -475,10 +475,6 @@ class RequestsPageService:
|
||||
await self._notify_import(record)
|
||||
return True
|
||||
if event_type == "albumImportIncomplete":
|
||||
logger.info(
|
||||
"Partial import detected for %s",
|
||||
record.musicbrainz_id,
|
||||
)
|
||||
await self._request_history.async_update_status(
|
||||
record.musicbrainz_id,
|
||||
"incomplete",
|
||||
|
||||
@@ -120,17 +120,6 @@ class ScrobbleService:
|
||||
services[service_name] = ServiceResult(success=True)
|
||||
any_success = True
|
||||
|
||||
logger.info(
|
||||
"Now playing reported",
|
||||
extra={
|
||||
"artist": request.artist_name,
|
||||
"track": request.track_name,
|
||||
"services": {
|
||||
k: {"success": v.success, "error": v.error}
|
||||
for k, v in services.items()
|
||||
},
|
||||
},
|
||||
)
|
||||
return ScrobbleResponse(accepted=any_success, services=services)
|
||||
|
||||
async def submit_scrobble(
|
||||
@@ -205,16 +194,4 @@ class ScrobbleService:
|
||||
if any_success:
|
||||
self._record_dedup(dedup)
|
||||
|
||||
logger.info(
|
||||
"Scrobble submitted",
|
||||
extra={
|
||||
"artist": request.artist_name,
|
||||
"track": request.track_name,
|
||||
"timestamp": request.timestamp,
|
||||
"services": {
|
||||
k: {"success": v.success, "error": v.error}
|
||||
for k, v in services.items()
|
||||
},
|
||||
},
|
||||
)
|
||||
return ScrobbleResponse(accepted=any_success, services=services)
|
||||
|
||||
@@ -1,9 +1,6 @@
|
||||
import logging
|
||||
from repositories.protocols import LidarrRepositoryProtocol
|
||||
from api.v1.schemas.common import StatusReport, ServiceStatus
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class StatusService:
|
||||
def __init__(self, lidarr_repo: LidarrRepositoryProtocol):
|
||||
|
||||
@@ -1,4 +1,3 @@
|
||||
import logging
|
||||
import re
|
||||
import uuid
|
||||
from datetime import datetime, timezone
|
||||
@@ -12,8 +11,6 @@ from infrastructure.persistence import YouTubeStore
|
||||
from infrastructure.serialization import to_jsonable
|
||||
from repositories.protocols import YouTubeRepositoryProtocol
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
_VIDEO_ID_RE = re.compile(
|
||||
r'(?:youtube\.com/watch\?.*v=|youtu\.be/|youtube\.com/embed/)([a-zA-Z0-9_-]{11})'
|
||||
)
|
||||
@@ -256,7 +253,7 @@ class YouTubeService:
|
||||
) -> YouTubeLink:
|
||||
video_id = extract_video_id(youtube_url)
|
||||
if not video_id:
|
||||
raise ValidationError("Invalid YouTube URL — could not extract video ID")
|
||||
raise ValidationError("Invalid YouTube URL: could not extract a video ID")
|
||||
|
||||
if not album_id:
|
||||
album_id = f"manual-{uuid.uuid4().hex[:12]}"
|
||||
@@ -289,7 +286,7 @@ class YouTubeService:
|
||||
if youtube_url:
|
||||
new_vid = extract_video_id(youtube_url)
|
||||
if not new_vid:
|
||||
raise ValidationError("Invalid YouTube URL — could not extract video ID")
|
||||
raise ValidationError("Invalid YouTube URL: could not extract a video ID")
|
||||
video_id = new_vid
|
||||
embed_url = f"https://www.youtube.com/embed/{new_vid}"
|
||||
|
||||
|
||||
@@ -1,5 +1,4 @@
|
||||
import pytest
|
||||
import logging
|
||||
from unittest.mock import AsyncMock, MagicMock
|
||||
|
||||
from fastapi import FastAPI
|
||||
@@ -96,30 +95,6 @@ def test_suggest_whitespace_padded_valid_input_strips(client, mock_search_servic
|
||||
mock_search_service.suggest.assert_called_once_with(query="ab", limit=5)
|
||||
|
||||
|
||||
def test_suggest_debug_log_contains_fields_without_query_text(client, mock_search_service, caplog):
|
||||
"""Debug log includes query_len, results, time_ms but not the raw query text."""
|
||||
mock_search_service.suggest = AsyncMock(
|
||||
return_value=SuggestResponse(results=[
|
||||
SuggestResult(
|
||||
type="artist", title="Muse", musicbrainz_id="mb-1",
|
||||
in_library=False, requested=False, score=90,
|
||||
)
|
||||
])
|
||||
)
|
||||
|
||||
with caplog.at_level(logging.DEBUG, logger="api.v1.routes.search"):
|
||||
response = client.get("/search/suggest?q=muse")
|
||||
|
||||
assert response.status_code == 200
|
||||
log_messages = [r.message for r in caplog.records if "Suggest" in r.message]
|
||||
assert len(log_messages) >= 1
|
||||
log_msg = log_messages[0]
|
||||
assert "query_len=4" in log_msg
|
||||
assert "results=1" in log_msg
|
||||
assert "time_ms=" in log_msg
|
||||
assert "muse" not in log_msg
|
||||
|
||||
|
||||
def test_search_response_tolerates_additive_score_field():
|
||||
"""Existing /api/search consumers tolerate the additive score field on SearchResult."""
|
||||
mock_search_service = MagicMock()
|
||||
|
||||
@@ -5,6 +5,7 @@ from unittest.mock import AsyncMock, MagicMock, PropertyMock
|
||||
|
||||
import pytest
|
||||
|
||||
from core.exceptions import ExternalServiceError
|
||||
from repositories.plex_models import PlexPlaylist, PlexTrack
|
||||
from repositories.navidrome_models import SubsonicPlaylist, SubsonicSong
|
||||
from repositories.jellyfin_models import JellyfinItem
|
||||
@@ -325,6 +326,6 @@ class TestJellyfinImportPlaylist:
|
||||
svc = _jellyfin_service(playlists=[pl], items=tracks)
|
||||
ps = _mock_playlist_service()
|
||||
ps.add_tracks = AsyncMock(side_effect=Exception("fail"))
|
||||
with pytest.raises(Exception):
|
||||
with pytest.raises(ExternalServiceError):
|
||||
await svc.import_playlist("jf-1", ps)
|
||||
ps.delete_playlist.assert_awaited_once_with("new-pl-1")
|
||||
|
||||
@@ -1,16 +1,13 @@
|
||||
"""Phase 9 observability contract tests.
|
||||
|
||||
Verifies that every key log event fires with the required fields, and that
|
||||
SSE / cache-stats wiring propagates AudioDB data end-to-end.
|
||||
Verifies SSE / cache-stats wiring propagates AudioDB data end-to-end.
|
||||
"""
|
||||
|
||||
from unittest.mock import AsyncMock, MagicMock, patch
|
||||
|
||||
import httpx
|
||||
import msgspec
|
||||
import pytest
|
||||
|
||||
from tests.helpers import assert_log_fields
|
||||
from repositories.audiodb_models import (
|
||||
AudioDBArtistImages,
|
||||
AudioDBArtistResponse,
|
||||
@@ -71,191 +68,6 @@ def _make_image_service(settings=None, disk_cache=None, repo=None):
|
||||
)
|
||||
|
||||
|
||||
|
||||
|
||||
CACHE_REQUIRED_FIELDS = ["action", "entity_type", "mbid", "lookup_source"]
|
||||
|
||||
|
||||
class TestCacheLogContract:
|
||||
@pytest.mark.asyncio
|
||||
async def test_miss_includes_lookup_source(self, caplog):
|
||||
svc = _make_image_service()
|
||||
with caplog.at_level("DEBUG"):
|
||||
await svc.get_cached_artist_images(TEST_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.cache", CACHE_REQUIRED_FIELDS)
|
||||
assert any("action=miss" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_corrupt_includes_lookup_source(self, caplog):
|
||||
disk = AsyncMock()
|
||||
disk.get_audiodb_artist = AsyncMock(return_value="not-a-dict")
|
||||
disk.delete_entity = AsyncMock()
|
||||
svc = _make_image_service(disk_cache=disk)
|
||||
with caplog.at_level("DEBUG"):
|
||||
await svc.get_cached_artist_images(TEST_MBID)
|
||||
|
||||
msgs = assert_log_fields(
|
||||
caplog.records, "audiodb.cache", CACHE_REQUIRED_FIELDS,
|
||||
)
|
||||
assert any("action=corrupt" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_hit_includes_lookup_source(self, caplog):
|
||||
images = AudioDBArtistImages(
|
||||
thumb_url="https://example.com/thumb.jpg",
|
||||
is_negative=False,
|
||||
lookup_source="mbid",
|
||||
)
|
||||
raw = msgspec.structs.asdict(images)
|
||||
disk = AsyncMock()
|
||||
disk.get_audiodb_artist = AsyncMock(return_value=raw)
|
||||
svc = _make_image_service(disk_cache=disk)
|
||||
with caplog.at_level("DEBUG"):
|
||||
await svc.get_cached_artist_images(TEST_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.cache", CACHE_REQUIRED_FIELDS)
|
||||
assert any("action=hit" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_write_mbid_includes_lookup_source(self, caplog):
|
||||
repo = AsyncMock()
|
||||
repo.get_artist_by_mbid = AsyncMock(return_value=SAMPLE_ARTIST_RESP)
|
||||
svc = _make_image_service(repo=repo)
|
||||
with caplog.at_level("DEBUG"):
|
||||
await svc.fetch_and_cache_artist_images(TEST_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.cache", CACHE_REQUIRED_FIELDS)
|
||||
assert any("action=write" in m and "lookup_source=mbid" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_fetch_error_mbid_includes_lookup_source(self, caplog):
|
||||
repo = AsyncMock()
|
||||
repo.get_artist_by_mbid = AsyncMock(side_effect=Exception("network"))
|
||||
svc = _make_image_service(repo=repo)
|
||||
with caplog.at_level("DEBUG"):
|
||||
await svc.fetch_and_cache_artist_images(TEST_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.cache", CACHE_REQUIRED_FIELDS)
|
||||
assert any("action=fetch_error" in m and "lookup_source=mbid" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_album_miss_includes_lookup_source(self, caplog):
|
||||
svc = _make_image_service()
|
||||
with caplog.at_level("DEBUG"):
|
||||
await svc.get_cached_album_images(TEST_ALBUM_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.cache", CACHE_REQUIRED_FIELDS)
|
||||
assert any("action=miss" in m and "entity_type=album" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_album_write_mbid_includes_lookup_source(self, caplog):
|
||||
repo = AsyncMock()
|
||||
repo.get_album_by_mbid = AsyncMock(return_value=SAMPLE_ALBUM_RESP)
|
||||
svc = _make_image_service(repo=repo)
|
||||
with caplog.at_level("DEBUG"):
|
||||
await svc.fetch_and_cache_album_images(TEST_ALBUM_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.cache", CACHE_REQUIRED_FIELDS)
|
||||
assert any("action=write" in m and "entity_type=album" in m for m in msgs)
|
||||
|
||||
|
||||
|
||||
|
||||
LOOKUP_REQUIRED_FIELDS = ["entity", "lookup_type", "found", "elapsed_ms"]
|
||||
|
||||
|
||||
class TestLookupLogContract:
|
||||
@pytest.fixture(autouse=True)
|
||||
def _reset_resilience(self):
|
||||
from repositories.audiodb_repository import _audiodb_circuit_breaker
|
||||
_audiodb_circuit_breaker.reset()
|
||||
yield
|
||||
_audiodb_circuit_breaker.reset()
|
||||
|
||||
@pytest.fixture(autouse=True)
|
||||
def _stub_retry_sleep(self):
|
||||
with patch("infrastructure.resilience.retry.asyncio.sleep", new=AsyncMock()):
|
||||
yield
|
||||
|
||||
def _make_repo(self):
|
||||
from repositories.audiodb_repository import AudioDBRepository
|
||||
client = AsyncMock(spec=httpx.AsyncClient)
|
||||
prefs = MagicMock()
|
||||
settings = MagicMock()
|
||||
settings.audiodb_enabled = True
|
||||
settings.audiodb_api_key = "test_key"
|
||||
prefs.get_advanced_settings.return_value = settings
|
||||
return AudioDBRepository(
|
||||
http_client=client,
|
||||
preferences_service=prefs,
|
||||
api_key="test_key",
|
||||
)
|
||||
|
||||
def _mock_response(self, status_code=200, json_data=None):
|
||||
resp = MagicMock(spec=httpx.Response)
|
||||
resp.status_code = status_code
|
||||
resp.content = msgspec.json.encode(json_data or {})
|
||||
return resp
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_artist_mbid_found_logs_lookup(self, caplog):
|
||||
repo = self._make_repo()
|
||||
data = {"artists": [{
|
||||
"idArtist": "111239", "strArtist": "Coldplay",
|
||||
"strMusicBrainzID": TEST_MBID,
|
||||
"strArtistThumb": "https://example.com/thumb.jpg",
|
||||
}]}
|
||||
repo._client.get = AsyncMock(return_value=self._mock_response(200, data))
|
||||
with caplog.at_level("DEBUG"):
|
||||
await repo.get_artist_by_mbid(TEST_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.lookup", LOOKUP_REQUIRED_FIELDS)
|
||||
assert any("found=true" in m and "entity=artist" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_artist_mbid_not_found_logs_lookup(self, caplog):
|
||||
repo = self._make_repo()
|
||||
repo._client.get = AsyncMock(return_value=self._mock_response(200, {"artists": None}))
|
||||
with caplog.at_level("DEBUG"):
|
||||
await repo.get_artist_by_mbid(TEST_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.lookup", LOOKUP_REQUIRED_FIELDS)
|
||||
assert any("found=false" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_album_mbid_found_logs_lookup(self, caplog):
|
||||
repo = self._make_repo()
|
||||
data = {"album": [{
|
||||
"idAlbum": "2115888", "strAlbum": "Parachutes",
|
||||
"strMusicBrainzID": TEST_ALBUM_MBID,
|
||||
"strAlbumThumb": "https://example.com/thumb.jpg",
|
||||
}]}
|
||||
repo._client.get = AsyncMock(return_value=self._mock_response(200, data))
|
||||
with caplog.at_level("DEBUG"):
|
||||
await repo.get_album_by_mbid(TEST_ALBUM_MBID)
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.lookup", LOOKUP_REQUIRED_FIELDS)
|
||||
assert any("found=true" in m and "entity=album" in m for m in msgs)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_name_search_logs_lookup(self, caplog):
|
||||
repo = self._make_repo()
|
||||
data = {"artists": [{
|
||||
"idArtist": "111239", "strArtist": "Coldplay",
|
||||
"strMusicBrainzID": TEST_MBID,
|
||||
"strArtistThumb": "https://example.com/thumb.jpg",
|
||||
}]}
|
||||
repo._client.get = AsyncMock(return_value=self._mock_response(200, data))
|
||||
with caplog.at_level("DEBUG"):
|
||||
await repo.search_artist_by_name("Coldplay")
|
||||
|
||||
msgs = assert_log_fields(caplog.records, "audiodb.lookup", LOOKUP_REQUIRED_FIELDS)
|
||||
assert any("lookup_type=name" in m for m in msgs)
|
||||
|
||||
|
||||
|
||||
|
||||
class TestPrewarmLogContract:
|
||||
def _make_status_service(self):
|
||||
status = MagicMock()
|
||||
@@ -292,32 +104,6 @@ class TestPrewarmLogContract:
|
||||
audiodb_image_service=audiodb_svc,
|
||||
)
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_prewarm_progress_logs_fire(self, caplog):
|
||||
svc = AsyncMock()
|
||||
images = AudioDBArtistImages(thumb_url="https://x.com/t.jpg", is_negative=False)
|
||||
svc.get_cached_artist_images = AsyncMock(return_value=None)
|
||||
svc.get_cached_album_images = AsyncMock(return_value=None)
|
||||
svc.fetch_and_cache_artist_images = AsyncMock(return_value=images)
|
||||
svc.fetch_and_cache_album_images = AsyncMock(return_value=None)
|
||||
|
||||
precache = self._make_precache_service(audiodb_svc=svc)
|
||||
status = self._make_status_service()
|
||||
|
||||
artists = [{"mbid": TEST_MBID, "name": f"Artist{i}"} for i in range(1)]
|
||||
with caplog.at_level("DEBUG"):
|
||||
with patch.object(precache, '_download_audiodb_bytes', new_callable=AsyncMock, return_value=True):
|
||||
await precache._precache_audiodb_data(artists, [], status)
|
||||
|
||||
complete_logs = [
|
||||
r.message for r in caplog.records
|
||||
if r.message.startswith("audiodb.prewarm") and "action=complete" in r.message
|
||||
]
|
||||
assert len(complete_logs) >= 1
|
||||
for msg in complete_logs:
|
||||
assert "processed=" in msg
|
||||
assert "total=" in msg
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_prewarm_calls_update_phase_audiodb(self):
|
||||
svc = AsyncMock()
|
||||
|
||||
@@ -153,7 +153,6 @@
|
||||
}
|
||||
} catch (e) {
|
||||
if (isAbortError(e)) return;
|
||||
console.error('Failed to fetch discover queue:', e);
|
||||
} finally {
|
||||
loading = false;
|
||||
}
|
||||
@@ -177,7 +176,7 @@
|
||||
await fetchNewQueue();
|
||||
}
|
||||
} catch {
|
||||
/* ignore validation errors */
|
||||
// ignore fetch failures
|
||||
}
|
||||
}
|
||||
|
||||
@@ -224,7 +223,6 @@
|
||||
return data;
|
||||
} catch (e) {
|
||||
if (isAbortError(e)) return null;
|
||||
console.error('Failed to enrich item:', e);
|
||||
if (queue[index]?.release_group_mbid === mbid && !queue[index]?.enrichment) {
|
||||
queue[index] = { ...queue[index], enrichment: emptyEnrichment() };
|
||||
}
|
||||
@@ -269,7 +267,7 @@
|
||||
{ signal: abortController?.signal }
|
||||
);
|
||||
} catch {
|
||||
/* continue regardless */
|
||||
// ignore request failure
|
||||
}
|
||||
|
||||
queue = queue.filter((_, i) => i !== currentIndex);
|
||||
@@ -313,7 +311,7 @@
|
||||
|
||||
function truncateText(text: string, maxLen: number): string {
|
||||
if (text.length <= maxLen) return text;
|
||||
return text.slice(0, maxLen).trimEnd() + '…';
|
||||
return text.slice(0, maxLen).trimEnd() + '...';
|
||||
}
|
||||
|
||||
function resetYtSearch() {
|
||||
@@ -327,7 +325,7 @@
|
||||
signal: abortController?.signal
|
||||
});
|
||||
} catch {
|
||||
// YouTube not configured or network error — leave null
|
||||
// ignore quota fetch failure
|
||||
}
|
||||
}
|
||||
|
||||
@@ -369,7 +367,7 @@
|
||||
{#if loading}
|
||||
<div class="flex flex-col items-center justify-center py-16 px-8">
|
||||
<span class="loading loading-spinner loading-lg text-primary"></span>
|
||||
<p class="mt-4 text-base-content/60">Building your discovery queue…</p>
|
||||
<p class="mt-4 text-base-content/60">Building your discovery queue...</p>
|
||||
</div>
|
||||
{:else if queue.length === 0}
|
||||
<div class="flex flex-col items-center justify-center py-16 px-8">
|
||||
@@ -395,7 +393,7 @@
|
||||
{currentItem.album_name}
|
||||
</button>
|
||||
{#if currentItem.is_wildcard}
|
||||
<span class="badge badge-sm badge-warning">✨</span>
|
||||
<span class="badge badge-sm badge-warning">Wildcard</span>
|
||||
{/if}
|
||||
</div>
|
||||
{#if artistNavigationMbid}
|
||||
|
||||
@@ -107,10 +107,9 @@
|
||||
const data = await api.global.get<YouTubeTrackLink[]>(API.youtube.trackLinks(albumId));
|
||||
if (id !== fetchId) return;
|
||||
tracks = data.sort(compareDiscTrack);
|
||||
} catch (e) {
|
||||
} catch (_e) {
|
||||
if (id === fetchId) {
|
||||
trackError = true;
|
||||
console.warn('Failed to fetch YouTube track links', e);
|
||||
}
|
||||
} finally {
|
||||
if (id === fetchId) loadingTracks = false;
|
||||
|
||||
@@ -147,7 +147,6 @@ export class NativeAudioSource implements PlaybackSource {
|
||||
|
||||
seekTo(seconds: number): void {
|
||||
if (!this.seekable) {
|
||||
console.warn('[NativeAudio] seekTo ignored: stream is not seekable');
|
||||
return;
|
||||
}
|
||||
const clamped = Math.max(0, seconds);
|
||||
|
||||
@@ -75,23 +75,17 @@ describe('jellyfinPlaybackApi', () => {
|
||||
});
|
||||
});
|
||||
|
||||
it('warns on network errors without throwing', async () => {
|
||||
const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {});
|
||||
it('returns false on network errors without throwing', async () => {
|
||||
mockPost.mockRejectedValueOnce(new Error('Network down'));
|
||||
|
||||
await expect(api.reportProgress('item-1', 'sess-1', 10, false)).resolves.toBe(false);
|
||||
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('network error'));
|
||||
warnSpy.mockRestore();
|
||||
});
|
||||
|
||||
it('warns on non-ok response without throwing', async () => {
|
||||
const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {});
|
||||
it('returns false on non-ok responses without throwing', async () => {
|
||||
const { ApiError } = await import('$lib/api/client');
|
||||
mockPost.mockRejectedValueOnce(new ApiError(500, 'server_error', 'Internal error'));
|
||||
|
||||
await expect(api.reportProgress('item-1', 'sess-1', 10, false)).resolves.toBe(false);
|
||||
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('500'));
|
||||
warnSpy.mockRestore();
|
||||
});
|
||||
});
|
||||
|
||||
@@ -108,20 +102,17 @@ describe('jellyfinPlaybackApi', () => {
|
||||
});
|
||||
});
|
||||
|
||||
it('swallows errors silently', async () => {
|
||||
it('returns false on errors', async () => {
|
||||
mockPost.mockRejectedValueOnce(new Error('Network down'));
|
||||
|
||||
await expect(api.reportStop('item-1', 'sess-1', 60)).resolves.toBe(false);
|
||||
});
|
||||
|
||||
it('warns on non-ok response without throwing', async () => {
|
||||
const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {});
|
||||
it('returns false on non-ok responses without throwing', async () => {
|
||||
const { ApiError } = await import('$lib/api/client');
|
||||
mockPost.mockRejectedValueOnce(new ApiError(502, 'bad_gateway', 'Bad gateway'));
|
||||
|
||||
await expect(api.reportStop('item-1', 'sess-1', 60)).resolves.toBe(false);
|
||||
expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('502'));
|
||||
warnSpy.mockRestore();
|
||||
});
|
||||
});
|
||||
});
|
||||
|
||||
@@ -42,9 +42,7 @@ export async function reportProgress(
|
||||
is_paused: isPaused
|
||||
});
|
||||
return true;
|
||||
} catch (e) {
|
||||
const detail = e instanceof ApiError ? String(e.status) : 'network error';
|
||||
console.warn(`[Jellyfin] progress report failed: ${detail}`);
|
||||
} catch {
|
||||
return false;
|
||||
}
|
||||
}
|
||||
@@ -60,9 +58,7 @@ export async function reportStop(
|
||||
position_seconds: positionSeconds
|
||||
});
|
||||
return true;
|
||||
} catch (e) {
|
||||
const detail = e instanceof ApiError ? String(e.status) : 'network error';
|
||||
console.warn(`[Jellyfin] stop report failed: ${detail}`);
|
||||
} catch {
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1,32 +1,26 @@
|
||||
import { API } from '$lib/constants';
|
||||
import { api, ApiError } from '$lib/api/client';
|
||||
import { api } from '$lib/api/client';
|
||||
|
||||
export async function reportNavidromeScrobble(itemId: string): Promise<void> {
|
||||
try {
|
||||
const body = await api.global.post<{ status: string }>(API.stream.navidromeScrobble(itemId));
|
||||
if (body.status !== 'ok') {
|
||||
console.warn('[Navidrome] scrobble reported error');
|
||||
}
|
||||
} catch (e) {
|
||||
const detail = e instanceof ApiError ? String(e.status) : 'network error';
|
||||
console.warn(`[Navidrome] scrobble failed: ${detail}`);
|
||||
await api.global.post<{ status: string }>(API.stream.navidromeScrobble(itemId));
|
||||
} catch {
|
||||
// best-effort scrobble
|
||||
}
|
||||
}
|
||||
|
||||
export async function reportNavidromeNowPlaying(itemId: string): Promise<void> {
|
||||
try {
|
||||
await api.global.post(API.stream.navidromeNowPlaying(itemId));
|
||||
} catch (e) {
|
||||
const detail = e instanceof ApiError ? String(e.status) : 'network error';
|
||||
console.warn(`[Navidrome] now-playing failed: ${detail}`);
|
||||
} catch {
|
||||
// best-effort now-playing report
|
||||
}
|
||||
}
|
||||
|
||||
export async function reportNavidromeStopped(itemId: string): Promise<void> {
|
||||
try {
|
||||
await api.global.post(API.stream.navidromeStopped(itemId));
|
||||
} catch (e) {
|
||||
const detail = e instanceof ApiError ? String(e.status) : 'network error';
|
||||
console.warn(`[Navidrome] stopped report failed: ${detail}`);
|
||||
} catch {
|
||||
// best-effort stopped report
|
||||
}
|
||||
}
|
||||
|
||||
@@ -6,11 +6,6 @@ import type {
|
||||
} from '@tanstack/svelte-query-persist-client';
|
||||
import { del, entries, get, set } from 'idb-keyval';
|
||||
|
||||
/**
|
||||
* Creates an Indexed DB persister
|
||||
* @see https://developer.mozilla.org/en-US/docs/Web/API/IndexedDB_API
|
||||
* @see https://tanstack.com/query/latest/docs/framework/react/plugins/persistQueryClient#building-a-persister
|
||||
*/
|
||||
export function createIDBPersister(idbValidKey: string = 'tanstackQuery') {
|
||||
return {
|
||||
persistClient: async (client: PersistedClient) => {
|
||||
|
||||
@@ -26,8 +26,8 @@ async function load(): Promise<void> {
|
||||
directRemoteImagesEnabled: data.direct_remote_images_enabled ?? true
|
||||
});
|
||||
lastFetch = now;
|
||||
} catch (e) {
|
||||
console.warn('Failed to load image settings:', e);
|
||||
} catch {
|
||||
// use defaults on fetch failure
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -102,8 +102,7 @@ function createLibraryStore() {
|
||||
}));
|
||||
|
||||
cache.set({ mbids, requested });
|
||||
} catch (e) {
|
||||
console.error('Failed to fetch library MBIDs:', e);
|
||||
} catch {
|
||||
if (!background) {
|
||||
update((s) => ({ ...s, loading: false, initialized: true }));
|
||||
}
|
||||
|
||||
@@ -16,8 +16,8 @@ async function loadPreferences(): Promise<void> {
|
||||
try {
|
||||
const prefs = await api.global.get<UserPreferences>(`${API_BASE}/settings/preferences`);
|
||||
set(prefs);
|
||||
} catch (e) {
|
||||
console.error('Failed to load preferences:', e);
|
||||
} catch {
|
||||
// use defaults on fetch failure
|
||||
}
|
||||
}
|
||||
|
||||
@@ -29,8 +29,7 @@ async function savePreferences(prefs: UserPreferences): Promise<boolean> {
|
||||
);
|
||||
set(updated);
|
||||
return true;
|
||||
} catch (e) {
|
||||
console.error('Failed to save preferences:', e);
|
||||
} catch {
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -73,7 +73,7 @@ export function createLocalStorageCache<T>(
|
||||
return key.startsWith(keyPrefix);
|
||||
}
|
||||
|
||||
function isQuotaExceededError(error: unknown): boolean {
|
||||
function _isQuotaExceededError(error: unknown): boolean {
|
||||
if (!(error instanceof DOMException)) return false;
|
||||
return (
|
||||
error.code === 22 ||
|
||||
@@ -128,10 +128,7 @@ export function createLocalStorageCache<T>(
|
||||
try {
|
||||
localStorage.setItem(key, payload);
|
||||
return true;
|
||||
} catch (error) {
|
||||
if (!isQuotaExceededError(error)) {
|
||||
console.warn(`[localStorageCache] Failed to write key "${key}":`, error);
|
||||
}
|
||||
} catch {
|
||||
return false;
|
||||
}
|
||||
}
|
||||
@@ -172,8 +169,6 @@ export function createLocalStorageCache<T>(
|
||||
enforceMaxEntriesLimit();
|
||||
return;
|
||||
}
|
||||
|
||||
console.warn(`[localStorageCache] Storage quota exceeded for key "${key}".`);
|
||||
}
|
||||
|
||||
function remove(suffix?: string): void {
|
||||
|
||||
Some files were not shown because too many files have changed in this diff Show More
Reference in New Issue
Block a user