This commit is contained in:
2025-11-22 21:41:12 -05:00
parent dcc6c7b24e
commit 3d0b867427
6 changed files with 97 additions and 249 deletions

0
add_trgm_indexes.sql Normal file
View File

View File

@@ -25,7 +25,7 @@ from typing import Optional
logging.basicConfig( logging.basicConfig(
filename="cync_auth_events.log", filename="cync_auth_events.log",
level=logging.INFO, level=logging.INFO,
format="%(asctime)s - %(levelname)s - %(message)s", format="%(asctime)s - %(levelname)s - %(message)s"
) )
@@ -35,7 +35,6 @@ def _mask_token(token: Optional[str]) -> str:
return "<invalid_token>" return "<invalid_token>"
return f"{token[:4]}...{token[-4:]}" return f"{token[:4]}...{token[-4:]}"
def _log_token_state(user, context: str): def _log_token_state(user, context: str):
"""Log masked token state for debugging.""" """Log masked token state for debugging."""
if not user: if not user:
@@ -45,14 +44,15 @@ def _log_token_state(user, context: str):
try: try:
logging.info( logging.info(
f"{context} - Token state: access=%s refresh=%s expires_at=%s", f"{context} - Token state: access=%s refresh=%s expires_at=%s",
_mask_token(getattr(user, "access_token", None)), _mask_token(getattr(user, 'access_token', None)),
_mask_token(getattr(user, "refresh_token", None)), _mask_token(getattr(user, 'refresh_token', None)),
getattr(user, "expires_at", None), getattr(user, 'expires_at', None)
) )
except Exception as e: except Exception as e:
logging.error(f"Error logging token state: {e}") logging.error(f"Error logging token state: {e}")
class Lighting(FastAPI): class Lighting(FastAPI):
async def _close_session_safely(self): async def _close_session_safely(self):
"""Safely close the current session if it exists.""" """Safely close the current session if it exists."""
@@ -69,11 +69,7 @@ class Lighting(FastAPI):
async def _test_connection_health(self) -> bool: async def _test_connection_health(self) -> bool:
"""Test if the current connection is healthy by making a simple API call.""" """Test if the current connection is healthy by making a simple API call."""
if ( if not self.cync_api or not self.session or getattr(self.session, "closed", True):
not self.cync_api
or not self.session
or getattr(self.session, "closed", True)
):
return False return False
try: try:
@@ -106,9 +102,7 @@ class Lighting(FastAPI):
# If force_reconnect is True or connection is unhealthy, rebuild everything # If force_reconnect is True or connection is unhealthy, rebuild everything
if force_reconnect or not await self._test_connection_health(): if force_reconnect or not await self._test_connection_health():
logging.info( logging.info("Connection unhealthy or force reconnect requested. Rebuilding connection...")
"Connection unhealthy or force reconnect requested. Rebuilding connection..."
)
# Clean up existing connection # Clean up existing connection
await self._close_session_safely() await self._close_session_safely()
@@ -121,9 +115,12 @@ class Lighting(FastAPI):
ttl_dns_cache=300, ttl_dns_cache=300,
use_dns_cache=True, use_dns_cache=True,
keepalive_timeout=60, 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 # Load cached token and check validity
self.cync_user = None self.cync_user = None
@@ -181,18 +178,12 @@ class Lighting(FastAPI):
if twofa_code: if twofa_code:
logging.info("Retrying Cync login with 2FA code.") logging.info("Retrying Cync login with 2FA code.")
try: try:
self.cync_user = await self.auth.login( self.cync_user = await self.auth.login(two_factor_code=twofa_code)
two_factor_code=twofa_code
)
self._save_cached_user(self.cync_user) self._save_cached_user(self.cync_user)
logging.info("Logged in with 2FA successfully.") logging.info("Logged in with 2FA successfully.")
except Exception as e: except Exception as e:
logging.error("Cync 2FA login failed: %s", e) logging.error("Cync 2FA login failed: %s", e)
logging.info( logging.info("2FA failure details: Code=%s, User=%s", twofa_code, self.cync_user)
"2FA failure details: Code=%s, User=%s",
twofa_code,
self.cync_user,
)
raise Exception("Cync 2FA code invalid or not accepted.") raise Exception("Cync 2FA code invalid or not accepted.")
else: else:
logging.error("Cync 2FA required but no code provided.") logging.error("Cync 2FA required but no code provided.")
@@ -205,72 +196,6 @@ class Lighting(FastAPI):
try: try:
logging.info("Creating Cync API instance...") logging.info("Creating Cync API instance...")
_log_token_state(self.auth.user, "Before Cync.create") _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) self.cync_api = await Cync.create(self.auth)
logging.info("Cync API connection established successfully") logging.info("Cync API connection established successfully")
except Exception as e: except Exception as e:
@@ -285,63 +210,27 @@ class Lighting(FastAPI):
"error_message": str(e), "error_message": str(e),
"auth_state": { "auth_state": {
"has_auth": bool(self.auth), "has_auth": bool(self.auth),
"has_user": bool(getattr(self.auth, "user", None)), "has_user": bool(getattr(self.auth, 'user', None)),
"user_state": { "user_state": {
"access_token": _mask_token( "access_token": _mask_token(getattr(self.auth.user, 'access_token', None)) if self.auth and self.auth.user else None,
getattr(self.auth.user, "access_token", 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 } if self.auth and self.auth.user else None
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,
},
} }
diagnostic_file = f"cync_api_failure-{int(time.time())}.json" diagnostic_file = f"cync_api_failure-{int(time.time())}.json"
try: try:
with open(diagnostic_file, "w") as f: with open(diagnostic_file, 'w') as f:
json.dump(diagnostic_data, f, indent=2) json.dump(diagnostic_data, f, indent=2)
logging.info( logging.info(f"Saved API creation diagnostic data to {diagnostic_file}")
f"Saved API creation diagnostic data to {diagnostic_file}"
)
except Exception as save_error: 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 raise
# Final validation # Final validation
if ( if not self.cync_api or not self.session or getattr(self.session, "closed", True):
not self.cync_api
or not self.session
or getattr(self.session, "closed", True)
):
logging.error("Connection validation failed after setup") logging.error("Connection validation failed after setup")
_log_token_state( _log_token_state(getattr(self.auth, 'user', None), "Failed connection validation")
getattr(self.auth, "user", None), "Failed connection validation"
)
raise Exception("Failed to establish proper Cync connection") raise Exception("Failed to establish proper Cync connection")
""" """
@@ -445,20 +334,18 @@ class Lighting(FastAPI):
logging.error("Auth object is not initialized.") logging.error("Auth object is not initialized.")
raise Exception("Cync authentication not initialized.") raise Exception("Cync authentication not initialized.")
try: try:
user = getattr(self.auth, "user", None) user = getattr(self.auth, 'user', None)
_log_token_state(user, "Before refresh attempt") _log_token_state(user, "Before refresh attempt")
if user and hasattr(user, "expires_at") and user.expires_at > time.time(): 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): if callable(refresh):
try: try:
logging.info("Attempting token refresh...") logging.info("Attempting token refresh...")
result = refresh() result = refresh()
if inspect.isawaitable(result): if inspect.isawaitable(result):
await result await result
logging.info( logging.info("Token refresh completed successfully (awaited)")
"Token refresh completed successfully (awaited)"
)
else: else:
logging.info("Token refresh completed (non-awaitable)") logging.info("Token refresh completed (non-awaitable)")
except AuthFailedError as e: except AuthFailedError as e:
@@ -472,28 +359,20 @@ class Lighting(FastAPI):
"error_type": "AuthFailedError", "error_type": "AuthFailedError",
"error_message": str(e), "error_message": str(e),
"user_state": { "user_state": {
"access_token": _mask_token( "access_token": _mask_token(getattr(user, 'access_token', None)),
getattr(user, "access_token", None) "refresh_token": _mask_token(getattr(user, 'refresh_token', None)),
), "expires_at": getattr(user, 'expires_at', None)
"refresh_token": _mask_token( }
getattr(user, "refresh_token", None)
),
"expires_at": getattr(user, "expires_at", None),
},
} }
try: try:
diagnostic_file = ( diagnostic_file = f"cync_auth_failure-{int(time.time())}.json"
f"cync_auth_failure-{int(time.time())}.json" with open(diagnostic_file, 'w') as f:
)
with open(diagnostic_file, "w") as f:
json.dump(diagnostic_data, f, indent=2) json.dump(diagnostic_data, f, indent=2)
logging.info(f"Saved diagnostic data to {diagnostic_file}") logging.info(f"Saved diagnostic data to {diagnostic_file}")
except Exception as save_error: except Exception as save_error:
logging.error( logging.error(f"Failed to save diagnostic data: {save_error}")
f"Failed to save diagnostic data: {save_error}"
)
raise raise
login = getattr(self.auth, "login", None) login = getattr(self.auth, 'login', None)
if callable(login): if callable(login):
try: try:
result = login() result = login()
@@ -521,11 +400,7 @@ class Lighting(FastAPI):
logging.info("Logged in with 2FA successfully.") logging.info("Logged in with 2FA successfully.")
except Exception as e: except Exception as e:
logging.error("Cync 2FA login failed: %s", e) logging.error("Cync 2FA login failed: %s", e)
logging.info( logging.info("2FA failure details: Code=%s, User=%s", twofa_code, self.cync_user)
"2FA failure details: Code=%s, User=%s",
twofa_code,
self.cync_user,
)
raise Exception("Cync 2FA code invalid or not accepted.") raise Exception("Cync 2FA code invalid or not accepted.")
else: else:
logging.error("Cync 2FA required but no code provided.") logging.error("Cync 2FA required but no code provided.")
@@ -550,21 +425,15 @@ class Lighting(FastAPI):
expires_at = getattr(self.cync_user, "expires_at", 0) expires_at = getattr(self.cync_user, "expires_at", 0)
time_until_expiry = expires_at - time.time() time_until_expiry = expires_at - time.time()
if time_until_expiry < 600: # Less than 10 minutes if time_until_expiry < 600: # Less than 10 minutes
logging.info( logging.info(f"Token expires in {int(time_until_expiry/60)} minutes. Refreshing...")
f"Token expires in {int(time_until_expiry / 60)} minutes. Refreshing..."
)
try: try:
await self._refresh_or_login() await self._refresh_or_login()
except Exception as e: except Exception as e:
logging.error( logging.error(f"Token refresh failed during health check: {e}")
f"Token refresh failed during health check: {e}"
)
# Test connection health # Test connection health
if not await self._test_connection_health(): if not await self._test_connection_health():
logging.warning( logging.warning("Connection health check failed. Will reconnect on next API call.")
"Connection health check failed. Will reconnect on next API call."
)
except asyncio.CancelledError: except asyncio.CancelledError:
logging.info("Health check task cancelled") logging.info("Health check task cancelled")
@@ -689,17 +558,13 @@ class Lighting(FastAPI):
if not self.cync_api: if not self.cync_api:
raise Exception("Cync API not available after connection setup") raise Exception("Cync API not available after connection setup")
logging.info( logging.info(f"Attempt {attempt + 1}/{max_retries}: Getting devices from Cync API...")
f"Attempt {attempt + 1}/{max_retries}: Getting devices from Cync API..."
)
devices = self.cync_api.get_devices() devices = self.cync_api.get_devices()
if not devices: if not devices:
raise Exception("No devices returned from Cync API") raise Exception("No devices returned from Cync API")
logging.info( logging.info(f"Devices returned: {[getattr(d, 'name', 'unnamed') for d in devices]}")
f"Devices returned: {[getattr(d, 'name', 'unnamed') for d in devices]}"
)
light = next( light = next(
( (
@@ -711,16 +576,10 @@ class Lighting(FastAPI):
) )
if not light: if not light:
available_devices = [ available_devices = [getattr(d, 'name', 'unnamed') for d in devices]
getattr(d, "name", "unnamed") for d in devices raise Exception(f"Device '{self.cync_device_name}' not found. Available devices: {available_devices}")
]
raise Exception(
f"Device '{self.cync_device_name}' not found. Available devices: {available_devices}"
)
logging.info( logging.info(f"Selected device: {getattr(light, 'name', 'unnamed')}")
f"Selected device: {getattr(light, 'name', 'unnamed')}"
)
# Execute device operations # Execute device operations
operations_completed = [] operations_completed = []
@@ -736,18 +595,14 @@ class Lighting(FastAPI):
# Set brightness # Set brightness
if "brightness" in state: if "brightness" in state:
result = await light.set_brightness(brightness) result = await light.set_brightness(brightness)
operations_completed.append( operations_completed.append(f"set_brightness({brightness}): {result}")
f"set_brightness({brightness}): {result}"
)
# Set color # Set color
if rgb: if rgb:
result = await light.set_rgb(rgb) result = await light.set_rgb(rgb)
operations_completed.append(f"set_rgb({rgb}): {result}") operations_completed.append(f"set_rgb({rgb}): {result}")
logging.info( logging.info(f"All operations completed successfully: {operations_completed}")
f"All operations completed successfully: {operations_completed}"
)
break # Success, exit retry loop break # Success, exit retry loop
except ( except (
@@ -758,7 +613,7 @@ class Lighting(FastAPI):
ConnectionResetError, ConnectionResetError,
ConnectionError, ConnectionError,
OSError, OSError,
asyncio.TimeoutError, asyncio.TimeoutError
) as e: ) as e:
last_exception = e last_exception = e
logging.warning( logging.warning(
@@ -766,16 +621,12 @@ class Lighting(FastAPI):
) )
if attempt < max_retries - 1: if attempt < max_retries - 1:
# Wait a bit before retry to allow network/server recovery # Wait a bit before retry to allow network/server recovery
await asyncio.sleep( await asyncio.sleep(2 ** attempt) # Exponential backoff: 1s, 2s, 4s
2**attempt
) # Exponential backoff: 1s, 2s, 4s
continue continue
except (AuthFailedError, TwoFactorRequiredError) as e: except (AuthFailedError, TwoFactorRequiredError) as e:
last_exception = e last_exception = e
logging.error( logging.error(f"Authentication error (attempt {attempt + 1}/{max_retries}): {e}")
f"Authentication error (attempt {attempt + 1}/{max_retries}): {e}"
)
if attempt < max_retries - 1: if attempt < max_retries - 1:
# Clear cached tokens on auth errors # Clear cached tokens on auth errors
try: try:
@@ -793,16 +644,12 @@ class Lighting(FastAPI):
# On unexpected errors, try reconnecting for next attempt # On unexpected errors, try reconnecting for next attempt
if attempt < max_retries - 1: if attempt < max_retries - 1:
logging.warning( logging.warning("Forcing full reconnection due to unexpected error...")
"Forcing full reconnection due to unexpected error..."
)
await asyncio.sleep(1) await asyncio.sleep(1)
continue continue
# If we get here, all retries failed # If we get here, all retries failed
logging.error( logging.error(f"All {max_retries} attempts failed. Last error: {type(last_exception).__name__}: {last_exception}")
f"All {max_retries} attempts failed. Last error: {type(last_exception).__name__}: {last_exception}"
)
raise last_exception raise last_exception
logging.info( logging.info(

View File

@@ -1,4 +1,3 @@
import logging
import os import os
import urllib.parse import urllib.parse
import regex 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) aggregate_search = aggregate.Aggregate(exclude_methods=excluded_sources)
plain_lyrics: bool = not data.lrc plain_lyrics: bool = not data.lrc
result: Optional[Union[LyricsResult, dict]] = await aggregate_search.search( result: Optional[Union[LyricsResult, dict]] = await aggregate_search.search(

View File

@@ -766,7 +766,7 @@ class Radio(FastAPI):
# Try SR first with timeout # Try SR first with timeout
try: 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( lrc = await self.sr_util.get_lrc_by_artist_song(
artist, title, duration=duration artist, title, duration=duration
) )
@@ -782,7 +782,7 @@ class Radio(FastAPI):
# Try LRCLib as fallback with timeout # Try LRCLib as fallback with timeout
try: 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") logging.info("[LRC] Trying LRCLib fallback")
lrclib_result = await self.lrclib.search(artist, title, plain=False) lrclib_result = await self.lrclib.search(artist, title, plain=False)
if lrclib_result and lrclib_result.lyrics and isinstance(lrclib_result.lyrics, str): if lrclib_result and lrclib_result.lyrics and isinstance(lrclib_result.lyrics, str):

View File

@@ -20,6 +20,8 @@ from lyric_search.sources import private
from typing import Literal from typing import Literal
from pydantic import BaseModel from pydantic import BaseModel
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
class ValidBulkFetchRequest(BaseModel): class ValidBulkFetchRequest(BaseModel):
track_ids: list[int] track_ids: list[int]

View File

@@ -68,10 +68,10 @@ class Aggregate:
if plain: # do not record LRC fails if plain: # do not record LRC fails
try: try:
await self.redis_cache.increment_found_count("failed") await self.redis_cache.increment_found_count("failed")
await self.notifier.send( # await self.notifier.send(
"WARNING", # "WARNING",
f"Could not find {artist} - {song} via queried sources.", # f"Could not find {artist} - {song} via queried sources.",
) # )
except Exception as e: except Exception as e:
traceback.print_exc() traceback.print_exc()
logging.info("Could not increment redis failed counter: %s", str(e)) logging.info("Could not increment redis failed counter: %s", str(e))