diff --git a/api/routes.py b/api/routes.py index af58959..6e5642e 100644 --- a/api/routes.py +++ b/api/routes.py @@ -15,6 +15,8 @@ from api.models import ( SonarrWebhook, RadarrWebhook, MaintainarrWebhook, HealthResponse, TVSeasonRequest, TVEpisodeRequest, MovieUpdateRequest, EpisodeUpdateRequest, BulkUpdateRequest ) +# Import logging utility +from utils.logging import _log # Web routes removed - handled by separate web container # Global scan status tracking for detailed progress @@ -50,7 +52,7 @@ async def _read_payload(request: Request) -> dict: return json.loads(form["payload"]) return dict(form) except Exception as e: - print(f"ERROR: Failed to read webhook payload: {e}") # Using print since _log is not available + _log("ERROR", f"Failed to read webhook payload: {e}") return {} @@ -70,7 +72,7 @@ async def sonarr_webhook(request: Request, background_tasks: BackgroundTasks, de raise HTTPException(status_code=422, detail="Empty Sonarr payload") webhook = SonarrWebhook(**payload) - print(f"INFO: Received Sonarr webhook: {webhook.eventType}") + _log("INFO", f"Received Sonarr webhook: {webhook.eventType}") if webhook.eventType not in ["Download", "Upgrade", "Rename"]: return {"status": "ignored", "reason": f"Event type {webhook.eventType} not processed"} @@ -86,7 +88,7 @@ async def sonarr_webhook(request: Request, background_tasks: BackgroundTasks, de sonarr_path = series_info.get("path", "") if not imdb_id: - print(f"ERROR: No IMDb ID for series: {series_title}") + _log("ERROR", f"No IMDb ID for series: {series_title}") return {"status": "error", "reason": "No IMDb ID"} # Find series path @@ -97,7 +99,7 @@ async def sonarr_webhook(request: Request, background_tasks: BackgroundTasks, de # Extract episode data for targeted processing episodes_data = webhook.episodes or [] - print(f"DEBUG: Initial episodes_data from webhook.episodes: {len(episodes_data)} episodes") + _log("DEBUG", f"Initial episodes_data from webhook.episodes: {len(episodes_data)} episodes") # For all webhook events, if no episodes in webhook.episodes, try to extract from episodeFile # This ensures targeted processing for single episode operations (Download, Rename, Upgrade) @@ -137,7 +139,7 @@ async def sonarr_webhook(request: Request, background_tasks: BackgroundTasks, de "title": episode_file.get("title") # Note: Not including dateAdded - we use database-first approach with Sonarr fallback }] - print(f"INFO: Extracted episode info from episodeFile for {webhook.eventType}: S{season_num:02d}E{episode_num:02d}") + _log("INFO", f"Extracted episode info from episodeFile for {webhook.eventType}: S{season_num:02d}E{episode_num:02d}") else: print(f"DEBUG: Missing season/episode numbers in episodeFile for {webhook.eventType}") @@ -241,7 +243,7 @@ async def sonarr_webhook(request: Request, background_tasks: BackgroundTasks, de processing_mode = config.tv_webhook_processing_mode if episodes_data and len(episodes_data) <= 3: # Single episode or small batch processing_mode = "targeted" - print(f"INFO: Forcing targeted mode for {len(episodes_data)} episode(s)") + _log("INFO", f"Forcing targeted mode for {len(episodes_data)} episode(s)") # Add to batch queue with TV-prefixed key to avoid movie conflicts tv_batch_key = f"tv:{imdb_id}" @@ -257,7 +259,7 @@ async def sonarr_webhook(request: Request, background_tasks: BackgroundTasks, de return {"status": "accepted", "message": f"Sonarr webhook queued for {tv_batch_key}"} except Exception as e: - print(f"ERROR: Sonarr webhook error: {e}") + _log("ERROR", f"Sonarr webhook error: {e}") raise HTTPException(status_code=422, detail=f"Invalid webhook: {e}") @@ -268,8 +270,8 @@ async def radarr_webhook(request: Request, background_tasks: BackgroundTasks, de try: payload = await _read_payload(request) - print(f"INFO: Received Radarr webhook: {payload.get('eventType', 'Unknown')}") - print(f"DEBUG: Full Radarr webhook payload: {payload}") + _log("INFO", f"Received Radarr webhook: {payload.get('eventType', 'Unknown')}") + _log("DEBUG", f"Full Radarr webhook payload: {payload}") # Filter supported event types (same as Sonarr: Download, Upgrade, Rename) event_type = payload.get('eventType', '') @@ -279,29 +281,29 @@ async def radarr_webhook(request: Request, background_tasks: BackgroundTasks, de # Extract movie info movie_data = payload.get("movie", {}) if not movie_data: - print("WARNING: No movie data in Radarr webhook") + _log("WARNING", "No movie data in Radarr webhook") return {"status": "error", "message": "No movie data"} # Get IMDb ID for batching key imdb_id = movie_data.get("imdbId", "").lower() if not imdb_id: - print("WARNING: No IMDb ID in Radarr webhook movie data") + _log("WARNING", "No IMDb ID in Radarr webhook movie data") return {"status": "error", "message": "No IMDb ID"} # Get movie path and map it movie_path = movie_data.get("folderPath") or movie_data.get("path", "") if not movie_path: - print("ERROR: No movie path in Radarr webhook") + _log("ERROR", "No movie path in Radarr webhook") return {"status": "error", "message": "No movie path provided"} # Map the path to container path container_path = path_mapper.radarr_path_to_container_path(movie_path) - print(f"DEBUG: Mapped Radarr path {movie_path} -> {container_path}") + _log("DEBUG", f"Mapped Radarr path {movie_path} -> {container_path}") # CRITICAL: Verify the mapped path actually exists if not Path(container_path).exists(): - print(f"ERROR: RADARR WEBHOOK REJECTED: Mapped path does not exist: {container_path}") - print(f"ERROR: This prevents processing wrong movies due to path mapping issues") + _log("ERROR", f"RADARR WEBHOOK REJECTED: Mapped path does not exist: {container_path}") + _log("ERROR", "This prevents processing wrong movies due to path mapping issues") return {"status": "error", "message": f"Mapped movie path does not exist: {container_path}"} # Verify the path contains the expected IMDb ID @@ -318,13 +320,13 @@ async def radarr_webhook(request: Request, background_tasks: BackgroundTasks, de # Add to batch queue with movie-prefixed key to avoid TV conflicts movie_batch_key = f"movie:{imdb_id}" - print(f"DEBUG: Adding Radarr webhook to batch: key={movie_batch_key}, movie_title={movie_data.get('title', 'Unknown')}") + _log("DEBUG", f"Adding Radarr webhook to batch: key={movie_batch_key}, movie_title={movie_data.get('title', 'Unknown')}") batcher.add_webhook(movie_batch_key, movie_webhook_data, "movie") return {"status": "success", "message": f"Radarr webhook queued for {movie_batch_key}"} except Exception as e: - print(f"ERROR: Radarr webhook error: {e}") + _log("ERROR", f"Radarr webhook error: {e}") return {"status": "error", "message": str(e)} @@ -339,8 +341,8 @@ async def maintainarr_webhook(request: Request, background_tasks: BackgroundTask raise HTTPException(status_code=422, detail="Empty Maintainarr payload") webhook = MaintainarrWebhook(**payload) - print(f"INFO: Received Maintainarr webhook: {webhook.notification_type}") - print(f"DEBUG: Full Maintainarr webhook payload: {payload}") + _log("INFO", f"Received Maintainarr webhook: {webhook.notification_type}") + _log("DEBUG", f"Full Maintainarr webhook payload: {payload}") # Handle test notifications differently for debugging notification_type = webhook.notification_type or "" @@ -385,7 +387,7 @@ async def maintainarr_webhook(request: Request, background_tasks: BackgroundTask break if not imdb_id: - print(f"WARNING: No IMDb ID found in Maintainarr webhook - Message: '{message}', Subject: '{subject}'") + _log("WARNING", f"No IMDb ID found in Maintainarr webhook - Message: '{message}', Subject: '{subject}'") return {"status": "ignored", "reason": "No IMDb ID found in webhook payload"} # Try to extract title from subject or message @@ -414,7 +416,7 @@ async def maintainarr_webhook(request: Request, background_tasks: BackgroundTask elif movie: media_type = "Movie" else: - print(f"INFO: Media {title} ({imdb_id}) not found in database") + _log("INFO", f"Media {title} ({imdb_id}) not found in database") return {"status": "ignored", "reason": f"Media {imdb_id} not found in database"} # Process deletion based on media type @@ -422,7 +424,7 @@ async def maintainarr_webhook(request: Request, background_tasks: BackgroundTask removed_items = [] if media_type == "Movie": - print(f"INFO: Processing movie deletion for {title} ({imdb_id})") + _log("INFO", f"Processing movie deletion for {title} ({imdb_id})") # Check if movie exists in database movie = db.get_movie_by_imdb(imdb_id) @@ -430,14 +432,14 @@ async def maintainarr_webhook(request: Request, background_tasks: BackgroundTask if db.delete_movie(imdb_id): removed_count += 1 removed_items.append(f"Movie: {title} ({imdb_id})") - print(f"SUCCESS: Removed movie {title} ({imdb_id}) from database") + _log("INFO", f"SUCCESS: Removed movie {title} ({imdb_id}) from database") else: - print(f"WARNING: Failed to remove movie {title} ({imdb_id}) from database") + _log("WARNING", f"Failed to remove movie {title} ({imdb_id}) from database") else: - print(f"INFO: Movie {title} ({imdb_id}) not found in database") + _log("INFO", f"Movie {title} ({imdb_id}) not found in database") elif media_type == "Series": - print(f"INFO: Processing series deletion for {title} ({imdb_id})") + _log("INFO", f"Processing series deletion for {title} ({imdb_id})") # Check if series exists in database series = db.get_series_by_imdb(imdb_id) @@ -453,11 +455,11 @@ async def maintainarr_webhook(request: Request, background_tasks: BackgroundTask if db.delete_series(imdb_id): removed_count += 1 removed_items.append(f"Series: {title} ({imdb_id})") - print(f"SUCCESS: Removed series {title} ({imdb_id}) from database") + _log("INFO", f"SUCCESS: Removed series {title} ({imdb_id}) from database") else: - print(f"WARNING: Failed to remove series {title} ({imdb_id}) from database") + _log("WARNING", f"Failed to remove series {title} ({imdb_id}) from database") else: - print(f"INFO: Series {title} ({imdb_id}) not found in database") + _log("INFO", f"Series {title} ({imdb_id}) not found in database") # Log the cleanup operation if removed_count > 0: @@ -481,9 +483,9 @@ async def maintainarr_webhook(request: Request, background_tasks: BackgroundTask } except Exception as e: - print(f"ERROR: Maintainarr webhook error: {e}") + _log("ERROR", f"Maintainarr webhook error: {e}") import traceback - print(f"ERROR: Traceback: {traceback.format_exc()}") + _log("ERROR", f"Traceback: {traceback.format_exc()}") return {"status": "error", "message": str(e)} @@ -495,7 +497,7 @@ async def _log_maintainarr_cleanup(event_type: str, media_type: str, title: str, log_message += f" from collection '{collection_name}'" log_message += f". Removed from database: {', '.join(removed_items)}" - print(f"INFO: {log_message}") + _log("INFO", log_message) # Could extend this to write to a cleanup log file or database table @@ -2261,63 +2263,7 @@ async def lookup_episode(imdb_id: str, season: int, episode: int, dependencies: else: dateadded_str = str(dateadded) - # AUTO-FIX: Update NFO file with missing dateadded element - try: - nfo_manager = dependencies.get("nfo_manager") - config = dependencies.get("config") - if nfo_manager and config: - print(f"DEBUG: Auto-fixing NFO for episode {imdb_id} S{season:02d}E{episode:02d}") - - # Find the series directory using filesystem search - from pathlib import Path - - # Search common TV library paths based on the logs we see from Emby - tv_search_paths = [ - Path("/media/TV"), - Path("/mnt/unionfs/Media/TV"), - Path("/media/tv"), - Path("/mnt/unionfs/Media/TV/tv"), - Path("/mnt/unionfs/Media/TV/tv6") - ] - - # Look for series directory with IMDb ID pattern - pattern = f"*[imdb-{imdb_id}]*" - series_matches = [] - - for search_path in tv_search_paths: - if search_path.exists(): - matches = list(search_path.glob(f"**/{pattern}")) - series_matches.extend(matches) - if matches: - break # Use first successful search path - - if series_matches: - series_dir = series_matches[0] # Take first match - season_dir = series_dir / config.get_season_dir_name(season) - - if season_dir.exists(): - print(f"DEBUG: Found season directory: {season_dir}") - - # Use NFO manager to update the episode NFO file - nfo_manager.create_episode_nfo( - season_dir, - season, - episode, - imdb_id, - dateadded, - result.get('aired'), - source=f"NFOGuard auto-fix via Emby lookup - {result.get('source', 'database')}" - ) - print(f"SUCCESS: Auto-fixed NFO file for {imdb_id} S{season:02d}E{episode:02d}") - else: - print(f"WARNING: Season directory not found: {season_dir}") - else: - print(f"WARNING: Series directory not found for {imdb_id} in any search paths: {[str(p) for p in tv_search_paths]}") - else: - print(f"DEBUG: Auto-fix skipped - nfo_manager: {nfo_manager is not None}, config: {config is not None}") - except Exception as fix_error: - print(f"WARNING: Auto-fix failed for {imdb_id} S{season:02d}E{episode:02d}: {fix_error}") - # Don't fail the lookup if auto-fix fails + # NOTE: Auto-fix functionality removed - just return database data return { "found": True, @@ -2327,7 +2273,7 @@ async def lookup_episode(imdb_id: str, season: int, episode: int, dependencies: "dateadded": dateadded_str, "source": result.get('source', 'database'), "air_date": result.get('air_date') if result.get('air_date') else None, - "auto_fixed": True # Indicate that we attempted auto-fix + "auto_fixed": False # Auto-fix functionality disabled } else: # Not found in database @@ -2375,58 +2321,7 @@ async def lookup_movie(imdb_id: str, dependencies: dict): else: dateadded_str = str(dateadded) - # AUTO-FIX: Update NFO file with missing dateadded element - try: - nfo_manager = dependencies.get("nfo_manager") - config = dependencies.get("config") - if nfo_manager and config: - print(f"DEBUG: Auto-fixing NFO for movie {imdb_id}") - - # Find the movie directory using filesystem search - from pathlib import Path - - # Search common movie library paths - movie_search_paths = [ - Path("/media/Movies"), - Path("/mnt/unionfs/Media/Movies"), - Path("/media/movies") - ] - - # Look for movie directory with IMDb ID pattern - pattern = f"*[imdb-{imdb_id}]*" - movie_matches = [] - - for search_path in movie_search_paths: - if search_path.exists(): - matches = list(search_path.glob(f"**/{pattern}")) - movie_matches.extend(matches) - if matches: - break # Use first successful search path - - if movie_matches: - movie_dir = movie_matches[0] # Take first match - - if movie_dir.exists(): - print(f"DEBUG: Found movie directory: {movie_dir}") - - # Use NFO manager to update the movie NFO file - nfo_manager.create_movie_nfo( - movie_dir, - imdb_id, - dateadded, - result.get('released'), - source=f"NFOGuard auto-fix via Emby lookup - {result.get('source', 'database')}" - ) - print(f"SUCCESS: Auto-fixed NFO file for movie {imdb_id}") - else: - print(f"WARNING: Movie directory not found: {movie_dir}") - else: - print(f"WARNING: Movie directory not found for {imdb_id} in any search paths: {[str(p) for p in movie_search_paths]}") - else: - print(f"DEBUG: Auto-fix skipped - nfo_manager: {nfo_manager is not None}, config: {config is not None}") - except Exception as fix_error: - print(f"WARNING: Auto-fix failed for movie {imdb_id}: {fix_error}") - # Don't fail the lookup if auto-fix fails + # NOTE: Auto-fix functionality removed - just return database data return { "found": True, @@ -2434,7 +2329,7 @@ async def lookup_movie(imdb_id: str, dependencies: dict): "dateadded": dateadded_str, "source": result.get('source', 'database'), "released": result.get('released') if result.get('released') else None, - "auto_fixed": True # Indicate that we attempted auto-fix + "auto_fixed": False # Auto-fix functionality disabled } else: # Not found in database diff --git a/utils/logging.py b/utils/logging.py index c89c135..c1a4c05 100644 --- a/utils/logging.py +++ b/utils/logging.py @@ -10,6 +10,49 @@ from datetime import datetime, timezone from zoneinfo import ZoneInfo +class SafeRotatingFileHandler(logging.handlers.RotatingFileHandler): + """A RotatingFileHandler that handles missing backup files gracefully""" + + def doRollover(self): + """ + Override doRollover to handle missing backup files gracefully + """ + if self.stream: + self.stream.close() + self.stream = None + + if self.backupCount > 0: + # Remove the oldest backup if it exists + oldest_backup = f"{self.baseFilename}.{self.backupCount}" + if os.path.exists(oldest_backup): + try: + os.remove(oldest_backup) + except (OSError, FileNotFoundError): + pass # Ignore if file doesn't exist or can't be removed + + # Rename existing backups, skipping missing ones + for i in range(self.backupCount - 1, 0, -1): + sfn = f"{self.baseFilename}.{i}" + dfn = f"{self.baseFilename}.{i + 1}" + if os.path.exists(sfn): + try: + os.rename(sfn, dfn) + except (OSError, FileNotFoundError): + pass # Skip if source doesn't exist or rename fails + + # Rename the main log file + dfn = f"{self.baseFilename}.1" + if os.path.exists(self.baseFilename): + try: + os.rename(self.baseFilename, dfn) + except (OSError, FileNotFoundError): + pass # Skip if main file doesn't exist + + # Open the new log file + if not self.delay: + self.stream = self._open() + + class TimezoneAwareFormatter(logging.Formatter): """Formatter that respects the container timezone""" def __init__(self, *args, **kwargs): @@ -50,15 +93,32 @@ def _setup_file_logging(): logger = logging.getLogger("NFOGuard") logger.setLevel(logging.DEBUG) - file_handler = logging.handlers.RotatingFileHandler( - log_dir / "nfoguard.log", maxBytes=50*1024*1024, backupCount=3 - ) + # Clear any existing handlers to avoid duplicates + logger.handlers.clear() + + try: + file_handler = SafeRotatingFileHandler( + log_dir / "nfoguard.log", maxBytes=50*1024*1024, backupCount=3 + ) + + formatter = TimezoneAwareFormatter( + '[%(asctime)s] %(levelname)s: %(message)s' + ) + file_handler.setFormatter(formatter) + logger.addHandler(file_handler) + except Exception as e: + # If RotatingFileHandler fails, fall back to regular FileHandler + print(f"Warning: Could not setup rotating file handler ({e}), using regular file handler") + try: + file_handler = logging.FileHandler(log_dir / "nfoguard.log") + formatter = TimezoneAwareFormatter( + '[%(asctime)s] %(levelname)s: %(message)s' + ) + file_handler.setFormatter(formatter) + logger.addHandler(file_handler) + except Exception as e2: + print(f"Error: Could not setup any file logging: {e2}") - formatter = TimezoneAwareFormatter( - '[%(asctime)s] %(levelname)s: %(message)s' - ) - file_handler.setFormatter(formatter) - logger.addHandler(file_handler) return logger