2025-10-02 10:40:11 -04:00
|
|
|
import logging
|
|
|
|
|
import json
|
|
|
|
|
import os
|
|
|
|
|
import time
|
|
|
|
|
import aiohttp
|
2025-10-22 06:55:37 -04:00
|
|
|
import asyncio
|
2025-11-21 12:29:12 -05:00
|
|
|
import traceback
|
|
|
|
|
from datetime import datetime
|
2025-10-02 10:40:11 -04:00
|
|
|
from fastapi import FastAPI, Depends, HTTPException, Request
|
|
|
|
|
from fastapi_throttle import RateLimiter
|
|
|
|
|
from fastapi.responses import JSONResponse
|
|
|
|
|
import redis
|
|
|
|
|
from lyric_search.sources import private
|
|
|
|
|
from auth.deps import get_current_user
|
|
|
|
|
from dotenv import load_dotenv
|
2025-10-02 10:45:30 -04:00
|
|
|
from pycync.user import User # type: ignore
|
|
|
|
|
from pycync.cync import Cync as Cync # type: ignore
|
2025-10-02 10:40:11 -04:00
|
|
|
from pycync import Auth # type: ignore
|
|
|
|
|
from pycync.exceptions import TwoFactorRequiredError, AuthFailedError # type: ignore
|
2025-10-22 06:55:37 -04:00
|
|
|
import inspect
|
|
|
|
|
import getpass
|
2025-11-21 12:29:12 -05:00
|
|
|
from typing import Optional
|
|
|
|
|
|
|
|
|
|
# Configure logging to write to a file for specific events
|
|
|
|
|
logging.basicConfig(
|
|
|
|
|
filename="cync_auth_events.log",
|
|
|
|
|
level=logging.INFO,
|
2025-11-22 21:43:48 -05:00
|
|
|
format="%(asctime)s - %(levelname)s - %(message)s",
|
2025-11-21 12:29:12 -05:00
|
|
|
)
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
def _mask_token(token: Optional[str]) -> str:
|
|
|
|
|
"""Mask sensitive token data for logging, showing only first/last 4 chars."""
|
|
|
|
|
if not token or len(token) < 8:
|
|
|
|
|
return "<invalid_token>"
|
|
|
|
|
return f"{token[:4]}...{token[-4:]}"
|
|
|
|
|
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
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
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
try:
|
|
|
|
|
logging.info(
|
|
|
|
|
f"{context} - Token state: access=%s refresh=%s expires_at=%s",
|
2025-11-22 21:43:48 -05:00
|
|
|
_mask_token(getattr(user, "access_token", None)),
|
|
|
|
|
_mask_token(getattr(user, "refresh_token", None)),
|
|
|
|
|
getattr(user, "expires_at", None),
|
2025-11-21 12:29:12 -05:00
|
|
|
)
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logging.error(f"Error logging token state: {e}")
|
2025-10-02 10:40:11 -04:00
|
|
|
|
|
|
|
|
|
|
|
|
|
class Lighting(FastAPI):
|
2025-11-21 12:29:12 -05:00
|
|
|
async def _close_session_safely(self):
|
|
|
|
|
"""Safely close the current session if it exists."""
|
|
|
|
|
if self.session and not getattr(self.session, "closed", True):
|
|
|
|
|
try:
|
|
|
|
|
await self.session.close()
|
|
|
|
|
# Wait a bit for the underlying connections to close
|
|
|
|
|
await asyncio.sleep(0.1)
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logging.warning(f"Error closing session: {e}")
|
|
|
|
|
self.session = None
|
|
|
|
|
self.auth = None
|
|
|
|
|
self.cync_api = None
|
|
|
|
|
|
|
|
|
|
async def _test_connection_health(self) -> bool:
|
|
|
|
|
"""Test if the current connection is healthy by making a simple API call."""
|
2025-11-22 21:43:48 -05:00
|
|
|
if (
|
|
|
|
|
not self.cync_api
|
|
|
|
|
or not self.session
|
|
|
|
|
or getattr(self.session, "closed", True)
|
|
|
|
|
):
|
2025-11-21 12:29:12 -05:00
|
|
|
return False
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
try:
|
|
|
|
|
# Make a simple API call to test connectivity
|
|
|
|
|
devices = self.cync_api.get_devices()
|
|
|
|
|
# Just check if we get a response without errors
|
|
|
|
|
return devices is not None
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logging.warning(f"Connection health check failed: {e}")
|
|
|
|
|
return False
|
|
|
|
|
|
|
|
|
|
async def ensure_cync_connection(self, force_reconnect: bool = False):
|
2025-10-02 10:40:11 -04:00
|
|
|
"""Ensure aiohttp session and Cync API are alive, re-create if needed."""
|
|
|
|
|
# Check required environment variables
|
|
|
|
|
missing_vars = []
|
|
|
|
|
if not self.cync_email:
|
|
|
|
|
missing_vars.append("CYNC_EMAIL")
|
|
|
|
|
if not self.cync_password:
|
|
|
|
|
missing_vars.append("CYNC_PASSWORD")
|
|
|
|
|
if not self.cync_device_name:
|
|
|
|
|
missing_vars.append("CYNC_DEVICE_NAME")
|
|
|
|
|
if missing_vars:
|
2025-10-02 10:45:30 -04:00
|
|
|
raise Exception(
|
|
|
|
|
f"Missing required environment variables: {', '.join(missing_vars)}"
|
|
|
|
|
)
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-02 10:40:11 -04:00
|
|
|
# Cast to str after check to silence linter
|
|
|
|
|
cync_email: str = self.cync_email # type: ignore
|
|
|
|
|
cync_password: str = self.cync_password # type: ignore
|
|
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# If force_reconnect is True or connection is unhealthy, rebuild everything
|
|
|
|
|
if force_reconnect or not await self._test_connection_health():
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.info(
|
|
|
|
|
"Connection unhealthy or force reconnect requested. Rebuilding connection..."
|
|
|
|
|
)
|
|
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Clean up existing connection
|
|
|
|
|
await self._close_session_safely()
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Create new session with timeout configuration
|
|
|
|
|
timeout = aiohttp.ClientTimeout(total=30, connect=10)
|
|
|
|
|
connector = aiohttp.TCPConnector(
|
|
|
|
|
limit=100,
|
|
|
|
|
limit_per_host=30,
|
|
|
|
|
ttl_dns_cache=300,
|
|
|
|
|
use_dns_cache=True,
|
|
|
|
|
keepalive_timeout=60,
|
2025-11-22 21:43:48 -05:00
|
|
|
enable_cleanup_closed=True,
|
2025-11-22 21:41:12 -05:00
|
|
|
)
|
2025-11-22 21:43:48 -05:00
|
|
|
self.session = aiohttp.ClientSession(timeout=timeout, connector=connector)
|
|
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
# Load cached token and check validity
|
|
|
|
|
self.cync_user = None
|
2025-10-02 10:40:11 -04:00
|
|
|
cached_user = self._load_cached_user()
|
2025-10-22 06:55:37 -04:00
|
|
|
token_status = None
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
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
|
|
|
|
|
if cached_user.expires_at > (time.time() + buffer_time):
|
|
|
|
|
token_status = "valid"
|
2025-10-22 06:55:37 -04:00
|
|
|
else:
|
2025-11-21 12:29:12 -05:00
|
|
|
token_status = "expired"
|
2025-10-22 06:55:37 -04:00
|
|
|
else:
|
2025-11-21 12:29:12 -05:00
|
|
|
token_status = "no cached user or missing expires_at"
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
logging.info(f"Cync token status: {token_status}")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
if token_status == "valid" and cached_user is not None:
|
|
|
|
|
# Use cached token
|
2025-10-02 10:45:30 -04:00
|
|
|
self.auth = Auth(
|
|
|
|
|
session=self.session,
|
|
|
|
|
user=cached_user,
|
|
|
|
|
username=cync_email,
|
|
|
|
|
password=cync_password,
|
|
|
|
|
)
|
2025-10-22 06:55:37 -04:00
|
|
|
self.cync_user = cached_user
|
|
|
|
|
logging.info("Reusing valid cached token, no 2FA required.")
|
2025-10-02 10:40:11 -04:00
|
|
|
else:
|
2025-11-21 12:29:12 -05:00
|
|
|
# Need fresh login - clear any cached user that's expired
|
|
|
|
|
if token_status == "expired":
|
|
|
|
|
try:
|
|
|
|
|
os.remove(self.token_cache_path)
|
|
|
|
|
logging.info("Removed expired token cache")
|
|
|
|
|
except (OSError, FileNotFoundError):
|
|
|
|
|
pass
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.info("Initializing new Auth instance...")
|
2025-10-02 10:45:30 -04:00
|
|
|
self.auth = Auth(
|
2025-10-22 06:55:37 -04:00
|
|
|
session=self.session,
|
|
|
|
|
username=cync_email,
|
|
|
|
|
password=cync_password,
|
2025-10-02 10:45:30 -04:00
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
try:
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.info("Attempting fresh login...")
|
2025-10-02 10:40:11 -04:00
|
|
|
self.cync_user = await self.auth.login()
|
2025-11-21 12:29:12 -05:00
|
|
|
_log_token_state(self.cync_user, "After fresh login")
|
2025-10-02 10:40:11 -04:00
|
|
|
self._save_cached_user(self.cync_user)
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.info("Fresh login successful")
|
2025-10-02 10:40:11 -04:00
|
|
|
except TwoFactorRequiredError:
|
2025-10-22 06:55:37 -04:00
|
|
|
twofa_code = os.getenv("CYNC_2FA_CODE")
|
|
|
|
|
if not twofa_code:
|
|
|
|
|
print("Cync 2FA required. Please enter your code:")
|
|
|
|
|
twofa_code = getpass.getpass("2FA Code: ")
|
|
|
|
|
if twofa_code:
|
|
|
|
|
logging.info("Retrying Cync login with 2FA code.")
|
|
|
|
|
try:
|
2025-11-22 21:43:48 -05:00
|
|
|
self.cync_user = await self.auth.login(
|
|
|
|
|
two_factor_code=twofa_code
|
|
|
|
|
)
|
2025-10-22 06:55:37 -04:00
|
|
|
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)
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.info(
|
|
|
|
|
"2FA failure details: Code=%s, User=%s",
|
|
|
|
|
twofa_code,
|
|
|
|
|
self.cync_user,
|
|
|
|
|
)
|
2025-10-22 06:55:37 -04:00
|
|
|
raise Exception("Cync 2FA code invalid or not accepted.")
|
|
|
|
|
else:
|
|
|
|
|
logging.error("Cync 2FA required but no code provided.")
|
|
|
|
|
raise Exception("Cync 2FA required.")
|
2025-10-02 10:40:11 -04:00
|
|
|
except AuthFailedError as e:
|
2025-10-02 10:45:30 -04:00
|
|
|
logging.error("Failed to authenticate with Cync API: %s", e)
|
2025-10-02 10:40:11 -04:00
|
|
|
raise Exception("Cync authentication failed.")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Create new Cync API instance
|
|
|
|
|
try:
|
|
|
|
|
logging.info("Creating Cync API instance...")
|
|
|
|
|
_log_token_state(self.auth.user, "Before Cync.create")
|
|
|
|
|
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())
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Save diagnostic info
|
|
|
|
|
diagnostic_data = {
|
|
|
|
|
"timestamp": datetime.now().isoformat(),
|
|
|
|
|
"error_type": type(e).__name__,
|
|
|
|
|
"error_message": str(e),
|
|
|
|
|
"auth_state": {
|
|
|
|
|
"has_auth": bool(self.auth),
|
2025-11-22 21:43:48 -05:00
|
|
|
"has_user": bool(getattr(self.auth, "user", None)),
|
2025-11-21 12:29:12 -05:00
|
|
|
"user_state": {
|
2025-11-22 21:43:48 -05:00
|
|
|
"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,
|
|
|
|
|
},
|
2025-11-21 12:29:12 -05:00
|
|
|
}
|
|
|
|
|
diagnostic_file = f"cync_api_failure-{int(time.time())}.json"
|
|
|
|
|
try:
|
2025-11-22 21:43:48 -05:00
|
|
|
with open(diagnostic_file, "w") as f:
|
2025-11-21 12:29:12 -05:00
|
|
|
json.dump(diagnostic_data, f, indent=2)
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.info(
|
|
|
|
|
f"Saved API creation diagnostic data to {diagnostic_file}"
|
|
|
|
|
)
|
2025-11-21 12:29:12 -05:00
|
|
|
except Exception as save_error:
|
|
|
|
|
logging.error(f"Failed to save diagnostic data: {save_error}")
|
|
|
|
|
raise
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Final validation
|
2025-11-22 21:43:48 -05:00
|
|
|
if (
|
|
|
|
|
not self.cync_api
|
|
|
|
|
or not self.session
|
|
|
|
|
or getattr(self.session, "closed", True)
|
|
|
|
|
):
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.error("Connection validation failed after setup")
|
2025-11-22 21:43:48 -05:00
|
|
|
_log_token_state(
|
|
|
|
|
getattr(self.auth, "user", None), "Failed connection validation"
|
|
|
|
|
)
|
2025-11-21 12:29:12 -05:00
|
|
|
raise Exception("Failed to establish proper Cync connection")
|
2025-10-02 10:45:30 -04:00
|
|
|
|
2025-10-02 10:40:11 -04:00
|
|
|
"""
|
|
|
|
|
Lighting Endpoints
|
|
|
|
|
"""
|
|
|
|
|
|
|
|
|
|
def __init__(self, app: FastAPI, util, constants) -> None:
|
|
|
|
|
"""Initialize Lighting endpoints and persistent Cync connection."""
|
|
|
|
|
load_dotenv()
|
|
|
|
|
self.app: FastAPI = app
|
|
|
|
|
self.util = util
|
|
|
|
|
self.constants = constants
|
2025-10-02 10:45:30 -04:00
|
|
|
self.redis_client = redis.Redis(
|
|
|
|
|
password=private.REDIS_PW, decode_responses=True
|
|
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
self.lighting_key = "lighting:state"
|
|
|
|
|
|
|
|
|
|
# Cync config
|
|
|
|
|
self.cync_email = os.getenv("CYNC_EMAIL")
|
|
|
|
|
self.cync_password = os.getenv("CYNC_PASSWORD")
|
|
|
|
|
self.cync_device_name = os.getenv("CYNC_DEVICE_NAME")
|
|
|
|
|
self.token_cache_path = "cync_token.json"
|
|
|
|
|
self.session = None
|
|
|
|
|
self.auth = None
|
|
|
|
|
self.cync_user = None
|
|
|
|
|
self.cync_api = None
|
2025-11-21 12:29:12 -05:00
|
|
|
self.health_check_task: Optional[asyncio.Task] = None
|
2025-10-02 10:40:11 -04:00
|
|
|
|
|
|
|
|
# Set up Cync connection at startup using FastAPI event
|
|
|
|
|
@app.on_event("startup")
|
|
|
|
|
async def startup_event():
|
|
|
|
|
# Check required environment variables
|
|
|
|
|
missing_vars = []
|
|
|
|
|
if not self.cync_email:
|
|
|
|
|
missing_vars.append("CYNC_EMAIL")
|
|
|
|
|
if not self.cync_password:
|
|
|
|
|
missing_vars.append("CYNC_PASSWORD")
|
|
|
|
|
if not self.cync_device_name:
|
|
|
|
|
missing_vars.append("CYNC_DEVICE_NAME")
|
|
|
|
|
if missing_vars:
|
2025-10-02 10:45:30 -04:00
|
|
|
raise Exception(
|
|
|
|
|
f"Missing required environment variables: {', '.join(missing_vars)}"
|
|
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
# Use ensure_cync_connection which has proper token caching
|
2025-11-21 12:29:12 -05:00
|
|
|
try:
|
|
|
|
|
await self.ensure_cync_connection()
|
|
|
|
|
logging.info("Cync lighting system initialized successfully")
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logging.error(f"Failed to initialize Cync connection at startup: {e}")
|
|
|
|
|
# Don't raise - allow server to start, connection will be retried on first request
|
2025-10-22 06:55:37 -04:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Schedule periodic token validation and connection health checks
|
|
|
|
|
self.health_check_task = asyncio.create_task(self._schedule_health_checks())
|
|
|
|
|
|
|
|
|
|
@app.on_event("shutdown")
|
|
|
|
|
async def shutdown_event():
|
|
|
|
|
# Cancel health check task
|
|
|
|
|
if self.health_check_task and not self.health_check_task.done():
|
|
|
|
|
self.health_check_task.cancel()
|
|
|
|
|
try:
|
|
|
|
|
await self.health_check_task
|
|
|
|
|
except asyncio.CancelledError:
|
|
|
|
|
logging.info("Health check task cancelled successfully")
|
|
|
|
|
pass
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Clean up connections
|
|
|
|
|
await self._close_session_safely()
|
|
|
|
|
logging.info("Cync lighting system shut down cleanly")
|
2025-10-22 06:55:37 -04:00
|
|
|
|
|
|
|
|
# Register endpoints
|
2025-10-02 10:40:11 -04:00
|
|
|
self.endpoints: dict = {
|
|
|
|
|
"lighting/state": self.get_lighting_state,
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
for endpoint, handler in self.endpoints.items():
|
2025-10-22 06:55:37 -04:00
|
|
|
self.app.add_api_route(
|
2025-10-02 10:40:11 -04:00
|
|
|
f"/{endpoint}",
|
|
|
|
|
handler,
|
|
|
|
|
methods=["GET"],
|
|
|
|
|
include_in_schema=True,
|
2025-10-02 10:45:30 -04:00
|
|
|
dependencies=[
|
2025-10-15 10:10:56 -04:00
|
|
|
Depends(RateLimiter(times=25, seconds=2)),
|
2025-10-02 10:45:30 -04:00
|
|
|
Depends(get_current_user),
|
|
|
|
|
],
|
2025-10-02 10:40:11 -04:00
|
|
|
)
|
|
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
self.app.add_api_route(
|
2025-10-02 10:40:11 -04:00
|
|
|
"/lighting/state",
|
|
|
|
|
self.set_lighting_state,
|
|
|
|
|
methods=["POST"],
|
|
|
|
|
include_in_schema=True,
|
2025-10-02 10:45:30 -04:00
|
|
|
dependencies=[
|
2025-10-15 10:10:56 -04:00
|
|
|
Depends(RateLimiter(times=25, seconds=2)),
|
2025-10-02 10:45:30 -04:00
|
|
|
Depends(get_current_user),
|
|
|
|
|
],
|
2025-10-02 10:40:11 -04:00
|
|
|
)
|
|
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
async def _refresh_or_login(self):
|
|
|
|
|
if not self.auth:
|
|
|
|
|
logging.error("Auth object is not initialized.")
|
|
|
|
|
raise Exception("Cync authentication not initialized.")
|
|
|
|
|
try:
|
2025-11-22 21:43:48 -05:00
|
|
|
user = getattr(self.auth, "user", None)
|
2025-11-21 12:29:12 -05:00
|
|
|
_log_token_state(user, "Before refresh attempt")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
if user and hasattr(user, "expires_at") and user.expires_at > time.time():
|
2025-11-22 21:43:48 -05:00
|
|
|
refresh = getattr(self.auth, "async_refresh_user_token", None)
|
2025-10-22 06:55:37 -04:00
|
|
|
if callable(refresh):
|
|
|
|
|
try:
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.info("Attempting token refresh...")
|
2025-10-22 06:55:37 -04:00
|
|
|
result = refresh()
|
|
|
|
|
if inspect.isawaitable(result):
|
|
|
|
|
await result
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.info(
|
|
|
|
|
"Token refresh completed successfully (awaited)"
|
|
|
|
|
)
|
2025-10-22 06:55:37 -04:00
|
|
|
else:
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.info("Token refresh completed (non-awaitable)")
|
2025-10-22 06:55:37 -04:00
|
|
|
except AuthFailedError as e:
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.error("Token refresh failed with AuthFailedError")
|
|
|
|
|
logging.error("Exception details: %s", str(e))
|
|
|
|
|
logging.error("Traceback:\n%s", traceback.format_exc())
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Save diagnostic info to file
|
|
|
|
|
diagnostic_data = {
|
|
|
|
|
"timestamp": datetime.now().isoformat(),
|
|
|
|
|
"error_type": "AuthFailedError",
|
|
|
|
|
"error_message": str(e),
|
|
|
|
|
"user_state": {
|
2025-11-22 21:43:48 -05:00
|
|
|
"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),
|
|
|
|
|
},
|
2025-11-21 12:29:12 -05:00
|
|
|
}
|
|
|
|
|
try:
|
2025-11-22 21:43:48 -05:00
|
|
|
diagnostic_file = (
|
|
|
|
|
f"cync_auth_failure-{int(time.time())}.json"
|
|
|
|
|
)
|
|
|
|
|
with open(diagnostic_file, "w") as f:
|
2025-11-21 12:29:12 -05:00
|
|
|
json.dump(diagnostic_data, f, indent=2)
|
|
|
|
|
logging.info(f"Saved diagnostic data to {diagnostic_file}")
|
|
|
|
|
except Exception as save_error:
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.error(
|
|
|
|
|
f"Failed to save diagnostic data: {save_error}"
|
|
|
|
|
)
|
2025-11-21 12:29:12 -05:00
|
|
|
raise
|
2025-11-22 21:43:48 -05:00
|
|
|
login = getattr(self.auth, "login", None)
|
2025-10-22 06:55:37 -04:00
|
|
|
if callable(login):
|
|
|
|
|
try:
|
|
|
|
|
result = login()
|
|
|
|
|
if inspect.isawaitable(result):
|
|
|
|
|
self.cync_user = await result
|
|
|
|
|
else:
|
|
|
|
|
self.cync_user = result
|
|
|
|
|
self._save_cached_user(self.cync_user)
|
|
|
|
|
logging.info("Logged in successfully.")
|
|
|
|
|
except TwoFactorRequiredError:
|
|
|
|
|
twofa_code = os.getenv("CYNC_2FA_CODE")
|
|
|
|
|
if not twofa_code:
|
|
|
|
|
# Prompt interactively if not set
|
|
|
|
|
print("Cync 2FA required. Please enter your code:")
|
|
|
|
|
twofa_code = getpass.getpass("2FA Code: ")
|
|
|
|
|
if twofa_code:
|
|
|
|
|
logging.info("Retrying Cync login with 2FA code.")
|
|
|
|
|
try:
|
|
|
|
|
result = login(two_factor_code=twofa_code)
|
|
|
|
|
if inspect.isawaitable(result):
|
|
|
|
|
self.cync_user = await result
|
|
|
|
|
else:
|
|
|
|
|
self.cync_user = result
|
|
|
|
|
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)
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.info(
|
|
|
|
|
"2FA failure details: Code=%s, User=%s",
|
|
|
|
|
twofa_code,
|
|
|
|
|
self.cync_user,
|
|
|
|
|
)
|
2025-10-22 06:55:37 -04:00
|
|
|
raise Exception("Cync 2FA code invalid or not accepted.")
|
|
|
|
|
else:
|
|
|
|
|
logging.error("Cync 2FA required but no code provided.")
|
|
|
|
|
raise Exception("Cync 2FA required.")
|
|
|
|
|
else:
|
|
|
|
|
raise Exception("Auth object missing login method.")
|
|
|
|
|
except AuthFailedError as e:
|
|
|
|
|
logging.error("Failed to authenticate with Cync API: %s", e)
|
|
|
|
|
raise Exception("Cync authentication failed.")
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logging.error("Unexpected error during authentication: %s", e)
|
|
|
|
|
raise
|
|
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
async def _schedule_health_checks(self):
|
|
|
|
|
"""Periodic health checks and token validation."""
|
2025-10-22 06:55:37 -04:00
|
|
|
while True:
|
|
|
|
|
try:
|
2025-11-21 12:29:12 -05:00
|
|
|
await asyncio.sleep(300) # Check every 5 minutes
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# 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
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.info(
|
|
|
|
|
f"Token expires in {int(time_until_expiry / 60)} minutes. Refreshing..."
|
|
|
|
|
)
|
2025-11-21 12:29:12 -05:00
|
|
|
try:
|
|
|
|
|
await self._refresh_or_login()
|
|
|
|
|
except Exception as e:
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.error(
|
|
|
|
|
f"Token refresh failed during health check: {e}"
|
|
|
|
|
)
|
|
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Test connection health
|
|
|
|
|
if not await self._test_connection_health():
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.warning(
|
|
|
|
|
"Connection health check failed. Will reconnect on next API call."
|
|
|
|
|
)
|
|
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
except asyncio.CancelledError:
|
|
|
|
|
logging.info("Health check task cancelled")
|
|
|
|
|
break
|
2025-10-22 06:55:37 -04:00
|
|
|
except Exception as e:
|
2025-11-21 12:29:12 -05:00
|
|
|
logging.error(f"Error during periodic health check: {e}")
|
|
|
|
|
# Continue the loop even on errors
|
2025-10-22 06:55:37 -04:00
|
|
|
|
2025-10-02 10:40:11 -04:00
|
|
|
def _load_cached_user(self):
|
|
|
|
|
try:
|
|
|
|
|
if os.path.exists(self.token_cache_path):
|
|
|
|
|
with open(self.token_cache_path, "r") as f:
|
|
|
|
|
data = json.load(f)
|
|
|
|
|
return User(
|
|
|
|
|
access_token=data["access_token"],
|
|
|
|
|
refresh_token=data["refresh_token"],
|
|
|
|
|
authorize=data["authorize"],
|
|
|
|
|
user_id=data["user_id"],
|
2025-10-02 10:45:30 -04:00
|
|
|
expires_at=data["expires_at"],
|
2025-10-02 10:40:11 -04:00
|
|
|
)
|
|
|
|
|
except Exception as e:
|
2025-10-02 10:45:30 -04:00
|
|
|
logging.warning("Failed to load cached Cync user: %s", e)
|
2025-10-02 10:40:11 -04:00
|
|
|
return None
|
|
|
|
|
|
|
|
|
|
def _save_cached_user(self, user):
|
|
|
|
|
try:
|
|
|
|
|
data = {
|
|
|
|
|
"access_token": user.access_token,
|
|
|
|
|
"refresh_token": user.refresh_token,
|
|
|
|
|
"authorize": user.authorize,
|
|
|
|
|
"user_id": user.user_id,
|
2025-10-02 10:45:30 -04:00
|
|
|
"expires_at": user.expires_at,
|
2025-10-02 10:40:11 -04:00
|
|
|
}
|
|
|
|
|
with open(self.token_cache_path, "w") as f:
|
|
|
|
|
json.dump(data, f)
|
|
|
|
|
logging.info("Saved Cync user tokens to disk.")
|
|
|
|
|
except Exception as e:
|
2025-10-02 10:45:30 -04:00
|
|
|
logging.warning("Failed to save Cync user tokens: %s", e)
|
2025-10-02 10:40:11 -04:00
|
|
|
|
|
|
|
|
async def get_lighting_state(self) -> JSONResponse:
|
|
|
|
|
"""
|
|
|
|
|
Get the current lighting state.
|
|
|
|
|
|
|
|
|
|
Returns:
|
|
|
|
|
- **JSONResponse**: Contains the current lighting state.
|
|
|
|
|
"""
|
|
|
|
|
try:
|
|
|
|
|
state = self.redis_client.get(self.lighting_key)
|
|
|
|
|
if state:
|
|
|
|
|
return JSONResponse(content=json.loads(str(state)))
|
|
|
|
|
else:
|
|
|
|
|
# Default state
|
|
|
|
|
default_state = {
|
|
|
|
|
"power": "off",
|
|
|
|
|
"brightness": 50,
|
2025-10-02 10:45:30 -04:00
|
|
|
"color": {"r": 255, "g": 255, "b": 255},
|
2025-10-02 10:40:11 -04:00
|
|
|
}
|
|
|
|
|
return JSONResponse(content=default_state)
|
|
|
|
|
except Exception as e:
|
2025-10-02 10:45:30 -04:00
|
|
|
logging.error("Error getting lighting state: %s", e)
|
2025-10-02 10:40:11 -04:00
|
|
|
raise HTTPException(status_code=500, detail="Internal server error")
|
|
|
|
|
|
|
|
|
|
async def set_lighting_state(self, request: Request) -> JSONResponse:
|
|
|
|
|
"""
|
|
|
|
|
Set the lighting state and apply it to the Cync device.
|
|
|
|
|
"""
|
2025-10-22 06:55:37 -04:00
|
|
|
logging.info("=== LIGHTING STATE REQUEST RECEIVED ===")
|
2025-10-02 10:40:11 -04:00
|
|
|
try:
|
|
|
|
|
state = await request.json()
|
2025-10-22 06:55:37 -04:00
|
|
|
logging.info(f"Requested state: {state}")
|
2025-10-02 10:40:11 -04:00
|
|
|
# Validate state (basic validation)
|
|
|
|
|
if not isinstance(state, dict):
|
2025-10-02 10:45:30 -04:00
|
|
|
raise HTTPException(
|
|
|
|
|
status_code=400, detail="State must be a JSON object"
|
|
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
|
|
|
|
|
# Store in Redis
|
|
|
|
|
self.redis_client.set(self.lighting_key, json.dumps(state))
|
|
|
|
|
|
|
|
|
|
await self.ensure_cync_connection()
|
|
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
# Validate and extract state values
|
2025-10-02 10:40:11 -04:00
|
|
|
power = state.get("power", "off")
|
|
|
|
|
if power not in ["on", "off"]:
|
2025-10-02 10:45:30 -04:00
|
|
|
raise HTTPException(
|
|
|
|
|
status_code=400, detail=f"Invalid power state: {power}"
|
|
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
|
|
|
|
|
brightness = state.get("brightness", 50)
|
|
|
|
|
if not isinstance(brightness, (int, float)) or not (0 <= brightness <= 100):
|
2025-10-02 10:45:30 -04:00
|
|
|
raise HTTPException(
|
|
|
|
|
status_code=400, detail=f"Invalid brightness: {brightness}"
|
|
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
|
|
|
|
|
color = state.get("color")
|
2025-10-02 10:45:30 -04:00
|
|
|
if (
|
|
|
|
|
color
|
|
|
|
|
and isinstance(color, dict)
|
|
|
|
|
and all(k in color for k in ["r", "g", "b"])
|
|
|
|
|
):
|
2025-10-02 10:40:11 -04:00
|
|
|
rgb = (color["r"], color["g"], color["b"])
|
|
|
|
|
elif all(k in state for k in ["red", "green", "blue"]):
|
|
|
|
|
rgb = (state["red"], state["green"], state["blue"])
|
|
|
|
|
for val, name in zip(rgb, ["red", "green", "blue"]):
|
|
|
|
|
if not isinstance(val, int) or not (0 <= val <= 255):
|
2025-10-02 10:45:30 -04:00
|
|
|
raise HTTPException(
|
|
|
|
|
status_code=400, detail=f"Invalid {name} color value: {val}"
|
|
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
else:
|
|
|
|
|
rgb = None
|
|
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Apply to Cync device with robust retry and error handling
|
|
|
|
|
max_retries = 3
|
|
|
|
|
last_exception: Exception = Exception("No attempts made")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
for attempt in range(max_retries):
|
|
|
|
|
try:
|
2025-11-21 12:29:12 -05:00
|
|
|
# Ensure connection before each attempt
|
|
|
|
|
force_reconnect = attempt > 0 # Force reconnect on retries
|
|
|
|
|
await self.ensure_cync_connection(force_reconnect=force_reconnect)
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
if not self.cync_api:
|
2025-11-21 12:29:12 -05:00
|
|
|
raise Exception("Cync API not available after connection setup")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
|
|
|
|
logging.info(
|
|
|
|
|
f"Attempt {attempt + 1}/{max_retries}: Getting devices from Cync API..."
|
|
|
|
|
)
|
2025-10-15 10:10:56 -04:00
|
|
|
devices = self.cync_api.get_devices()
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
if not devices:
|
|
|
|
|
raise Exception("No devices returned from Cync API")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
|
|
|
|
logging.info(
|
|
|
|
|
f"Devices returned: {[getattr(d, 'name', 'unnamed') for d in devices]}"
|
|
|
|
|
)
|
|
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
light = next(
|
|
|
|
|
(
|
|
|
|
|
d
|
|
|
|
|
for d in devices
|
|
|
|
|
if hasattr(d, "name") and d.name == self.cync_device_name
|
|
|
|
|
),
|
|
|
|
|
None,
|
|
|
|
|
)
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
if not light:
|
2025-11-22 21:43:48 -05:00
|
|
|
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')}"
|
|
|
|
|
)
|
|
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# Execute device operations
|
|
|
|
|
operations_completed = []
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
# Set power
|
|
|
|
|
if power == "on":
|
2025-10-22 06:55:37 -04:00
|
|
|
result = await light.turn_on()
|
2025-11-21 12:29:12 -05:00
|
|
|
operations_completed.append(f"turn_on: {result}")
|
2025-10-15 10:10:56 -04:00
|
|
|
else:
|
2025-10-22 06:55:37 -04:00
|
|
|
result = await light.turn_off()
|
2025-11-21 12:29:12 -05:00
|
|
|
operations_completed.append(f"turn_off: {result}")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
# Set brightness
|
|
|
|
|
if "brightness" in state:
|
2025-10-22 06:55:37 -04:00
|
|
|
result = await light.set_brightness(brightness)
|
2025-11-22 21:43:48 -05:00
|
|
|
operations_completed.append(
|
|
|
|
|
f"set_brightness({brightness}): {result}"
|
|
|
|
|
)
|
|
|
|
|
|
2025-10-15 10:10:56 -04:00
|
|
|
# Set color
|
|
|
|
|
if rgb:
|
2025-10-22 06:55:37 -04:00
|
|
|
result = await light.set_rgb(rgb)
|
2025-11-21 12:29:12 -05:00
|
|
|
operations_completed.append(f"set_rgb({rgb}): {result}")
|
2025-11-22 21:43:48 -05:00
|
|
|
|
|
|
|
|
logging.info(
|
|
|
|
|
f"All operations completed successfully: {operations_completed}"
|
|
|
|
|
)
|
2025-10-15 10:10:56 -04:00
|
|
|
break # Success, exit retry loop
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
except (
|
|
|
|
|
aiohttp.ClientConnectionError,
|
|
|
|
|
aiohttp.ClientOSError,
|
|
|
|
|
aiohttp.ServerDisconnectedError,
|
|
|
|
|
aiohttp.ClientConnectorError,
|
|
|
|
|
ConnectionResetError,
|
|
|
|
|
ConnectionError,
|
|
|
|
|
OSError,
|
2025-11-22 21:43:48 -05:00
|
|
|
asyncio.TimeoutError,
|
2025-11-21 12:29:12 -05:00
|
|
|
) as e:
|
|
|
|
|
last_exception = e
|
|
|
|
|
logging.warning(
|
|
|
|
|
f"Connection/network error (attempt {attempt + 1}/{max_retries}): {type(e).__name__}: {e}"
|
|
|
|
|
)
|
2025-10-15 10:10:56 -04:00
|
|
|
if attempt < max_retries - 1:
|
2025-11-21 12:29:12 -05:00
|
|
|
# Wait a bit before retry to allow network/server recovery
|
2025-11-22 21:43:48 -05:00
|
|
|
await asyncio.sleep(
|
|
|
|
|
2**attempt
|
|
|
|
|
) # Exponential backoff: 1s, 2s, 4s
|
2025-11-21 12:29:12 -05:00
|
|
|
continue
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
except (AuthFailedError, TwoFactorRequiredError) as e:
|
|
|
|
|
last_exception = e
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.error(
|
|
|
|
|
f"Authentication error (attempt {attempt + 1}/{max_retries}): {e}"
|
|
|
|
|
)
|
2025-11-21 12:29:12 -05:00
|
|
|
if attempt < max_retries - 1:
|
|
|
|
|
# Clear cached tokens on auth errors
|
|
|
|
|
try:
|
|
|
|
|
os.remove(self.token_cache_path)
|
|
|
|
|
logging.info("Cleared token cache due to auth error")
|
|
|
|
|
except (OSError, FileNotFoundError):
|
|
|
|
|
pass
|
|
|
|
|
await asyncio.sleep(1)
|
|
|
|
|
continue
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-10-22 06:55:37 -04:00
|
|
|
except Exception as e:
|
2025-11-21 12:29:12 -05:00
|
|
|
last_exception = e
|
|
|
|
|
error_msg = f"Unexpected error (attempt {attempt + 1}/{max_retries}): {type(e).__name__}: {e}"
|
|
|
|
|
logging.error(error_msg)
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# On unexpected errors, try reconnecting for next attempt
|
2025-10-22 06:55:37 -04:00
|
|
|
if attempt < max_retries - 1:
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.warning(
|
|
|
|
|
"Forcing full reconnection due to unexpected error..."
|
|
|
|
|
)
|
2025-11-21 12:29:12 -05:00
|
|
|
await asyncio.sleep(1)
|
|
|
|
|
continue
|
2025-11-22 21:43:48 -05:00
|
|
|
|
2025-11-21 12:29:12 -05:00
|
|
|
# If we get here, all retries failed
|
2025-11-22 21:43:48 -05:00
|
|
|
logging.error(
|
|
|
|
|
f"All {max_retries} attempts failed. Last error: {type(last_exception).__name__}: {last_exception}"
|
|
|
|
|
)
|
2025-11-21 12:29:12 -05:00
|
|
|
raise last_exception
|
2025-10-02 10:40:11 -04:00
|
|
|
|
2025-10-02 10:45:30 -04:00
|
|
|
logging.info(
|
|
|
|
|
"Successfully applied state to device '%s': %s",
|
|
|
|
|
self.cync_device_name,
|
|
|
|
|
state,
|
|
|
|
|
)
|
|
|
|
|
return JSONResponse(
|
|
|
|
|
content={
|
|
|
|
|
"message": "Lighting state updated and applied",
|
|
|
|
|
"state": state,
|
|
|
|
|
}
|
|
|
|
|
)
|
2025-10-02 10:40:11 -04:00
|
|
|
except HTTPException:
|
|
|
|
|
raise
|
|
|
|
|
except Exception as e:
|
2025-10-02 10:45:30 -04:00
|
|
|
logging.error("Error setting lighting state: %s", e)
|
|
|
|
|
raise HTTPException(status_code=500, detail="Internal server error")
|