diff --git a/endpoints/lighting.py b/endpoints/lighting.py index 9c3c18a..02ceba4 100644 --- a/endpoints/lighting.py +++ b/endpoints/lighting.py @@ -25,7 +25,7 @@ from typing import Optional logging.basicConfig( filename="cync_auth_events.log", level=logging.INFO, - format="%(asctime)s - %(levelname)s - %(message)s" + format="%(asctime)s - %(levelname)s - %(message)s", ) @@ -35,24 +35,24 @@ def _mask_token(token: Optional[str]) -> str: return "" return f"{token[:4]}...{token[-4:]}" + def _log_token_state(user, context: str): """Log masked token state for debugging.""" if not user: logging.info(f"{context} - No user object available") return - + try: logging.info( f"{context} - Token state: access=%s refresh=%s expires_at=%s", - _mask_token(getattr(user, 'access_token', None)), - _mask_token(getattr(user, 'refresh_token', None)), - getattr(user, 'expires_at', None) + _mask_token(getattr(user, "access_token", None)), + _mask_token(getattr(user, "refresh_token", None)), + getattr(user, "expires_at", None), ) except Exception as e: logging.error(f"Error logging token state: {e}") - class Lighting(FastAPI): async def _close_session_safely(self): """Safely close the current session if it exists.""" @@ -69,9 +69,13 @@ class Lighting(FastAPI): async def _test_connection_health(self) -> bool: """Test if the current connection is healthy by making a simple API call.""" - if not self.cync_api or not self.session or getattr(self.session, "closed", True): + if ( + not self.cync_api + or not self.session + or getattr(self.session, "closed", True) + ): return False - + try: # Make a simple API call to test connectivity devices = self.cync_api.get_devices() @@ -95,18 +99,20 @@ class Lighting(FastAPI): raise Exception( f"Missing required environment variables: {', '.join(missing_vars)}" ) - + # Cast to str after check to silence linter cync_email: str = self.cync_email # type: ignore cync_password: str = self.cync_password # type: ignore # If force_reconnect is True or connection is unhealthy, rebuild everything if force_reconnect or not await self._test_connection_health(): - logging.info("Connection unhealthy or force reconnect requested. Rebuilding connection...") - + logging.info( + "Connection unhealthy or force reconnect requested. Rebuilding connection..." + ) + # Clean up existing connection await self._close_session_safely() - + # Create new session with timeout configuration timeout = aiohttp.ClientTimeout(total=30, connect=10) connector = aiohttp.TCPConnector( @@ -115,18 +121,15 @@ class Lighting(FastAPI): ttl_dns_cache=300, use_dns_cache=True, keepalive_timeout=60, - enable_cleanup_closed=True + enable_cleanup_closed=True, ) - self.session = aiohttp.ClientSession( - timeout=timeout, - connector=connector - ) - + self.session = aiohttp.ClientSession(timeout=timeout, connector=connector) + # Load cached token and check validity self.cync_user = None cached_user = self._load_cached_user() token_status = None - + if cached_user and hasattr(cached_user, "expires_at"): # Add buffer time - consider token expired if less than 5 minutes remaining buffer_time = 300 # 5 minutes @@ -136,9 +139,9 @@ class Lighting(FastAPI): token_status = "expired" else: token_status = "no cached user or missing expires_at" - + logging.info(f"Cync token status: {token_status}") - + if token_status == "valid" and cached_user is not None: # Use cached token self.auth = Auth( @@ -157,7 +160,7 @@ class Lighting(FastAPI): logging.info("Removed expired token cache") except (OSError, FileNotFoundError): pass - + logging.info("Initializing new Auth instance...") self.auth = Auth( session=self.session, @@ -178,12 +181,18 @@ class Lighting(FastAPI): if twofa_code: logging.info("Retrying Cync login with 2FA code.") try: - self.cync_user = await self.auth.login(two_factor_code=twofa_code) + self.cync_user = await self.auth.login( + two_factor_code=twofa_code + ) self._save_cached_user(self.cync_user) logging.info("Logged in with 2FA successfully.") except Exception as e: logging.error("Cync 2FA login failed: %s", e) - logging.info("2FA failure details: Code=%s, User=%s", twofa_code, self.cync_user) + logging.info( + "2FA failure details: Code=%s, User=%s", + twofa_code, + self.cync_user, + ) raise Exception("Cync 2FA code invalid or not accepted.") else: logging.error("Cync 2FA required but no code provided.") @@ -191,7 +200,7 @@ class Lighting(FastAPI): except AuthFailedError as e: logging.error("Failed to authenticate with Cync API: %s", e) raise Exception("Cync authentication failed.") - + # Create new Cync API instance try: logging.info("Creating Cync API instance...") @@ -202,7 +211,7 @@ class Lighting(FastAPI): logging.error("Failed to create Cync API instance") logging.error("Exception details: %s", str(e)) logging.error("Traceback:\n%s", traceback.format_exc()) - + # Save diagnostic info diagnostic_data = { "timestamp": datetime.now().isoformat(), @@ -210,27 +219,47 @@ class Lighting(FastAPI): "error_message": str(e), "auth_state": { "has_auth": bool(self.auth), - "has_user": bool(getattr(self.auth, 'user', None)), + "has_user": bool(getattr(self.auth, "user", None)), "user_state": { - "access_token": _mask_token(getattr(self.auth.user, 'access_token', None)) if self.auth and self.auth.user else None, - "refresh_token": _mask_token(getattr(self.auth.user, 'refresh_token', None)) if self.auth and self.auth.user else None, - "expires_at": getattr(self.auth.user, 'expires_at', None) if self.auth and self.auth.user else None - } if self.auth and self.auth.user else None - } + "access_token": _mask_token( + getattr(self.auth.user, "access_token", None) + ) + if self.auth and self.auth.user + else None, + "refresh_token": _mask_token( + getattr(self.auth.user, "refresh_token", None) + ) + if self.auth and self.auth.user + else None, + "expires_at": getattr(self.auth.user, "expires_at", None) + if self.auth and self.auth.user + else None, + } + if self.auth and self.auth.user + else None, + }, } diagnostic_file = f"cync_api_failure-{int(time.time())}.json" try: - with open(diagnostic_file, 'w') as f: + with open(diagnostic_file, "w") as f: json.dump(diagnostic_data, f, indent=2) - logging.info(f"Saved API creation diagnostic data to {diagnostic_file}") + logging.info( + f"Saved API creation diagnostic data to {diagnostic_file}" + ) except Exception as save_error: logging.error(f"Failed to save diagnostic data: {save_error}") raise - + # Final validation - if not self.cync_api or not self.session or getattr(self.session, "closed", True): + if ( + not self.cync_api + or not self.session + or getattr(self.session, "closed", True) + ): logging.error("Connection validation failed after setup") - _log_token_state(getattr(self.auth, 'user', None), "Failed connection validation") + _log_token_state( + getattr(self.auth, "user", None), "Failed connection validation" + ) raise Exception("Failed to establish proper Cync connection") """ @@ -296,7 +325,7 @@ class Lighting(FastAPI): except asyncio.CancelledError: logging.info("Health check task cancelled successfully") pass - + # Clean up connections await self._close_session_safely() logging.info("Cync lighting system shut down cleanly") @@ -334,45 +363,55 @@ class Lighting(FastAPI): logging.error("Auth object is not initialized.") raise Exception("Cync authentication not initialized.") try: - user = getattr(self.auth, 'user', None) + user = getattr(self.auth, "user", None) _log_token_state(user, "Before refresh attempt") - + if user and hasattr(user, "expires_at") and user.expires_at > time.time(): - refresh = getattr(self.auth, 'async_refresh_user_token', None) + refresh = getattr(self.auth, "async_refresh_user_token", None) if callable(refresh): try: logging.info("Attempting token refresh...") result = refresh() if inspect.isawaitable(result): await result - logging.info("Token refresh completed successfully (awaited)") + logging.info( + "Token refresh completed successfully (awaited)" + ) else: logging.info("Token refresh completed (non-awaitable)") except AuthFailedError as e: logging.error("Token refresh failed with AuthFailedError") logging.error("Exception details: %s", str(e)) logging.error("Traceback:\n%s", traceback.format_exc()) - + # Save diagnostic info to file diagnostic_data = { "timestamp": datetime.now().isoformat(), "error_type": "AuthFailedError", "error_message": str(e), "user_state": { - "access_token": _mask_token(getattr(user, 'access_token', None)), - "refresh_token": _mask_token(getattr(user, 'refresh_token', None)), - "expires_at": getattr(user, 'expires_at', None) - } + "access_token": _mask_token( + getattr(user, "access_token", None) + ), + "refresh_token": _mask_token( + getattr(user, "refresh_token", None) + ), + "expires_at": getattr(user, "expires_at", None), + }, } try: - diagnostic_file = f"cync_auth_failure-{int(time.time())}.json" - with open(diagnostic_file, 'w') as f: + diagnostic_file = ( + f"cync_auth_failure-{int(time.time())}.json" + ) + with open(diagnostic_file, "w") as f: json.dump(diagnostic_data, f, indent=2) logging.info(f"Saved diagnostic data to {diagnostic_file}") except Exception as save_error: - logging.error(f"Failed to save diagnostic data: {save_error}") + logging.error( + f"Failed to save diagnostic data: {save_error}" + ) raise - login = getattr(self.auth, 'login', None) + login = getattr(self.auth, "login", None) if callable(login): try: result = login() @@ -400,7 +439,11 @@ class Lighting(FastAPI): logging.info("Logged in with 2FA successfully.") except Exception as e: logging.error("Cync 2FA login failed: %s", e) - logging.info("2FA failure details: Code=%s, User=%s", twofa_code, self.cync_user) + logging.info( + "2FA failure details: Code=%s, User=%s", + twofa_code, + self.cync_user, + ) raise Exception("Cync 2FA code invalid or not accepted.") else: logging.error("Cync 2FA required but no code provided.") @@ -419,22 +462,28 @@ class Lighting(FastAPI): while True: try: await asyncio.sleep(300) # Check every 5 minutes - + # Check token expiration (refresh if less than 10 minutes left) if self.cync_user and hasattr(self.cync_user, "expires_at"): expires_at = getattr(self.cync_user, "expires_at", 0) time_until_expiry = expires_at - time.time() if time_until_expiry < 600: # Less than 10 minutes - logging.info(f"Token expires in {int(time_until_expiry/60)} minutes. Refreshing...") + logging.info( + f"Token expires in {int(time_until_expiry / 60)} minutes. Refreshing..." + ) try: await self._refresh_or_login() except Exception as e: - logging.error(f"Token refresh failed during health check: {e}") - + logging.error( + f"Token refresh failed during health check: {e}" + ) + # Test connection health if not await self._test_connection_health(): - logging.warning("Connection health check failed. Will reconnect on next API call.") - + logging.warning( + "Connection health check failed. Will reconnect on next API call." + ) + except asyncio.CancelledError: logging.info("Health check task cancelled") break @@ -548,24 +597,28 @@ class Lighting(FastAPI): # Apply to Cync device with robust retry and error handling max_retries = 3 last_exception: Exception = Exception("No attempts made") - + for attempt in range(max_retries): try: # Ensure connection before each attempt force_reconnect = attempt > 0 # Force reconnect on retries await self.ensure_cync_connection(force_reconnect=force_reconnect) - + if not self.cync_api: raise Exception("Cync API not available after connection setup") - - logging.info(f"Attempt {attempt + 1}/{max_retries}: Getting devices from Cync API...") + + logging.info( + f"Attempt {attempt + 1}/{max_retries}: Getting devices from Cync API..." + ) devices = self.cync_api.get_devices() - + if not devices: raise Exception("No devices returned from Cync API") - - logging.info(f"Devices returned: {[getattr(d, 'name', 'unnamed') for d in devices]}") - + + logging.info( + f"Devices returned: {[getattr(d, 'name', 'unnamed') for d in devices]}" + ) + light = next( ( d @@ -574,16 +627,22 @@ class Lighting(FastAPI): ), None, ) - + if not light: - available_devices = [getattr(d, 'name', 'unnamed') for d in devices] - raise Exception(f"Device '{self.cync_device_name}' not found. Available devices: {available_devices}") - - logging.info(f"Selected device: {getattr(light, 'name', 'unnamed')}") - + available_devices = [ + getattr(d, "name", "unnamed") for d in devices + ] + raise Exception( + f"Device '{self.cync_device_name}' not found. Available devices: {available_devices}" + ) + + logging.info( + f"Selected device: {getattr(light, 'name', 'unnamed')}" + ) + # Execute device operations operations_completed = [] - + # Set power if power == "on": result = await light.turn_on() @@ -591,20 +650,24 @@ class Lighting(FastAPI): else: result = await light.turn_off() operations_completed.append(f"turn_off: {result}") - + # Set brightness if "brightness" in state: result = await light.set_brightness(brightness) - operations_completed.append(f"set_brightness({brightness}): {result}") - + operations_completed.append( + f"set_brightness({brightness}): {result}" + ) + # Set color if rgb: result = await light.set_rgb(rgb) operations_completed.append(f"set_rgb({rgb}): {result}") - - logging.info(f"All operations completed successfully: {operations_completed}") + + logging.info( + f"All operations completed successfully: {operations_completed}" + ) break # Success, exit retry loop - + except ( aiohttp.ClientConnectionError, aiohttp.ClientOSError, @@ -613,7 +676,7 @@ class Lighting(FastAPI): ConnectionResetError, ConnectionError, OSError, - asyncio.TimeoutError + asyncio.TimeoutError, ) as e: last_exception = e logging.warning( @@ -621,12 +684,16 @@ class Lighting(FastAPI): ) if attempt < max_retries - 1: # Wait a bit before retry to allow network/server recovery - await asyncio.sleep(2 ** attempt) # Exponential backoff: 1s, 2s, 4s + await asyncio.sleep( + 2**attempt + ) # Exponential backoff: 1s, 2s, 4s continue - + except (AuthFailedError, TwoFactorRequiredError) as e: last_exception = e - logging.error(f"Authentication error (attempt {attempt + 1}/{max_retries}): {e}") + logging.error( + f"Authentication error (attempt {attempt + 1}/{max_retries}): {e}" + ) if attempt < max_retries - 1: # Clear cached tokens on auth errors try: @@ -636,20 +703,24 @@ class Lighting(FastAPI): pass await asyncio.sleep(1) continue - + except Exception as e: last_exception = e error_msg = f"Unexpected error (attempt {attempt + 1}/{max_retries}): {type(e).__name__}: {e}" logging.error(error_msg) - + # On unexpected errors, try reconnecting for next attempt if attempt < max_retries - 1: - logging.warning("Forcing full reconnection due to unexpected error...") + logging.warning( + "Forcing full reconnection due to unexpected error..." + ) await asyncio.sleep(1) continue - + # If we get here, all retries failed - logging.error(f"All {max_retries} attempts failed. Last error: {type(last_exception).__name__}: {last_exception}") + logging.error( + f"All {max_retries} attempts failed. Last error: {type(last_exception).__name__}: {last_exception}" + ) raise last_exception logging.info( diff --git a/endpoints/radio.py b/endpoints/radio.py index 89e7cef..de2e4f9 100644 --- a/endpoints/radio.py +++ b/endpoints/radio.py @@ -766,7 +766,7 @@ class Radio(FastAPI): # Try SR first with timeout try: - async with asyncio.timeout(10.0): # 5 second timeout + async with asyncio.timeout(10.0): # 10 second timeout lrc = await self.sr_util.get_lrc_by_artist_song( artist, title, duration=duration ) diff --git a/endpoints/rip.py b/endpoints/rip.py index 575acb5..dc7d113 100644 --- a/endpoints/rip.py +++ b/endpoints/rip.py @@ -23,6 +23,7 @@ from pydantic import BaseModel logger = logging.getLogger() logger.setLevel(logging.DEBUG) + class ValidBulkFetchRequest(BaseModel): track_ids: list[int] target: str diff --git a/lyric_search/models.py b/lyric_search/models.py index 51e006f..5e377c6 100644 --- a/lyric_search/models.py +++ b/lyric_search/models.py @@ -1,6 +1,7 @@ """ Database models for LRCLib lyrics cache. """ + import os import urllib.parse from typing import Type, AsyncGenerator @@ -24,6 +25,7 @@ Base: Type[DeclarativeMeta] = declarative_base() class Tracks(Base): # type: ignore """Tracks table - stores track metadata.""" + __tablename__ = "tracks" id = Column(Integer, primary_key=True, autoincrement=True) @@ -60,6 +62,7 @@ class Tracks(Base): # type: ignore class Lyrics(Base): # type: ignore """Lyrics table - stores lyrics content.""" + __tablename__ = "lyrics" id = Column(Integer, primary_key=True, autoincrement=True) @@ -95,11 +98,7 @@ encoded_password = urllib.parse.quote_plus(POSTGRES_PASSWORD) DATABASE_URL: str = f"postgresql+asyncpg://{POSTGRES_USER}:{encoded_password}@{POSTGRES_HOST}:{POSTGRES_PORT}/{POSTGRES_DB}" async_engine: AsyncEngine = create_async_engine( - DATABASE_URL, - pool_size=20, - max_overflow=10, - pool_pre_ping=True, - echo=False + DATABASE_URL, pool_size=20, max_overflow=10, pool_pre_ping=True, echo=False ) AsyncSessionLocal = async_sessionmaker(bind=async_engine, expire_on_commit=False) diff --git a/lyric_search/sources/genius.py b/lyric_search/sources/genius.py index 37a41b7..c1a4ef7 100644 --- a/lyric_search/sources/genius.py +++ b/lyric_search/sources/genius.py @@ -106,7 +106,7 @@ class Genius: ) if not best_match: raise InvalidGeniusResponseException("No matching result") - + logging.info("To scrape: %s", to_scrape) ((scrape_stub, track), confidence) = best_match scrape_url: str = f"{self.genius_url}{scrape_stub[1:]}" diff --git a/lyric_search/sources/lrclib.py b/lyric_search/sources/lrclib.py index 3c405de..005ad2c 100644 --- a/lyric_search/sources/lrclib.py +++ b/lyric_search/sources/lrclib.py @@ -46,7 +46,7 @@ class LRCLib: async with AsyncSessionLocal() as db: best_match = None - + # Try exact match first (fastest) result = await db.execute( select( @@ -63,7 +63,7 @@ class LRCLib: .limit(1) ) best_match = result.first() - + # If no exact match, try prefix match (faster than full ILIKE) if not best_match: result = await db.execute( @@ -81,7 +81,7 @@ class LRCLib: .limit(1) ) best_match = result.first() - + # If still no match, try full ILIKE (slowest) if not best_match: result = await db.execute( @@ -106,7 +106,7 @@ class LRCLib: returned_artist = best_match.artist_name returned_song = best_match.name - + if plain: if not best_match.plain_lyrics: logging.info("No plain lyrics available on %s", self.label) @@ -125,19 +125,18 @@ class LRCLib: input_track = f"{artist} - {song}" returned_track = f"{returned_artist} - {returned_song}" match_result = self.matcher.find_best_match( - input_track=input_track, - candidate_tracks=[(0, returned_track)] + input_track=input_track, candidate_tracks=[(0, returned_track)] ) - + if not match_result: return None - + _matched, confidence = match_result - + logging.info("Result found on %s", self.label) time_end = time.time() time_diff = time_end - time_start - + matched = LyricsResult( artist=returned_artist, song=returned_song, @@ -146,10 +145,10 @@ class LRCLib: confidence=confidence, time=time_diff, ) - + await self.redis_cache.increment_found_count(self.label) return matched - + except Exception as e: logging.error("Exception in %s: %s", self.label, str(e)) return None diff --git a/utils/sr_wrapper.py b/utils/sr_wrapper.py index cf6b36e..a81682f 100644 --- a/utils/sr_wrapper.py +++ b/utils/sr_wrapper.py @@ -795,7 +795,7 @@ class SRUtil: tracks_with_diff.sort(key=lambda x: x[1]) best_track, min_diff = tracks_with_diff[0] logging.info(f"SR: Best match duration diff: {min_diff}s") - # If the closest match is more than 5 seconds off, consider no match + # If the closest match is more than 10 seconds off, consider no match if min_diff > 10: logging.info("SR: Duration diff too large, no match") return None