"""Execution engine for Video Library Manager. This module provides safe execution of file operations with: - Dry-run mode (default): simulates operations without making changes - Execute mode: performs actual file operations (requires explicit confirmation) - Comprehensive logging of all operations - Error handling and resilience """ import json import logging from datetime import datetime from pathlib import Path from typing import Optional from uuid import uuid4 from vlm.config import Config from vlm.logging_config import get_logger, log_operation from vlm.models import ExecutionPlan, FileOperation, OperationResult, RollbackLog from vlm.quarantine import QuarantineManager from vlm.state import StateManager from vlm.transaction import TransactionLog from vlm.utils import ensure_utc, is_within_root, utc_now class ExecutionEngine: """Engine for executing file operations safely with dry-run support.""" def __init__( self, logger: Optional[logging.Logger] = None, config: Optional[Config] = None, verbose_operations: bool = False, state_manager: Optional[StateManager] = None, ): """Initialize the execution engine. Args: logger: Optional logger instance (uses default if not provided) config: Optional config (required for quarantine operations) verbose_operations: Emit per-operation dry-run logs at INFO when True state_manager: Optional state manager for updating file statuses """ self.logger = logger or get_logger() self.config = config self.verbose_operations = verbose_operations self.state_manager = state_manager self._quarantine_manager: Optional[QuarantineManager] = ( QuarantineManager(config, self.logger) if config else None ) def execute_plan( self, plan: ExecutionPlan, mode: str = "dry-run", confirmed: bool = False ) -> tuple[list[OperationResult], dict, Optional[RollbackLog]]: """Execute an execution plan with the specified mode. Args: plan: The execution plan to execute mode: Execution mode - "dry-run" (default) or "execute" confirmed: Whether execution has been explicitly confirmed (required for execute mode) Returns: Tuple of (operation results, execution summary, rollback log) - operation results: List of results for each operation - execution summary: Dict with counts of successful, failed, and skipped operations - rollback log: RollbackLog if mode is "execute", None for dry-run Raises: ValueError: If mode is invalid or execute mode used without confirmation """ # Validate mode if mode not in ("dry-run", "execute"): raise ValueError(f"Invalid mode: {mode}. Must be 'dry-run' or 'execute'") # Require confirmation for execute mode if mode == "execute" and not confirmed: raise ValueError( "Execute mode requires explicit confirmation. " "Set confirmed=True or use --confirm flag in CLI" ) log_operation( self.logger, logging.INFO, f"Starting execution in {mode} mode with {len(plan.operations)} operations", operation_type="execute" ) # Initialize transaction log for execute mode transaction_log = None if mode == "execute": log_path = Path.home() / ".vlm" / "transaction.json" try: transaction_log = TransactionLog(log_path) transaction_log.start_transaction(plan) except OSError as exc: log_operation( self.logger, logging.WARNING, f"Transaction log disabled (cannot write {log_path}): {exc}", operation_type="execute", ) transaction_log = None # Execute all operations results = [] for i, operation in enumerate(plan.operations): try: result = self.execute_operation(operation, mode) except Exception as exc: # pragma: no cover - defensive containment error_msg = ( f"Unexpected failure during {operation.operation_type}: {exc}" ) self.logger.exception( error_msg, extra={ "operation_type": "execute", "file_path": f" - {operation.source_path}", }, ) result = OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=utc_now(), ) results.append(result) # Update transaction and state logs in execute mode if mode == "execute": if transaction_log: try: transaction_log.mark_operation_complete( i, result.success, result.error_message ) except OSError as exc: log_operation( self.logger, logging.WARNING, f"Failed to update transaction log: {exc}", operation_type="execute", ) transaction_log = None # Update file state if successful and not a no-op if result.success and operation.operation_type != "no-op" and self.state_manager: new_status = "quarantined" if operation.operation_type == "quarantine" else "executed" self.state_manager.set_file_state( operation.source_path, status=new_status, reason=operation.reason ) # We could save state incrementally, but saving at the end is more efficient. # For extra safety, we'll save every 10 operations. if (i + 1) % 10 == 0: self.state_manager.save() # Finalize transaction and state if mode == "execute": if transaction_log: status = "completed" if all(r.success for r in results) else "failed" try: transaction_log.complete_transaction(status=status) except OSError as exc: log_operation( self.logger, logging.WARNING, f"Failed to finalize transaction log: {exc}", operation_type="execute", ) if self.state_manager: self.state_manager.save() # Generate execution summary summary = self._generate_execution_summary(results) # Create rollback log only in execute mode rollback_log = None if mode == "execute": # Only include successful operations in rollback log successful_operations = [r for r in results if r.success] rollback_log = RollbackLog( log_id=str(uuid4()), execution_plan_id=plan.plan_id, executed_at=utc_now(), operations=successful_operations ) log_operation( self.logger, logging.INFO, f"Created rollback log with {len(successful_operations)} successful operations", operation_type="execute" ) # Log execution summary self._log_execution_summary(summary, mode) return results, summary, rollback_log def _validate_library_root_boundaries( self, operation: FileOperation, executed_at: datetime, ) -> OperationResult | None: """Reject move/rename operations that escape the configured library root.""" if not self.config or operation.operation_type not in ("move", "rename"): return None if not is_within_root(operation.source_path, self.config.library_root): error_msg = f"Unsafe source outside library root: {operation.source_path}" log_operation( self.logger, logging.ERROR, error_msg, operation_type="execute", file_path=operation.source_path, ) return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at, ) if operation.destination_path and not is_within_root( operation.destination_path, self.config.library_root ): error_msg = ( f"Unsafe destination outside library root: {operation.destination_path}" ) log_operation( self.logger, logging.ERROR, error_msg, operation_type="execute", file_path=operation.source_path, ) return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at, ) return None def execute_operation( self, operation: FileOperation, mode: str ) -> OperationResult: """Execute a single file operation. Args: operation: The file operation to execute mode: Execution mode - "dry-run" or "execute" Returns: OperationResult with success status and any error message """ executed_at = utc_now() # Handle no-op operations if operation.operation_type == "no-op": log_operation( self.logger, logging.DEBUG, f"Skipping no-op operation: {operation.reason}", operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=True, error_message=None, executed_at=executed_at ) # Handle preserve-directory operations if operation.operation_type == "preserve-directory": log_operation( self.logger, logging.DEBUG, f"Preserving directory: {operation.reason}", operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=True, error_message=None, executed_at=executed_at ) # Handle quarantine operations (no destination_path; use QuarantineManager) if operation.operation_type == "quarantine": if not self._quarantine_manager: return OperationResult( operation=operation, success=False, error_message="Config required for quarantine operations", executed_at=executed_at ) if mode == "dry-run": level = logging.INFO if self.verbose_operations else logging.DEBUG log_operation( self.logger, level, f"[DRY-RUN] Would quarantine: {operation.source_path} ({operation.reason})", operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=True, error_message=None, executed_at=executed_at ) # Quarantine the file and return the result directly # (includes the actual quarantine destination_path for rollback) return self._quarantine_manager.quarantine_file( operation.source_path, operation.reason ) # Handle conflicted operations if operation.has_conflict: log_operation( self.logger, logging.WARNING, f"Skipping conflicted operation: {operation.conflict_reason}", operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=False, error_message=f"Conflict: {operation.conflict_reason}", executed_at=executed_at ) boundary_error = self._validate_library_root_boundaries(operation, executed_at) if boundary_error is not None: return boundary_error # Execute based on mode if mode == "dry-run": return self._simulate_operation(operation, executed_at) else: return self._perform_operation(operation, executed_at) def _simulate_operation( self, operation: FileOperation, executed_at: datetime ) -> OperationResult: """Simulate an operation in dry-run mode without making changes. Args: operation: The file operation to simulate executed_at: Timestamp of execution Returns: OperationResult indicating what would happen """ dest = operation.destination_path msg = ( f"[DRY-RUN] Would quarantine: {operation.source_path} ({operation.reason})" if operation.operation_type == "quarantine" else f"[DRY-RUN] Would {operation.operation_type}: {operation.source_path} -> {dest}" ) log_operation( self.logger, logging.INFO if self.verbose_operations else logging.DEBUG, msg, operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=True, error_message=None, executed_at=executed_at ) def _perform_operation( self, operation: FileOperation, executed_at: datetime ) -> OperationResult: """Perform an actual file operation. Args: operation: The file operation to perform executed_at: Timestamp of execution Returns: OperationResult with success status and any error message """ try: # Validate source file exists if not operation.source_path.exists(): error_msg = f"Source file does not exist: {operation.source_path}" log_operation( self.logger, logging.ERROR, error_msg, operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at ) # Create destination directory if needed if operation.destination_path: operation.destination_path.parent.mkdir(parents=True, exist_ok=True) # Perform the move/rename operation operation.source_path.rename(operation.destination_path) log_operation( self.logger, logging.INFO, f"Successfully {operation.operation_type}: " f"{operation.source_path} -> {operation.destination_path}", operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=True, error_message=None, executed_at=executed_at ) except Exception as e: error_msg = f"Failed to {operation.operation_type}: {str(e)}" log_operation( self.logger, logging.ERROR, error_msg, operation_type="execute", file_path=operation.source_path ) return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at ) def _generate_execution_summary( self, results: list[OperationResult] ) -> dict: """Generate a structured execution summary. Args: results: List of operation results Returns: Dictionary with counts of successful, failed, and skipped operations """ successful = sum(1 for r in results if r.success) failed = sum( 1 for r in results if (not r.success) and (not r.operation.has_conflict) ) skipped = sum( 1 for r in results if r.operation.operation_type == "no-op" or r.operation.has_conflict ) return { "successful": successful, "failed": failed, "skipped": skipped, "total": len(results) } def _log_execution_summary( self, summary: dict, mode: str ) -> None: """Log a summary of execution results. Args: summary: Execution summary dictionary mode: Execution mode that was used """ summary_msg = ( f"Execution summary ({mode} mode): " f"{summary['successful']} successful, {summary['failed']} failed, {summary['skipped']} skipped" ) log_operation( self.logger, logging.INFO, summary_msg, operation_type="execute" ) def save_rollback_log( self, rollback_log: RollbackLog, output_path: Path ) -> None: """Save rollback log to disk in JSON format. Args: rollback_log: The rollback log to save output_path: Path where the rollback log should be saved """ # Convert rollback log to JSON-serializable format log_data = { "vlm_schema_version": "1.0", "log_id": rollback_log.log_id, "execution_plan_id": rollback_log.execution_plan_id, "executed_at": rollback_log.executed_at.isoformat(), "operations": [ { "operation_type": op.operation.operation_type, "source_path": str(op.operation.source_path), "destination_path": str(op.operation.destination_path) if op.operation.destination_path else None, "reason": op.operation.reason, "success": op.success, "error_message": op.error_message, "executed_at": op.executed_at.isoformat() } for op in rollback_log.operations ] } # Ensure output directory exists output_path.parent.mkdir(parents=True, exist_ok=True) # Write to file with open(output_path, 'w', encoding='utf-8') as f: json.dump(log_data, f, indent=2) log_operation( self.logger, logging.INFO, f"Saved rollback log to {output_path}", operation_type="execute" ) def load_rollback_log( self, log_path: Path ) -> RollbackLog: """Load rollback log from disk. Args: log_path: Path to the rollback log JSON file Returns: RollbackLog object loaded from the file Raises: FileNotFoundError: If the log file does not exist ValueError: If the log file is invalid JSON or missing required fields """ if not log_path.exists(): raise FileNotFoundError(f"Rollback log not found: {log_path}") try: with open(log_path, 'r', encoding='utf-8') as f: log_data = json.load(f) # Reconstruct RollbackLog from JSON data operations = [] for op_data in log_data["operations"]: # Reconstruct FileOperation file_op = FileOperation( operation_type=op_data["operation_type"], source_path=Path(op_data["source_path"]), destination_path=Path(op_data["destination_path"]) if op_data["destination_path"] else None, reason=op_data["reason"], has_conflict=False, # Conflicts don't matter for rollback conflict_reason=None ) # Reconstruct OperationResult (normalize naive datetime to UTC) op_result = OperationResult( operation=file_op, success=op_data["success"], error_message=op_data["error_message"], executed_at=ensure_utc(datetime.fromisoformat(op_data["executed_at"])) ) operations.append(op_result) rollback_log = RollbackLog( log_id=log_data["log_id"], execution_plan_id=log_data["execution_plan_id"], executed_at=ensure_utc(datetime.fromisoformat(log_data["executed_at"])), operations=operations ) log_operation( self.logger, logging.INFO, f"Loaded rollback log from {log_path} with {len(operations)} operations", operation_type="rollback" ) return rollback_log except (json.JSONDecodeError, KeyError) as e: raise ValueError(f"Invalid rollback log format: {str(e)}") def rollback( self, rollback_log: RollbackLog ) -> tuple[list[OperationResult], dict]: """Rollback operations from a rollback log (best-effort). This method attempts to reverse all operations in the rollback log by moving files from their destination back to their source. Operations are processed in LIFO (Last In, First Out) order for best-effort restoration. Args: rollback_log: The rollback log containing operations to reverse Returns: Tuple of (rollback results, rollback summary) - rollback results: List of OperationResult for each rollback attempt - rollback summary: Dict with counts of successful, failed, and skipped operations """ log_operation( self.logger, logging.INFO, f"Starting rollback of {len(rollback_log.operations)} operations (LIFO order)", operation_type="rollback" ) # Reverse the operation list (LIFO order) reversed_operations = list(reversed(rollback_log.operations)) # Attempt to rollback each operation results = [] for original_result in reversed_operations: result = self._rollback_operation(original_result) results.append(result) # Generate rollback summary summary = self._generate_rollback_summary(results) # Log rollback summary self._log_rollback_summary(summary) return results, summary def _rollback_operation( self, original_result: OperationResult ) -> OperationResult: """Rollback a single operation (best-effort). Args: original_result: The original operation result to rollback Returns: OperationResult indicating success or failure of the rollback """ operation = original_result.operation executed_at = utc_now() # Skip no-op operations if operation.operation_type == "no-op": log_operation( self.logger, logging.DEBUG, "Skipping rollback of no-op operation", operation_type="rollback", file_path=operation.source_path ) return OperationResult( operation=operation, success=True, error_message=None, executed_at=executed_at ) # Handle quarantine operations using QuarantineManager if operation.operation_type == "quarantine": if not self._quarantine_manager: error_msg = "Cannot rollback quarantine: QuarantineManager not available" log_operation( self.logger, logging.ERROR, error_msg, operation_type="rollback" ) return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at ) # Use QuarantineManager to restore the file if operation.destination_path: restore_result = self._quarantine_manager.restore_from_quarantine( operation.destination_path ) return OperationResult( operation=operation, success=restore_result.success, error_message=restore_result.error_message, executed_at=executed_at ) else: error_msg = "Cannot rollback quarantine: no destination path recorded" return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at ) try: # For move/rename operations, reverse the direction # Original: source -> destination # Rollback: destination -> source if operation.destination_path and operation.destination_path.exists(): # Move file back from destination to source operation.destination_path.rename(operation.source_path) log_operation( self.logger, logging.INFO, f"Successfully rolled back: {operation.destination_path} -> {operation.source_path}", operation_type="rollback", file_path=operation.destination_path ) return OperationResult( operation=operation, success=True, error_message=None, executed_at=executed_at ) else: # Destination file doesn't exist - cannot rollback error_msg = f"Cannot rollback: destination file not found at {operation.destination_path}" log_operation( self.logger, logging.WARNING, error_msg, operation_type="rollback", file_path=operation.destination_path ) return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at ) except Exception as e: # Handle rollback failures gracefully - log and continue error_msg = f"Failed to rollback operation: {str(e)}" log_operation( self.logger, logging.ERROR, error_msg, operation_type="rollback", file_path=operation.destination_path ) return OperationResult( operation=operation, success=False, error_message=error_msg, executed_at=executed_at ) def _generate_rollback_summary( self, results: list[OperationResult] ) -> dict: """Generate a structured rollback summary. Args: results: List of rollback operation results Returns: Dictionary with counts of successful, failed, and skipped operations """ successful = sum(1 for r in results if r.success) failed = sum(1 for r in results if not r.success) skipped = sum( 1 for r in results if r.operation.operation_type == "no-op" ) return { "successful": successful, "failed": failed, "skipped": skipped, "total": len(results) } def _log_rollback_summary( self, summary: dict ) -> None: """Log a summary of rollback results. Args: summary: Rollback summary dictionary """ summary_msg = ( f"Rollback summary: " f"{summary['successful']} successful, {summary['failed']} failed, {summary['skipped']} skipped" ) log_operation( self.logger, logging.INFO, summary_msg, operation_type="rollback" )