From 3d0b867427c26d1209b62eba9a518c0dfffb861b Mon Sep 17 00:00:00 2001 From: codey Date: Sat, 22 Nov 2025 21:41:12 -0500 Subject: [PATCH] Misc --- add_trgm_indexes.sql | 0 endpoints/lighting.py | 329 ++++++++---------------------- endpoints/lyric_search.py | 3 +- endpoints/radio.py | 4 +- endpoints/rip.py | 2 + lyric_search/sources/aggregate.py | 8 +- 6 files changed, 97 insertions(+), 249 deletions(-) create mode 100644 add_trgm_indexes.sql diff --git a/add_trgm_indexes.sql b/add_trgm_indexes.sql new file mode 100644 index 0000000..e69de29 diff --git a/endpoints/lighting.py b/endpoints/lighting.py index 9a36e94..9c3c18a 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,13 +69,9 @@ 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() @@ -99,20 +95,18 @@ 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( @@ -121,15 +115,18 @@ 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 @@ -139,9 +136,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( @@ -160,7 +157,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, @@ -181,18 +178,12 @@ 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.") @@ -200,84 +191,18 @@ 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...") _log_token_state(self.auth.user, "Before Cync.create") - - # Check if token needs refresh before API creation - now = time.time() - expires_at = getattr(self.auth.user, "expires_at", 0) - time_until_expiry = expires_at - now - logging.info( - f"Token expires in {int(time_until_expiry / 60)} minutes (at {datetime.fromtimestamp(expires_at).isoformat()})" - ) - - # Always try refresh if we're reusing a cached token - if token_status == "valid": - logging.info("Testing cached token with refresh attempt") - try: - refresh = getattr(self.auth, "async_refresh_user_token", None) - if callable(refresh): - # Log session state before refresh - if hasattr(self.session, "cookie_jar"): - try: - cookie_count = len(self.session.cookie_jar) - logging.info( - f"Session has {cookie_count} cookies before refresh" - ) - except Exception as cookie_e: - logging.warning( - f"Could not check cookies: {cookie_e}" - ) - - result = refresh() - if inspect.isawaitable(result): - try: - await result - logging.info("Token refresh test succeeded") - except AuthFailedError: - logging.warning( - "Cached token rejected by server despite being valid locally" - ) - # Clear cached token and force fresh login - try: - os.remove(self.token_cache_path) - logging.info("Cleared rejected token cache") - except (OSError, FileNotFoundError): - pass - - logging.info( - "Attempting fresh login after refresh rejection..." - ) - self.auth = Auth( - session=self.session, - username=cync_email, - password=cync_password, - ) - self.cync_user = await self.auth.login() - self._save_cached_user(self.cync_user) - logging.info( - "Fresh login successful after refresh rejection" - ) - else: - logging.warning( - "Refresh method returned non-awaitable result" - ) - except Exception as refresh_e: - logging.error(f"Pre-API refresh failed: {refresh_e}") - logging.error( - "Refresh error traceback:\n%s", traceback.format_exc() - ) - self.cync_api = await Cync.create(self.auth) logging.info("Cync API connection established successfully") except Exception as e: 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(), @@ -285,63 +210,27 @@ 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, - "time_until_expiry_minutes": int( - (getattr(self.auth.user, "expires_at", 0) - time.time()) - / 60 - ) - if self.auth and self.auth.user - else None, - "refresh_method_exists": hasattr( - self.auth, "async_refresh_user_token" - ) - if self.auth - else False, - "refresh_method_callable": callable( - getattr(self.auth, "async_refresh_user_token", None) - ) - if self.auth - else False, - } - 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") """ @@ -407,7 +296,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") @@ -445,55 +334,45 @@ 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() @@ -521,11 +400,7 @@ 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.") @@ -544,28 +419,22 @@ 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 @@ -679,28 +548,24 @@ 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 @@ -709,22 +574,16 @@ 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() @@ -732,24 +591,20 @@ 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, @@ -758,7 +613,7 @@ class Lighting(FastAPI): ConnectionResetError, ConnectionError, OSError, - asyncio.TimeoutError, + asyncio.TimeoutError ) as e: last_exception = e logging.warning( @@ -766,16 +621,12 @@ 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: @@ -785,24 +636,20 @@ 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/lyric_search.py b/endpoints/lyric_search.py index 6e75fe0..feba254 100644 --- a/endpoints/lyric_search.py +++ b/endpoints/lyric_search.py @@ -1,4 +1,3 @@ -import logging import os import urllib.parse import regex @@ -187,7 +186,7 @@ class LyricSearch(FastAPI): }, ) - excluded_sources: Optional[list] = data.excluded_sources + excluded_sources: list = data.excluded_sources or [] aggregate_search = aggregate.Aggregate(exclude_methods=excluded_sources) plain_lyrics: bool = not data.lrc result: Optional[Union[LyricsResult, dict]] = await aggregate_search.search( diff --git a/endpoints/radio.py b/endpoints/radio.py index f25cfbc..89e7cef 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(5.0): # 5 second timeout + async with asyncio.timeout(10.0): # 5 second timeout lrc = await self.sr_util.get_lrc_by_artist_song( artist, title, duration=duration ) @@ -782,7 +782,7 @@ class Radio(FastAPI): # Try LRCLib as fallback with timeout try: - async with asyncio.timeout(5.0): # 5 second timeout + async with asyncio.timeout(10.0): # 10 second timeout logging.info("[LRC] Trying LRCLib fallback") lrclib_result = await self.lrclib.search(artist, title, plain=False) if lrclib_result and lrclib_result.lyrics and isinstance(lrclib_result.lyrics, str): diff --git a/endpoints/rip.py b/endpoints/rip.py index 0a9355d..575acb5 100644 --- a/endpoints/rip.py +++ b/endpoints/rip.py @@ -20,6 +20,8 @@ from lyric_search.sources import private from typing import Literal from pydantic import BaseModel +logger = logging.getLogger() +logger.setLevel(logging.DEBUG) class ValidBulkFetchRequest(BaseModel): track_ids: list[int] diff --git a/lyric_search/sources/aggregate.py b/lyric_search/sources/aggregate.py index 492ecd0..21559c3 100644 --- a/lyric_search/sources/aggregate.py +++ b/lyric_search/sources/aggregate.py @@ -68,10 +68,10 @@ class Aggregate: if plain: # do not record LRC fails try: await self.redis_cache.increment_found_count("failed") - await self.notifier.send( - "WARNING", - f"Could not find {artist} - {song} via queried sources.", - ) + # await self.notifier.send( + # "WARNING", + # f"Could not find {artist} - {song} via queried sources.", + # ) except Exception as e: traceback.print_exc() logging.info("Could not increment redis failed counter: %s", str(e))