diff --git a/src/opsbox/backup/config.example.yaml b/src/opsbox/backup/config.example.yaml index 6dc69aa..15686e3 100644 --- a/src/opsbox/backup/config.example.yaml +++ b/src/opsbox/backup/config.example.yaml @@ -13,15 +13,17 @@ keep_last: "10" keep_daily: "21" keep_monthly: "5" ssh_key_max_retries: 12 -detailed_report: true network_host: null ssh_key: null ssh_user: null restic_password: null user_id: null deletion_threshold: null # Send warning email if more than this many files are deleted (null to disable) -alteration_threshold: null # Send warning email if more than this many files are altered (null to disable) -monitored_folders: [] # List of folders to monitor for changes (empty list to disable) +alteration_threshold: null # Send warning email if more than this many files are altered/changed (null to disable) +addition_threshold: null # Send warning email if more than this many files are newly added (null to disable) +min_source_entries: 1 # Abort the backup if the source directory has fewer than this many entries (protects against unmounted/empty sources) +check_read_data_subset: "20%" # Portion of repository data that "restic check" re-reads and verifies during maintenance (e.g. "20%", "100%", "1G") +monitored_folders: [] # Folders to watch: ANY change (added/altered/deleted file) inside triggers an alert email (empty list to disable) # Example: # - /path/to/important/folder # - /another/monitored/path diff --git a/src/opsbox/backup/config_manager.py b/src/opsbox/backup/config_manager.py index 2e71d49..a799e29 100644 --- a/src/opsbox/backup/config_manager.py +++ b/src/opsbox/backup/config_manager.py @@ -31,10 +31,19 @@ class BackupConfig: keep_daily: str = "21" keep_monthly: str = "5" ssh_key_max_retries: int = 12 - detailed_report: bool = True restic_password: str | None = None backup_title: str = "Default backupt title" + # Minimum number of entries the backup source must contain. The backup is + # aborted if fewer entries are found (protects against unmounted/empty + # sources). Defaults to 1, i.e. abort only when the source is completely empty. + min_source_entries: int = 1 + + # Fraction of the repository data that "restic check" re-reads and verifies + # during maintenance (e.g. "20%", "100%", "1G"). Higher values verify more + # data at the cost of runtime. + check_read_data_subset: str = "20%" + # Network and SSH fields network_host: str | None = None ssh_key: str | None = None @@ -44,6 +53,7 @@ class BackupConfig: # Threshold fields for warning emails deletion_threshold: int | None = None alteration_threshold: int | None = None + addition_threshold: int | None = None # Monitored folders for change alerts monitored_folders: list[str] = field(default_factory=list) @@ -54,6 +64,32 @@ def __post_init__(self) -> None: self._validate_ssh_configuration() self._validate_paths() self._validate_retention_policy() + self._validate_source_and_thresholds() + + def _validate_source_and_thresholds(self) -> None: + """Validate the source-entry minimum and change-count thresholds.""" + if not isinstance(self.min_source_entries, int) or self.min_source_entries < 0: + error_msg = ( + f"'min_source_entries' must be a non-negative integer, " + f"got: {self.min_source_entries!r}" + ) + raise InvalidResticConfigError(error_msg) + + for name in ( + "deletion_threshold", + "alteration_threshold", + "addition_threshold", + ): + value = getattr(self, name) + if value is not None and (not isinstance(value, int) or value < 0): + error_msg = ( + f"'{name}' must be a non-negative integer or null, got: {value!r}" + ) + raise InvalidResticConfigError(error_msg) + + if not str(self.check_read_data_subset).strip(): + error_msg = "'check_read_data_subset' must be a non-empty value" + raise InvalidResticConfigError(error_msg) def _validate_required_fields(self) -> None: """Validate that all required fields are present and non-empty.""" @@ -195,11 +231,16 @@ def load_config(config_path: str) -> BackupConfig: ssh_key_max_retries=int(config_data.get("ssh_key_max_retries", 12)), restic_password=config_data.get("restic_password"), user_id=config_data.get("user_id", os.getuid()), - detailed_report=config_data.get("detailed_report", True), deletion_threshold=config_data.get("deletion_threshold"), alteration_threshold=config_data.get("alteration_threshold"), + addition_threshold=config_data.get("addition_threshold"), monitored_folders=config_data.get("monitored_folders", []), backup_title=config_data.get("backup_title", "Default backup title"), + min_source_entries=int(config_data.get("min_source_entries", 1)), + check_read_data_subset=config_data.get( + "check_read_data_subset", + "20%", + ), ) except KeyError as e: @@ -238,7 +279,6 @@ def get_default_config() -> dict[str, Any]: "keep_daily": "21", "keep_monthly": "5", "ssh_key_max_retries": 12, - "detailed_report": True, "network_host": None, "ssh_key": None, "ssh_user": None, @@ -246,5 +286,8 @@ def get_default_config() -> dict[str, Any]: "user_id": None, "deletion_threshold": None, # Send warning if more than this many files deleted "alteration_threshold": None, # Send warning if more than this many files altered + "addition_threshold": None, # Send warning if more than this many files added "monitored_folders": [], # List of folders to monitor for changes + "min_source_entries": 1, # Abort backup if source has fewer entries + "check_read_data_subset": "20%", # Portion of data verified by restic check } diff --git a/src/opsbox/backup/exceptions.py b/src/opsbox/backup/exceptions.py index 815299a..8789c97 100644 --- a/src/opsbox/backup/exceptions.py +++ b/src/opsbox/backup/exceptions.py @@ -31,6 +31,15 @@ class ResticEnvNotSetError(BackupEnvironmentError): """Raised when restic environment is not properly configured.""" +class EmptySourceError(BackupEnvironmentError): + """Raised when the backup source is missing or (near) empty. + + Guards against backing up an unmounted or empty source directory, which + would otherwise create an almost empty snapshot and risk data loss once + old snapshots are pruned. + """ + + class SecurityError(BackupError): """Raised when there are security-related issues.""" @@ -71,6 +80,15 @@ class ResticCommandFailedError(ResticError): """Raised when any restic command fails.""" +class ResticRepositoryLockedError(ResticCommandFailedError): + """Raised when a restic command fails because the repository is locked. + + Subclasses :class:`ResticCommandFailedError` so existing handlers keep + working, while allowing callers to react specifically (e.g. run + ``restic unlock`` to remove stale locks and retry once). + """ + + class SnapshotIDNotFoundError(ResticError): """Raised when snapshot ID cannot be found in restic output.""" diff --git a/src/opsbox/backup/password_manager.py b/src/opsbox/backup/password_manager.py index ed666e4..5bd1e1d 100644 --- a/src/opsbox/backup/password_manager.py +++ b/src/opsbox/backup/password_manager.py @@ -129,7 +129,7 @@ def validate_password_strength(self, password: str) -> bool: # Basic validation - password should be at least MIN_PASSWORD_LENGTH characters if len(password) < self.MIN_PASSWORD_LENGTH: self.logger.warning( - f"Password is shorter than recommended minimum length ({self.MIN_PASSWORD_LENGTH} characters)", + "Password is shorter than recommended minimum length (characters)", ) return False diff --git a/src/opsbox/backup/restic_backup.py b/src/opsbox/backup/restic_backup.py index 0d61c05..1f714bc 100644 --- a/src/opsbox/backup/restic_backup.py +++ b/src/opsbox/backup/restic_backup.py @@ -2,36 +2,42 @@ import argparse import hashlib +import json import os import sys import tempfile +from collections.abc import Callable from dataclasses import dataclass from pathlib import Path +from typing import TypeVar from opsbox.backup.config_manager import ConfigManager from opsbox.backup.exceptions import ( BackupError, ConfigurationError, - DiffParsingError, + EmptySourceError, InvalidResticConfigError, MaintenanceError, NetworkUnreachableError, ResticBackupFailedError, - ResticCommandFailedError, + ResticRepositoryLockedError, SnapshotIDNotFoundError, SSHKeyNotFoundError, UserDoesNotExistError, + VerificationError, WrongOSForResticBackupError, ) from opsbox.backup.network_checker import NetworkChecker from opsbox.backup.password_manager import PasswordManager -from opsbox.backup.restic_client import ResticClient +from opsbox.backup.restic_client import ResticClient, is_lock_error from opsbox.backup.snapshot_id import ResticSnapshotId from opsbox.backup.ssh_manager import SSHManager from opsbox.encrypted_mail import EncryptedMail from opsbox.locking import LockManager from opsbox.logging import LoggingConfig, configure_logging +_T = TypeVar("_T") + @dataclass class ResticDiff: @@ -149,7 +155,27 @@ def _initialize_components(self, restic_path: str) -> None: restic_path, self.config.backup_target, self.logger, - self.encrypted_mail, + ) + + def _failure_mail_subject(self, error: BaseException) -> str: + """Pick a failure mail subject that matches the failing stage.""" + title = self.config.backup_title + if isinstance(error, VerificationError): + return f"Backup {title} verification failed" + if isinstance(error, MaintenanceError): + return f"Backup maintenance {title} failed" + return f"Backup {title} failed" + + def _send_failure_email(self, error: BaseException) -> None: + """Send a single failure notification with the full session log.""" + attachment = None + session_log = getattr(self.restic_client, "session_log", None) + if isinstance(session_log, (str, Path)) and Path(session_log).exists(): + attachment = str(session_log) + self.encrypted_mail.send_mail_with_retries( + subject=self._failure_mail_subject(error), + message=f"Backup failed: {error}", + mail_attachment=attachment, ) def run(self) -> None: @@ -158,6 +184,9 @@ def run(self) -> None: try: self.logger.info(f"Starting backup {self.config.backup_title} workflow") + # Step 0: Ensure the source is present and not empty + self._check_source_not_empty() + # Step 1: Setup environment self._setup_environment() @@ -172,12 +201,11 @@ def run(self) -> None: # Step 4: Execute backup snapshot_id = self._execute_backup() - # Step 5: Verify backup - if self._verify_backup(snapshot_id): - # Step 6: Perform maintenance - self._perform_maintenance() - else: - self._handle_verification_failure() + # Step 5: Verify backup (raises VerificationError on failure) + self._verify_backup(snapshot_id) + + # Step 6: Perform maintenance + self._perform_maintenance() self.logger.info("Backup workflow completed successfully") @@ -193,12 +221,9 @@ def run(self) -> None: message=f"Backup was skipped: {e}", ) except BackupError as e: - # Handle backup-specific errors + # Single failure notification for the whole workflow self.logger.exception("Backup failed") - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} failed", - message=f"Backup failed: {e}", - ) + self._send_failure_email(e) raise except Exception as e: # Handle unexpected errors @@ -210,6 +235,43 @@ def run(self) -> None: error_msg = f"Unexpected error: {e}" raise BackupError(error_msg, original_error=e) from e + def _check_source_not_empty(self) -> None: + """Abort the backup if the source directory is missing or (near) empty. + + Backing up an unmounted or empty source would create an almost empty + snapshot and could cause data loss once old snapshots are pruned. This + guard counts the entries in the source directory and raises if there are + fewer than ``min_source_entries``. + + Raises: + EmptySourceError: If the source is inaccessible or has too few entries + + """ + source = Path(self.config.backup_source) + self.logger.info( + f"Checking backup source {source} has at least " + f"{self.config.min_source_entries} entries", + ) + + try: + entry_count = sum(1 for _ in source.iterdir()) + except (FileNotFoundError, NotADirectoryError, PermissionError) as e: + error_msg = ( + f"Backup source is not an accessible directory: {source} ({e}). " + f"Aborting to avoid backing up a missing or unmounted source." + ) + raise EmptySourceError(error_msg) from e + + if entry_count < self.config.min_source_entries: + error_msg = ( + f"Backup source {source} contains only {entry_count} entries " + f"(minimum required: {self.config.min_source_entries}). " + f"Aborting to avoid backing up an empty or unmounted source." + ) + raise EmptySourceError(error_msg) + + self.logger.info(f"Backup source check passed ({entry_count} entries)") + def _setup_environment(self) -> None: """Set up the restic environment with password and SSH configuration.""" self.logger.info("Setting up restic environment") @@ -263,143 +325,178 @@ def _setup_ssh(self) -> None: self.config.ssh_key_max_retries, ) + def _run_with_lock_retry( + self, + operation: Callable[[], _T], + description: str, + ) -> _T: + """Run a restic operation, recovering once from a stale repository lock. + + If the operation fails because the repository is locked (e.g. a stale + lock left behind by a previously killed run), ``restic unlock`` is run + to remove stale locks and the operation is retried exactly once. If it + is still locked afterwards the error propagates so a real, concurrent + run is not silently overridden. + """ + try: + return operation() + except ResticRepositoryLockedError: + self.logger.warning( + f"Restic repository is locked during '{description}'; " + "removing stale locks and retrying once.", + ) + self.restic_client.unlock() + try: + return operation() + except ResticRepositoryLockedError: + self.logger.exception( + f"Restic repository still locked after unlock during " + f"'{description}'", + ) + raise + def _execute_backup(self) -> ResticSnapshotId: - """Execute the restic backup operation.""" + """Execute the restic backup operation and notify on success. + + Failures propagate to :meth:`run`, which sends the single failure email. + """ self.logger.info(f"Starting backup of {self.config.backup_source}") - try: - snapshot_id = self.restic_client.backup( + snapshot_id = self._run_with_lock_retry( + lambda: self.restic_client.backup( self.config.backup_source, self.config.excluded_files, - ) - - # Send success notification with diff summary - diff_summary = self._generate_diff_summary(snapshot_id) - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} successful", - message=f"Backup completed successfully.\nSnapshot ID: {snapshot_id}\n\nDiff Summary:\n{diff_summary}", - mail_attachment=str(self.restic_client.log_file), - ) - except ( - ResticBackupFailedError, - SnapshotIDNotFoundError, - ResticCommandFailedError, - ) as e: - # Send failure notification with log - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} failed", - message=f"Backup failed: {e}", - mail_attachment=str(self.restic_client.log_file) - if self.restic_client.log_file.exists() - else None, - ) - raise - else: - return snapshot_id - - def _is_section_header(self, line: str) -> bool: - """Check if a line is a section header. + ), + "backup", + ) - Args: - line: Line to check + # Send success notification with diff summary + diff_summary = self._generate_diff_summary(snapshot_id) + self.encrypted_mail.send_mail_with_retries( + subject=f"Backup {self.config.backup_title} successful", + message=( + f"Backup completed successfully.\nSnapshot ID: {snapshot_id}\n\n" + f"Diff Summary:\n{diff_summary}" + ), + mail_attachment=str(self.restic_client.session_log), + ) + return snapshot_id - Returns: - True if the line is a section header + def _parse_diff_line(self, line: str) -> dict | None: + """Parse a single line of ``restic diff --json`` output into a message. + Returns the decoded message dict, or None for blank lines, non-JSON + lines (logged as a warning) and non-dict payloads. """ - line_lower = line.lower() - return any( - word in line_lower - for word in [ - "files:", - "dirs:", - "others:", - "data blobs:", - "tree blobs:", - "summary", - ] - ) - - def _extract_file_path_from_plain_path( - self, - line: str, - ) -> Path: - """Extract file path from a plain path line in restic diff output. + line_stripped = line.strip() + if not line_stripped: + return None - Parses lines in the format: - - "M /path/to/file.txt" (modified) - - "- /path/to/file.txt" (deleted) - - "+ /path/to/file.txt" (added) + try: + message = json.loads(line_stripped) + except json.JSONDecodeError: + # stdout is captured cleanly, so any non-JSON line is unexpected + self.logger.warning( + f"Ignoring non-JSON line in diff output: {line_stripped}", + ) + return None - Args: - line: Line to parse (e.g., "M /home/user/file.txt") + if not isinstance(message, dict): + return None + return message - Returns: - File path as Path object if found, None otherwise + def _classify_change( + self, + message: dict, + *, + added_files: list[Path], + altered_files: list[Path], + deleted_files: list[Path], + ) -> None: + """Append a ``change`` message's path to the matching change list. + A single change carries one modifier; "+" added, "-" removed, "M" + content modified. Metadata-only changes (e.g. "U"/"T") are intentionally + ignored. """ - line_stripped = line.strip() - if not line_stripped: - error_msg = "Empty line in diff output" - self.logger.error(error_msg) - raise DiffParsingError(error_msg) - - # Check if line starts with M, -, or + followed by spaces - if line_stripped.startswith(("M", "-", "+")): - # Remove the prefix character and any following whitespace - path_str = line_stripped[1:].strip() - if path_str and path_str.startswith("/"): - return Path(path_str) - error_msg = f"Invalid line in diff output: {line_stripped}" - self.logger.error(error_msg) - raise DiffParsingError(error_msg) + path_str = message.get("path") + modifier = message.get("modifier", "") + if not path_str: + return + + path = Path(path_str) + if "+" in modifier: + added_files.append(path) + elif "-" in modifier: + deleted_files.append(path) + elif "M" in modifier: + altered_files.append(path) def _parse_diff_output( self, diff_output: str, snapshot_id: ResticSnapshotId, ) -> ResticDiff: - """Parse restic diff output to extract deleted, altered, and added files. + """Parse ``restic diff --json`` output into added/altered/deleted files. + + The output is newline-delimited JSON. Each change is a message of type + ``change`` with a ``path`` and a ``modifier`` string (e.g. "+", "-", + "M", or combinations such as "MU"). + + A well-formed ``restic diff --json`` run always ends with a + ``statistics`` message. If that message is missing, the diff did not + complete correctly, so the output is considered invalid and an error is + raised (the report must succeed; a broken report means something went + wrong with the run). Args: - diff_output: The raw output from restic diff command + diff_output: The raw JSON output from the restic diff command snapshot_id: The snapshot ID this diff is for Returns: ResticDiff object containing added, altered, and deleted files + Raises: + ResticBackupFailedError: If the diff output is empty or does not + contain the terminating ``statistics`` message + """ deleted_files: list[Path] = [] altered_files: list[Path] = [] added_files: list[Path] = [] + saw_statistics = False - # Handle None or empty diff output - if not diff_output: - error_msg = "No diff output found" + if not diff_output or not diff_output.strip(): + error_msg = "restic diff produced no output" self.logger.error(error_msg) raise ResticBackupFailedError(error_msg) for line in diff_output.splitlines(): - line_stripped = line.strip() - if not line_stripped: + message = self._parse_diff_line(line) + if message is None: continue - # Extract path from lines starting with M (modified), - (deleted), or + (added) - if line_stripped.startswith("-"): - # Deleted file - deleted_files.append( - self._extract_file_path_from_plain_path(line_stripped), - ) - elif line_stripped.startswith("+"): - # Modified or added file (both count as altered) - altered_files.append( - self._extract_file_path_from_plain_path(line_stripped), - ) - elif line_stripped.startswith("M"): - # Modified or added file (both count as altered) - added_files.append( - self._extract_file_path_from_plain_path(line_stripped), - ) + message_type = message.get("message_type") + if message_type == "statistics": + saw_statistics = True + continue + if message_type != "change": + continue + + self._classify_change( + message, + added_files=added_files, + altered_files=altered_files, + deleted_files=deleted_files, + ) + + if not saw_statistics: + error_msg = ( + "restic diff --json did not emit a terminating 'statistics' " + "message; the diff output is incomplete or invalid" + ) + self.logger.error(error_msg) + raise ResticBackupFailedError(error_msg) return ResticDiff( added_files=added_files, @@ -408,64 +505,114 @@ def _parse_diff_output( snapshot_id=snapshot_id, ) + def _extract_diff_statistics(self, diff_output: str) -> str: + """Extract a human-readable summary from ``restic diff --json`` output. + + Looks for the ``statistics`` message emitted at the end of the diff. + + Args: + diff_output: The raw JSON output from the restic diff command + + Returns: + A formatted summary string, or a fallback message if unavailable + + """ + for line in diff_output.splitlines(): + line_stripped = line.strip() + if not line_stripped: + continue + try: + message = json.loads(line_stripped) + except json.JSONDecodeError: + continue + if ( + not isinstance(message, dict) + or message.get("message_type") != "statistics" + ): + continue + + added = message.get("added", {}) or {} + removed = message.get("removed", {}) or {} + changed_files = message.get("changed_files") + + summary_lines = [] + if changed_files is not None: + summary_lines.append(f"Changed files: {changed_files}") + summary_lines.append( + f"Added: files={added.get('files', 0)}, " + f"dirs={added.get('dirs', 0)}, bytes={added.get('bytes', 0)}", + ) + summary_lines.append( + f"Removed: files={removed.get('files', 0)}, " + f"dirs={removed.get('dirs', 0)}, bytes={removed.get('bytes', 0)}", + ) + return "\n".join(summary_lines) + + return "No summary available." + + def _send_threshold_warning( + self, + change_type: str, + files: list[Path], + threshold: int, + snapshot_id: ResticSnapshotId, + ) -> None: + """Send a warning email because a change-count threshold was exceeded. + + Args: + change_type: The kind of change ("deleted", "altered" or "added") + files: The affected files + threshold: The configured threshold that was exceeded + snapshot_id: The snapshot ID this change belongs to + + """ + self.logger.warning( + f"{change_type.capitalize()} threshold exceeded: {len(files)} files " + f"{change_type} (threshold: {threshold})", + ) + file_list = "\n".join(str(path) for path in files[: self.MAX_FILES_IN_EMAIL]) + if len(files) > self.MAX_FILES_IN_EMAIL: + file_list += f"\n... and {len(files) - self.MAX_FILES_IN_EMAIL} more files" + self.encrypted_mail.send_mail_with_retries( + subject=( + f"Backup {self.config.backup_title} Warning: {len(files)} files " + f"{change_type} (threshold: {threshold})" + ), + message=( + f"Warning: The backup detected {len(files)} {change_type} files, " + f"which exceeds the threshold of {threshold}.\n\n" + f"Snapshot ID: {snapshot_id}\n\n" + f"{change_type.capitalize()} files:\n{file_list}" + ), + ) + def _check_thresholds_and_send_warnings( self, diff: ResticDiff, ) -> None: """Check thresholds and send warning emails if exceeded. + Deleted, altered and added files are each checked against their own + independent threshold. + Args: diff: ResticDiff object containing file changes and snapshot ID """ - # Check deletion threshold - if ( - self.config.deletion_threshold is not None - and len(diff.deleted_files) > self.config.deletion_threshold - ): - self.logger.warning( - f"Deletion threshold exceeded: {len(diff.deleted_files)} files deleted " - f"(threshold: {self.config.deletion_threshold})", - ) - deleted_list = "\n".join( - str(path) for path in diff.deleted_files[: self.MAX_FILES_IN_EMAIL] - ) # Limit to first N files - if len(diff.deleted_files) > self.MAX_FILES_IN_EMAIL: - deleted_list += f"\n... and {len(diff.deleted_files) - self.MAX_FILES_IN_EMAIL} more files" - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} Warning: {len(diff.deleted_files)} files deleted (threshold: {self.config.deletion_threshold})", - message=( - f"Warning: The backup detected {len(diff.deleted_files)} deleted files, " - f"which exceeds the threshold of {self.config.deletion_threshold}.\n\n" - f"Snapshot ID: {diff.snapshot_id}\n\n" - f"Deleted files:\n{deleted_list}" - ), - ) + threshold_checks: tuple[tuple[str, list[Path], int | None], ...] = ( + ("deleted", diff.deleted_files, self.config.deletion_threshold), + ("altered", diff.altered_files, self.config.alteration_threshold), + ("added", diff.added_files, self.config.addition_threshold), + ) - # Check alteration threshold - altered_and_added = diff.altered_files + diff.added_files - if ( - self.config.alteration_threshold is not None - and len(altered_and_added) > self.config.alteration_threshold - ): - self.logger.warning( - f"Alteration threshold exceeded: {len(altered_and_added)} files altered " - f"(threshold: {self.config.alteration_threshold})", - ) - altered_list = "\n".join( - str(path) for path in altered_and_added[: self.MAX_FILES_IN_EMAIL] - ) # Limit to first N files - if len(altered_and_added) > self.MAX_FILES_IN_EMAIL: - altered_list += f"\n... and {len(altered_and_added) - self.MAX_FILES_IN_EMAIL} more files" - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} Warning: {len(altered_and_added)} files altered (threshold: {self.config.alteration_threshold})", - message=( - f"Warning: The backup detected {len(altered_and_added)} altered files, " - f"which exceeds the threshold of {self.config.alteration_threshold}.\n\n" - f"Snapshot ID: {diff.snapshot_id}\n\n" - f"Altered files:\n{altered_list}" - ), - ) + for change_type, files, threshold in threshold_checks: + if threshold is not None and len(files) > threshold: + self._send_threshold_warning( + change_type, + files, + threshold, + diff.snapshot_id, + ) def _is_file_in_monitored_folder(self, file_path: Path) -> bool: """Check if a file is within any of the monitored folders. @@ -569,8 +716,9 @@ def _check_monitored_folders_and_send_alerts( ) -> None: """Check for changes in monitored folders and send email alerts. - Sends a separate email for each monitored folder containing only the files - that were deleted or altered in that specific folder. + Sends a separate email for each monitored folder and change type (added, + altered, deleted) containing only the files affected in that specific + folder. Any change inside a monitored folder triggers a notification. Args: diff: ResticDiff object containing file changes and snapshot ID @@ -579,65 +727,62 @@ def _check_monitored_folders_and_send_alerts( if not self.config.monitored_folders: return - # Iterate over each monitored folder and send separate emails - for monitored_folder in self.config.monitored_folders: - # Filter files for this specific monitored folder - folder_deleted = self._filter_files_for_monitored_folder( - diff.deleted_files, - monitored_folder, - ) - folder_altered = self._filter_files_for_monitored_folder( - diff.altered_files, - monitored_folder, - ) + # Every change type is reported so that any modification triggers an alert. + change_categories: tuple[tuple[str, list[Path]], ...] = ( + ("added", diff.added_files), + ("altered", diff.altered_files), + ("deleted", diff.deleted_files), + ) - # Send alert for deleted files in this monitored folder - if folder_deleted: - self.logger.warning( - f"Files deleted in monitored folder {monitored_folder}: " - f"{len(folder_deleted)} files", - ) - deleted_list = "\n".join( - str(path) for path in folder_deleted[: self.MAX_FILES_IN_EMAIL] - ) - if len(folder_deleted) > self.MAX_FILES_IN_EMAIL: - deleted_list += f"\n... and {len(folder_deleted) - self.MAX_FILES_IN_EMAIL} more files" - self.encrypted_mail.send_mail_with_retries( - subject=( - f"Backup {self.config.backup_title} Alert: {len(folder_deleted)} files deleted in " - f"monitored folder: {monitored_folder}" - ), - message=( - f"Alert: The backup detected {len(folder_deleted)} deleted files " - f"in monitored folder: {monitored_folder}\n\n" - f"Snapshot ID: {diff.snapshot_id}\n\n" - f"Deleted files:\n{deleted_list}" - ), + for monitored_folder in self.config.monitored_folders: + for change_type, files in change_categories: + folder_files = self._filter_files_for_monitored_folder( + files, + monitored_folder, ) + if folder_files: + self._send_monitored_folder_alert( + monitored_folder, + change_type, + folder_files, + diff.snapshot_id, + ) + + def _send_monitored_folder_alert( + self, + monitored_folder: str, + change_type: str, + files: list[Path], + snapshot_id: ResticSnapshotId, + ) -> None: + """Send an alert email for one change type in a monitored folder. - # Send alert for altered files in this monitored folder - if folder_altered: - self.logger.warning( - f"Files altered in monitored folder {monitored_folder}: " - f"{len(folder_altered)} files", - ) - altered_list = "\n".join( - str(path) for path in folder_altered[: self.MAX_FILES_IN_EMAIL] - ) - if len(folder_altered) > self.MAX_FILES_IN_EMAIL: - altered_list += f"\n... and {len(folder_altered) - self.MAX_FILES_IN_EMAIL} more files" - self.encrypted_mail.send_mail_with_retries( - subject=( - f"Backup {self.config.backup_title} Alert: {len(folder_altered)} files altered in " - f"monitored folder: {monitored_folder}" - ), - message=( - f"Alert: The backup detected {len(folder_altered)} altered files " - f"in monitored folder: {monitored_folder}\n\n" - f"Snapshot ID: {diff.snapshot_id}\n\n" - f"Altered files:\n{altered_list}" - ), - ) + Args: + monitored_folder: The monitored folder the files belong to + change_type: The kind of change ("added", "altered" or "deleted") + files: The affected files inside the monitored folder + snapshot_id: The snapshot ID this change belongs to + + """ + self.logger.warning( + f"Files {change_type} in monitored folder {monitored_folder}: " + f"{len(files)} files", + ) + file_list = "\n".join(str(path) for path in files[: self.MAX_FILES_IN_EMAIL]) + if len(files) > self.MAX_FILES_IN_EMAIL: + file_list += f"\n... and {len(files) - self.MAX_FILES_IN_EMAIL} more files" + self.encrypted_mail.send_mail_with_retries( + subject=( + f"Backup {self.config.backup_title} Alert: {len(files)} files " + f"{change_type} in monitored folder: {monitored_folder}" + ), + message=( + f"Alert: The backup detected {len(files)} {change_type} files " + f"in monitored folder: {monitored_folder}\n\n" + f"Snapshot ID: {snapshot_id}\n\n" + f"{change_type.capitalize()} files:\n{file_list}" + ), + ) def _send_file_changes_email( self, @@ -716,13 +861,21 @@ def _generate_diff_summary(self, snapshot_id: ResticSnapshotId) -> str: if len(snapshots) < self.MIN_SNAPSHOTS_FOR_DIFF: return "Not enough snapshots to generate diff summary." - # Get the previous snapshot (second to last) - # Convert snapshot IDs to ResticSnapshotId for comparison - current_snapshot = snapshots[-1] - if current_snapshot != snapshot_id: - error_msg = f"Here I was expecting to find the current snapshot, but I found something else. Expected: {snapshot_id}, Found: {current_snapshot}" + # Locate the just-created snapshot in the (time-ordered) list and + # use the one immediately before it, instead of assuming it is the + # last entry. This is robust against ordering surprises or a newer + # snapshot created by a concurrent run. + if snapshot_id not in snapshots: + error_msg = ( + f"Current snapshot {snapshot_id} was not found in the " + f"snapshot list returned by restic." + ) raise SnapshotIDNotFoundError(error_msg) - previous_snapshot = snapshots[-2] + + current_index = snapshots.index(snapshot_id) + if current_index == 0: + return "No previous snapshot available to generate diff summary." + previous_snapshot = snapshots[current_index - 1] diff_output = self.restic_client.diff(previous_snapshot, snapshot_id) @@ -737,38 +890,54 @@ def _generate_diff_summary(self, snapshot_id: ResticSnapshotId) -> str: # Check monitored folders and send alerts if needed self._check_monitored_folders_and_send_alerts(diff) - # Parse diff output to extract summary - summary_lines = [] - collecting_summary = False - - for line in diff_output.splitlines(): - if any( - word in line - for word in [ - "Files: ", - "Dirs: ", - "Others: ", - "Data Blobs: ", - "Tree Blobs: ", - "Added: ", - "Removed: ", - ] - ): - collecting_summary = True - - if collecting_summary: - summary_lines.append(line) - - return ( - "\n".join(summary_lines) if summary_lines else "No summary available." - ) + return self._extract_diff_statistics(diff_output) except (ValueError, TypeError, AttributeError) as e: self.logger.warning(f"Failed to generate diff summary: {e}") return f"Failed to generate diff summary: {e}" - def _verify_backup(self, snapshot_id: ResticSnapshotId) -> bool: - """Verify the backup by checking if specific files exist.""" + def _is_file_found_in_find_output(self, find_output: str) -> bool: + """Check whether ``restic find --json`` reported at least one match. + + ``find`` is invoked with ``-s ``, so the output is restricted + to the verified snapshot and any hit is within it. The output is a JSON + array of objects with ``hits``/``matches`` fields. + + Args: + find_output: The raw JSON output from restic find + + Returns: + True if at least one match was found, False otherwise + + """ + if not find_output or not find_output.strip(): + return False + + try: + results = json.loads(find_output) + except json.JSONDecodeError: + self.logger.exception("Failed to parse restic find --json output") + return False + + if not isinstance(results, list): + return False + + for entry in results: + if not isinstance(entry, dict): + continue + matches = entry.get("matches") or [] + hits = entry.get("hits", len(matches)) + if hits: + return True + return False + + def _verify_backup(self, snapshot_id: ResticSnapshotId) -> None: + """Verify the backup by checking if a configured file exists in the snapshot. + + Raises: + VerificationError: If the file is missing or verification cannot run + + """ self.logger.info(f"Verifying backup snapshot {snapshot_id}") try: @@ -776,83 +945,106 @@ def _verify_backup(self, snapshot_id: ResticSnapshotId) -> bool: self.config.file_to_check, snapshot_id, ) - - if f"Found matching entries in snapshot {snapshot_id}" in find_output: - self.logger.info("Backup verification successful") - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} verification successful", - message=f"Backup verification successful for snapshot {snapshot_id}. File {self.config.file_to_check} found.", - ) - return True - self.logger.error( - f"Backup verification failed - file {self.config.file_to_check} not found", - ) - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} verification failed", - message=f"Backup verification failed for snapshot {snapshot_id} - file {self.config.file_to_check} not found", - ) - return False # noqa: TRY300 - except Exception as e: self.logger.exception( f"Backup {self.config.backup_title} verification failed", ) + error_msg = f"Backup verification failed: {e}" + raise VerificationError(error_msg, original_error=e) from e + + if self._is_file_found_in_find_output(find_output): + self.logger.info("Backup verification successful") self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} verification failed", - message=f"Backup verification failed: {e}", + subject=f"Backup {self.config.backup_title} verification successful", + message=( + f"Backup verification successful for snapshot {snapshot_id}. " + f"File {self.config.file_to_check} found." + ), ) - return False + return - def _handle_verification_failure(self) -> None: - """Handle backup verification failure.""" self.logger.error( - f"Backup {self.config.backup_title} verification failed - skipping maintenance", + f"Backup verification failed - file {self.config.file_to_check} not found", ) - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup {self.config.backup_title} verification failed", - message="Backup verification failed. Maintenance skipped.", + error_msg = ( + f"Backup verification failed for snapshot {snapshot_id} - " + f"file {self.config.file_to_check} not found. Maintenance skipped." ) + raise VerificationError(error_msg) + + def _check_repository_integrity(self) -> str: + """Run ``restic check`` and recover once from a stale repository lock. + + ``check`` does not raise on a non-zero exit code (so integrity warnings + can be inspected), so a repository lock surfaces as lock text in the + output rather than as an exception. In that case stale locks are removed + and the check is retried once. + """ + check_output = self.restic_client.check(self.config.check_read_data_subset) + if is_lock_error(check_output): + self.logger.warning( + "Restic repository is locked during 'check'; " + "removing stale locks and retrying once.", + ) + self.restic_client.unlock() + check_output = self.restic_client.check(self.config.check_read_data_subset) + return check_output def _perform_maintenance(self) -> None: - """Perform maintenance operations on the repository.""" + """Perform maintenance: forget → check → prune (only if check is clean). + + ``forget`` only drops snapshot references and is relatively safe. + ``prune`` permanently deletes unreferenced data, so it runs only after + ``restic check`` reports a clean repository. + """ self.logger.info("Starting maintenance operations") try: - # Forget old snapshots - self.restic_client.forget( - self.config.keep_last, - self.config.keep_daily, - self.config.keep_monthly, + # Forget old snapshots (references only; pack data remains until prune) + self._run_with_lock_retry( + lambda: self.restic_client.forget( + self.config.keep_last, + self.config.keep_daily, + self.config.keep_monthly, + ), + "forget", ) - # Clean up cache + # Clean up local cache (independent of repository integrity) self.restic_client.cache_cleanup() - # Prune repository - self.restic_client.prune() - - # Check repository integrity - check_output = self.restic_client.check() + # Verify repository integrity before destructive cleanup + check_output = self._check_repository_integrity() - if "no errors were found" in check_output: - self.logger.info("Maintenance completed successfully") - self.encrypted_mail.send_mail_with_retries( - subject=f"Backup maintenance {self.config.backup_title} successful", - message="Repository maintenance completed successfully.", + if "no errors were found" not in check_output: + self.logger.warning( + "Repository check reported problems - skipping prune to " + "avoid deleting data from a potentially unhealthy repository", ) - else: - self.logger.warning("Maintenance completed with warnings") self.encrypted_mail.send_mail_with_retries( - subject=f"Backup maintenance {self.config.backup_title} completed with warnings", - message=f"Repository maintenance completed with warnings:\n{check_output}", + subject=( + f"Backup maintenance {self.config.backup_title} " + "completed with warnings" + ), + message=( + "Repository check reported problems. Prune was skipped " + "to avoid deleting data from a potentially unhealthy " + f"repository.\n\nCheck output:\n{check_output}" + ), ) + return - except Exception as e: - self.logger.exception("Maintenance failed") + # Repo is clean - safe to permanently remove unreferenced data + self._run_with_lock_retry(self.restic_client.prune, "prune") + + self.logger.info("Maintenance completed successfully") self.encrypted_mail.send_mail_with_retries( - subject=f"Backup maintenance {self.config.backup_title} failed", - message=f"Repository maintenance failed: {e}", + subject=f"Backup maintenance {self.config.backup_title} successful", + message="Repository maintenance completed successfully.", ) + + except Exception as e: + self.logger.exception("Maintenance failed") error_msg = f"Maintenance failed: {e}" raise MaintenanceError(error_msg, original_error=e) from e diff --git a/src/opsbox/backup/restic_client.py b/src/opsbox/backup/restic_client.py index 89ac456..ed9463a 100644 --- a/src/opsbox/backup/restic_client.py +++ b/src/opsbox/backup/restic_client.py @@ -1,5 +1,6 @@ """Restic client for executing restic commands with proper error handling and logging.""" +import json import logging import subprocess import tempfile @@ -7,45 +8,73 @@ from opsbox.backup.exceptions import ( ResticCommandFailedError, + ResticRepositoryLockedError, SnapshotIDNotFoundError, ) from opsbox.backup.snapshot_id import ResticSnapshotId -from opsbox.encrypted_mail import EncryptedMail + +# Substrings restic prints (to stderr/log) when a repository lock blocks a +# command. Matched case-insensitively so callers can react to stale locks. +LOCK_ERROR_SIGNATURES = ( + "repository is already locked", + "unable to create lock", +) + + +def is_lock_error(text: str | None) -> bool: + """Return True if ``text`` looks like a restic repository-lock error.""" + if not text: + return False + lowered = text.lower() + return any(sig in lowered for sig in LOCK_ERROR_SIGNATURES) class ResticClient: - """Handles all restic command execution with proper error handling and logging.""" + """Handles all restic command execution with proper error handling and logging. + + Does not send notifications: callers (e.g. ``BackupScript``) own alerting. + """ - MIN_SNAPSHOT_ID_LENGTH = 7 - MAX_SNAPSHOT_ID_LENGTH = 8 SNAPSHOT_PARTS_MIN_LENGTH = 2 + is_lock_error = staticmethod(is_lock_error) + def __init__( self, restic_path: str, backup_target: str, logger: logging.Logger, - encrypted_mail: EncryptedMail, ) -> None: - """Initialize the restic client with path, target, logger, and encrypted mail.""" + """Initialize the restic client with path, target, and logger.""" self.restic_path = restic_path self.backup_target = backup_target self.logger = logger - self.encrypted_mail = encrypted_mail self.temp_dir = Path(tempfile.gettempdir()) self.temp_dir.mkdir(parents=True, exist_ok=True) self.cache_dir = self.temp_dir / "restic_cache" self._restic_env: dict[str, str] | None = None - # Create temporary log file for all commands + # Per-command capture (truncated each run) vs cumulative session log for emails with tempfile.NamedTemporaryFile( suffix=".log", prefix="restic_", delete=False, ) as temp_file: - temp_file_path = temp_file.name - self.log_file = Path(temp_file_path) - self.logger.info(f"Created temporary log file: {self.log_file}") + self.log_file = Path(temp_file.name) + with tempfile.NamedTemporaryFile( + suffix=".log", + prefix="restic_session_", + delete=False, + ) as session_file: + self.session_log = Path(session_file.name) + self.session_log.write_text( + f"Restic session log\nrepository: {self.backup_target}\n", + encoding="utf-8", + ) + self.logger.info( + f"Created temporary log file: {self.log_file} " + f"and session log: {self.session_log}", + ) def set_environment( self, @@ -74,40 +103,52 @@ def _get_environment(self) -> dict[str, str]: raise ValueError(error_msg) return self._restic_env - def _send_error_email( + def _append_to_session_log( self, command: list[str], - error_msg: str, - log_contents: str | None = None, + command_output: str = "", + stdout: str | None = None, ) -> None: - """Send encrypted email with error details and log file.""" - try: - subject = f"Restic command failed: {' '.join(command[:3])}..." - message = f"Command: {' '.join(command)}\n\nError: {error_msg}" - - # Include log contents in message if available - if log_contents: - message += f"\n\nLog contents:\n{log_contents}" - - self.encrypted_mail.send_mail_with_retries( - subject=subject, - message=message, - mail_attachment=str(self.log_file) if self.log_file.exists() else None, - ) - except Exception: - self.logger.exception("Failed to send error email") + """Append one command's output to the cumulative session log. + + ``log_file`` stays per-command (truncated) for parsing; ``session_log`` + accumulates everything so email attachments cover the full run. + """ + parts = [f"\n=== {' '.join(command)} ===\n", command_output] + if not command_output.endswith("\n") and command_output: + parts.append("\n") + if stdout is not None: + parts.append("--- stdout ---\n") + parts.append(stdout) + if stdout and not stdout.endswith("\n"): + parts.append("\n") + with self.session_log.open("a", encoding="utf-8") as session_file: + session_file.write("".join(parts)) def _run_command( self, command: list[str], text: bool = True, timeout: int = 3600, + raise_on_error: bool = True, ) -> subprocess.CompletedProcess[str]: - """Execute a command with proper error handling and logging.""" + """Execute a command with proper error handling and logging. + + Args: + command: The command and arguments to execute + text: Whether to decode the output as text + timeout: Timeout in seconds for the command + raise_on_error: If True, a non-zero exit code raises + ResticCommandFailedError. If False, the non-zero exit code is + logged as a warning and the completed process (including its + output) is returned so the caller can inspect it. Operational + failures (timeout, subprocess errors) always raise. + + """ self.logger.debug(f"Running command: {' '.join(command)}") try: - # Run command and capture output to log file + # Capture this command only; session_log keeps the full run history with self.log_file.open("w") as f: result = subprocess.run( # noqa: S603 command, @@ -121,32 +162,110 @@ def _run_command( ) result.stdout = self.log_file.read_text() + self._append_to_session_log(command, result.stdout) # Check for non-zero exit code if result.returncode != 0: - log_contents = ( - self.log_file.read_text() if self.log_file.exists() else None + error_msg = f"Command returned non-zero exit code: {result.returncode}" + self.logger.error(f"{error_msg} - Command: {' '.join(command)}") + if raise_on_error: + log_contents = result.stdout or None + # A repository lock is potentially recoverable: let the + # caller unlock stale locks and retry instead of alerting. + if self.is_lock_error(log_contents): + self.logger.warning( + "Restic reported a repository lock error.", + ) + raise ResticRepositoryLockedError(error_msg) + raise ResticCommandFailedError(error_msg) + self.logger.warning( + "Continuing despite non-zero exit code " + "(raise_on_error=False); caller will inspect the output.", + ) + return result # noqa: TRY300 + + except subprocess.TimeoutExpired as e: + log_contents = self.log_file.read_text() if self.log_file.exists() else None + self._append_to_session_log(command, log_contents or "") + error_msg = f"Command timed out after {timeout} seconds" + self.logger.exception(f"{error_msg}: {' '.join(command)}") + raise ResticCommandFailedError(error_msg) from e + except subprocess.SubprocessError as e: + log_contents = self.log_file.read_text() if self.log_file.exists() else None + self._append_to_session_log(command, log_contents or "") + error_msg = f"Command failed: {e}" + self.logger.exception(f"{error_msg} - Command: {' '.join(command)}") + raise ResticCommandFailedError(error_msg) from e + + def _run_json_command( + self, + command: list[str], + timeout: int = 3600, + ) -> str: + """Execute a restic ``--json`` command and return its raw stdout. + + stdout is captured separately (kept free of any stderr/progress noise) + so it can be parsed as JSON, while stderr is written to the log file for + error reporting. Both are appended to ``session_log``. + + Args: + command: The command and arguments to execute (should include --json) + timeout: Timeout in seconds for the command + + Returns: + The command's stdout as a string + + Raises: + ResticCommandFailedError: If the command fails or times out + + """ + self.logger.debug(f"Running JSON command: {' '.join(command)}") + + try: + with self.log_file.open("w") as f: + result = subprocess.run( # noqa: S603 + command, + stdout=subprocess.PIPE, + stderr=f, + text=True, + timeout=timeout, + env=self._get_environment(), + check=False, ) + + stderr_text = self.log_file.read_text() if self.log_file.exists() else "" + stdout_text = result.stdout or "" + self._append_to_session_log( + command, + stderr_text, + stdout=stdout_text, + ) + + if result.returncode != 0: error_msg = f"Command returned non-zero exit code: {result.returncode}" self.logger.error(f"{error_msg} - Command: {' '.join(command)}") - self._send_error_email(command, error_msg, log_contents) raise ResticCommandFailedError(error_msg) - return result # noqa: TRY300 + return stdout_text # noqa: TRY300 except subprocess.TimeoutExpired as e: log_contents = self.log_file.read_text() if self.log_file.exists() else None + self._append_to_session_log(command, log_contents or "") error_msg = f"Command timed out after {timeout} seconds" self.logger.exception(f"{error_msg}: {' '.join(command)}") - self._send_error_email(command, error_msg, log_contents) raise ResticCommandFailedError(error_msg) from e except subprocess.SubprocessError as e: log_contents = self.log_file.read_text() if self.log_file.exists() else None + self._append_to_session_log(command, log_contents or "") error_msg = f"Command failed: {e}" self.logger.exception(f"{error_msg} - Command: {' '.join(command)}") - self._send_error_email(command, error_msg, log_contents) raise ResticCommandFailedError(error_msg) from e def unlock(self) -> None: - """Unlock the restic repository.""" + """Remove stale locks from the restic repository. + + A non-zero exit code is logged as a warning instead of raising, so that + a failed unlock does not mask the original operation the caller is + trying to recover (it will retry and surface the real error itself). + """ self.logger.info("Unlocking restic repository") cmd = [ self.restic_path, @@ -155,7 +274,7 @@ def unlock(self) -> None: self.backup_target, *self._get_cache_dir_args(), ] - result = self._run_command(cmd) + result = self._run_command(cmd, raise_on_error=False) if result.returncode != 0: self.logger.warning( f"Unlock command returned non-zero exit code: {result.returncode}", @@ -182,7 +301,6 @@ def backup( for exclude in excluded_files: cmd.extend(["--exclude", exclude]) - # Use _run_command which handles logging and error emailing self._run_command(cmd) # Extract snapshot ID from log file @@ -203,57 +321,72 @@ def _extract_snapshot_id(self, output: str) -> ResticSnapshotId: raise SnapshotIDNotFoundError(error_msg) def get_snapshots(self) -> list[ResticSnapshotId]: - """Get list of snapshot IDs.""" + """Get list of snapshot IDs, ordered from oldest to newest. + + Uses ``restic snapshots --json`` so the result is parsed from structured + data instead of fragile column-based text scraping. + """ cmd = [ self.restic_path, "snapshots", + "--json", "-r", self.backup_target, *self._get_cache_dir_args(), ] - result = self._run_command(cmd) + stdout = self._run_json_command(cmd) - if result.returncode != 0: - error_msg = "Failed to get snapshots" - raise ResticCommandFailedError(error_msg) + try: + snapshots_data = json.loads(stdout) if stdout.strip() else [] + except json.JSONDecodeError as e: + error_msg = f"Failed to parse restic snapshots JSON output: {e}" + self.logger.exception(error_msg) + raise ResticCommandFailedError(error_msg) from e snapshot_ids = [] - for line in result.stdout.splitlines(): - parts = line.split() - if ( - len(parts) > 0 - and len(parts[0]) >= self.MIN_SNAPSHOT_ID_LENGTH - and len(parts[0]) <= self.MAX_SNAPSHOT_ID_LENGTH - ): - snapshot_ids.append(ResticSnapshotId(parts[0])) + for entry in snapshots_data: + short_id = ( + entry.get("short_id") + or entry.get("id", "")[: ResticSnapshotId.SNAPSHOT_ID_LENGTH] + ) + if short_id: + snapshot_ids.append(ResticSnapshotId(short_id)) return snapshot_ids def diff(self, snapshot1: ResticSnapshotId, snapshot2: ResticSnapshotId) -> str: - """Get diff between two snapshots.""" + """Get diff between two snapshots as newline-delimited JSON. + + Uses ``restic diff --json`` so the caller can parse structured change + and statistics messages instead of scraping text markers. + """ cmd = [ self.restic_path, "diff", str(snapshot1), str(snapshot2), + "--json", "-r", self.backup_target, *self._get_cache_dir_args(), ] - result = self._run_command(cmd) - if result.returncode != 0: - error_msg = "Failed to get diff between snapshots" - raise ResticCommandFailedError(error_msg) - self.logger.info(f"Diff output: {result.stdout}") - return result.stdout + stdout = self._run_json_command(cmd) + self.logger.info(f"Diff output: {stdout}") + return stdout def find(self, file_pattern: str, snapshot_id: ResticSnapshotId) -> str: - """Find files in a snapshot.""" + """Find files in a snapshot, returning the raw ``restic find --json`` output. + + The output is a JSON array of objects (one per snapshot) with ``hits``, + ``snapshot`` and ``matches`` fields, so the caller can determine matches + from structured data instead of scraping text. + """ cmd = [ self.restic_path, "find", file_pattern, + "--json", "-s", str(snapshot_id), "--repo", @@ -261,12 +394,7 @@ def find(self, file_pattern: str, snapshot_id: ResticSnapshotId) -> str: *self._get_cache_dir_args(), ] - result = self._run_command(cmd) - if result.returncode != 0: - error_msg = f"Failed to find {file_pattern} in snapshot {snapshot_id}" - raise ResticCommandFailedError(error_msg) - - return result.stdout or "" + return self._run_json_command(cmd) def forget(self, keep_last: str, keep_daily: str, keep_monthly: str) -> None: """Forget old snapshots according to retention policy.""" @@ -322,7 +450,13 @@ def cache_cleanup(self) -> None: raise ResticCommandFailedError(error_msg) def check(self, read_data_subset: str = "20%") -> str: - """Check repository integrity.""" + """Check repository integrity and return the check output. + + A non-zero exit code (e.g. the repository has errors) does not raise: + the output is returned so the caller can distinguish "no errors were + found" from a repository that reported problems, and report accordingly. + Operational failures (timeout, subprocess errors) still raise. + """ self.logger.info("Running repository check") cmd = [ self.restic_path, @@ -333,9 +467,5 @@ def check(self, read_data_subset: str = "20%") -> str: *self._get_cache_dir_args(), ] - result = self._run_command(cmd) - if result.returncode != 0: - error_msg = "Repository check failed" - raise ResticCommandFailedError(error_msg) - + result = self._run_command(cmd, raise_on_error=False) return result.stdout or "" diff --git a/src/opsbox/locking/lock_manager.py b/src/opsbox/locking/lock_manager.py index 0d71502..2381b7a 100644 --- a/src/opsbox/locking/lock_manager.py +++ b/src/opsbox/locking/lock_manager.py @@ -1,15 +1,30 @@ """Lock management functionality for concurrent operations.""" +import fcntl import logging +import os +import socket import types +from datetime import datetime from pathlib import Path from opsbox.encrypted_mail import EncryptedMail from opsbox.exceptions import EmailSettingsNotFoundError, LockAlreadyTakenError +_HOLDER_INFO_READ_SIZE = 4096 + class LockManager: - """Manages file-based locks for concurrent operations.""" + """Manages advisory ``flock``-based locks for concurrent operations. + + The lock is held via an exclusive, non-blocking ``fcntl.flock`` on an open + file descriptor for the lifetime of the manager. This is robust against + stale locks: a lock file that merely exists (e.g. left behind by a crashed + process) does not block a new run, because the advisory lock is released + automatically by the kernel when the holding process dies. Diagnostic + information (PID, host, acquisition time) is written into the lock file so + that a genuinely concurrent run can report who currently holds the lock. + """ def __init__( self, @@ -31,6 +46,7 @@ def __init__( self.logger = logger self.encrypted_mail = encrypted_mail self.script_name = script_name + self._lock_fd: int | None = None def __enter__(self) -> "LockManager": """Context manager entry point.""" @@ -47,35 +63,85 @@ def __exit__( self.release_lock() def create_lock(self) -> None: - """Create a lock file. + """Acquire an exclusive advisory lock on the lock file. Raises: - LockAlreadyTakenError: If the lock file already exists + LockAlreadyTakenError: If the lock is actively held by another + (running) process. """ - if self.lock_file.exists(): - self.logger.error("Lock file exists. Another instance may be running.") - - # Send email notification if configured - if self.encrypted_mail and self.script_name: - try: - self.encrypted_mail.send_mail_with_retries( - subject=f"Lock already taken by script {self.script_name}", - message=f"The lock file {self.lock_file} already exists. Script {self.script_name} cannot acquire lock.", - ) - except (EmailSettingsNotFoundError, OSError): - self.logger.exception("Failed to send lock notification email") - - # Raise custom exception - error_message = f"Lock file {self.lock_file} already exists." - raise LockAlreadyTakenError(error_message) - self.lock_file.touch() + # Open (creating if necessary) and keep the descriptor for the whole + # lifetime of the lock: the flock is bound to this open file description. + fd = os.open(self.lock_file, os.O_RDWR | os.O_CREAT, 0o644) + + try: + fcntl.flock(fd, fcntl.LOCK_EX | fcntl.LOCK_NB) + except OSError as error: + # The lock is currently held by another live process. + holder_info = self._read_holder_info(fd) + os.close(fd) + self.logger.exception( + "Lock is held by another running instance. " + f"Current holder: {holder_info}", + ) + self._notify_lock_taken(holder_info) + error_message = f"Lock file {self.lock_file} is already held." + raise LockAlreadyTakenError(error_message) from error + + self._lock_fd = fd + self._write_holder_info(fd) self.logger.info(f"Lock file {self.lock_file} created.") def release_lock(self) -> None: - """Release the lock file.""" - if self.lock_file.exists(): - self.lock_file.unlink() - self.logger.info("Lock file released.") - else: + """Release the advisory lock and close the descriptor.""" + if self._lock_fd is None: self.logger.warning("Lock file does not exist when attempting to release.") + return + + try: + fcntl.flock(self._lock_fd, fcntl.LOCK_UN) + finally: + os.close(self._lock_fd) + self._lock_fd = None + self.logger.info("Lock file released.") + + def _write_holder_info(self, fd: int) -> None: + """Write PID/host/timestamp diagnostics into the lock file.""" + info = ( + f"pid={os.getpid()} " + f"host={socket.gethostname()} " + f"acquired={datetime.now().astimezone().isoformat()}" + ) + try: + os.lseek(fd, 0, os.SEEK_SET) + os.ftruncate(fd, 0) + os.write(fd, info.encode("utf-8")) + os.fsync(fd) + except OSError: + self.logger.debug("Could not write lock holder diagnostics", exc_info=True) + + def _read_holder_info(self, fd: int) -> str: + """Read the diagnostics written by the current lock holder.""" + try: + os.lseek(fd, 0, os.SEEK_SET) + raw = os.read(fd, _HOLDER_INFO_READ_SIZE) + except OSError: + return "unknown (could not read lock file)" + info = raw.decode("utf-8", errors="replace").strip() + return info or "unknown (lock file empty)" + + def _notify_lock_taken(self, holder_info: str) -> None: + """Send an email notification that the lock could not be acquired.""" + if not (self.encrypted_mail and self.script_name): + return + try: + self.encrypted_mail.send_mail_with_retries( + subject=f"Lock already taken by script {self.script_name}", + message=( + f"The lock file {self.lock_file} is held by another running " + f"instance; script {self.script_name} cannot acquire the lock.\n\n" + f"Current holder: {holder_info}" + ), + ) + except (EmailSettingsNotFoundError, OSError): + self.logger.exception("Failed to send lock notification email") diff --git a/tests/backup/test_config_manager.py b/tests/backup/test_config_manager.py index c9dafcd..cf1a48f 100644 --- a/tests/backup/test_config_manager.py +++ b/tests/backup/test_config_manager.py @@ -407,7 +407,6 @@ def test_backup_config_default_values(self) -> None: assert config.keep_daily == "21" assert config.keep_monthly == "5" assert config.ssh_key_max_retries == 12 - assert config.detailed_report is True assert config.default_user == getpass.getuser() def test_get_default_config(self) -> None: diff --git a/tests/backup/test_restic_backup.py b/tests/backup/test_restic_backup.py index ef0a417..7facef7 100644 --- a/tests/backup/test_restic_backup.py +++ b/tests/backup/test_restic_backup.py @@ -10,15 +10,71 @@ from opsbox.backup.exceptions import ( ConfigurationError, + EmptySourceError, NetworkUnreachableError, ResticBackupFailedError, + ResticRepositoryLockedError, SSHKeyNotFoundError, + VerificationError, WrongOSForResticBackupError, ) from opsbox.backup.restic_backup import BackupScript from opsbox.backup.snapshot_id import ResticSnapshotId +def make_diff_ndjson( + entries: list[tuple[str, str]] | None = None, + *, + changed_files: int = 0, +) -> str: + """Build 'restic diff --json' ndjson output from (modifier, path) tuples. + + A terminating ``statistics`` message is always appended, mirroring real + ``restic diff --json`` output (which the parser now requires). + """ + entries = entries or [] + lines = [ + json.dumps({"message_type": "change", "path": path, "modifier": modifier}) + for modifier, path in entries + ] + empty_stat = { + "files": 0, + "dirs": 0, + "others": 0, + "data_blobs": 0, + "tree_blobs": 0, + "bytes": 0, + } + lines.append( + json.dumps( + { + "message_type": "statistics", + "source_snapshot": "aaaaaaaa", + "target_snapshot": "bbbbbbbb", + "changed_files": changed_files, + "added": empty_stat, + "removed": empty_stat, + }, + ), + ) + return "\n".join(lines) + + +def make_find_json(*, found: bool = True) -> str: + """Build 'restic find --json' output; found=False yields no matches.""" + if not found: + return json.dumps([]) + return json.dumps( + [ + { + "hits": 1, + "snapshot": "0" * 64, + "matches": [{"path": "/important_file.txt", "type": "file"}], + }, + ], + ) + + class TestBackupScript: """Test cases for BackupScript functionality.""" @@ -30,6 +86,8 @@ def temp_config(self) -> Generator[tuple[Path, Path, Path], None, None]: email_settings = Path(temp_dir) / "email.json" backup_source = Path(temp_dir) / "source" backup_source.mkdir() + # Add an entry so the non-empty source guard passes by default + (backup_source / "dummy.txt").write_text("data") email_settings.write_text(json.dumps({"sender": "test@example.com"})) config_data = { @@ -119,10 +177,8 @@ def test_run_complete_backup_workflow_success( ResticSnapshotId("a1b2c3d4"), ResticSnapshotId("c9d0e1f2"), ] - mock_restic_client.diff.return_value = "Files: 10\nDirs: 5" - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot c9d0e1f2" - ) + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -205,9 +261,7 @@ def test_run_backup_with_network_check( ResticSnapshotId("a1b2c3d4"), ResticSnapshotId("c9d0e1f2"), ] - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot c9d0e1f2" - ) + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -281,9 +335,7 @@ def test_run_backup_with_ssh_setup(self, temp_config, mock_lock_manager) -> None ResticSnapshotId("a1b2c3d4"), ResticSnapshotId("c9d0e1f2"), ] - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot c9d0e1f2" - ) + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -465,10 +517,8 @@ def test_run_backup_verification_success( ResticSnapshotId("a1b2c3d4"), ResticSnapshotId("87654321"), ] - mock_restic_client.diff.return_value = "Files: 10" - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot 87654321" - ) + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -508,7 +558,7 @@ def test_run_backup_verification_failure( temp_config, mock_lock_manager, ) -> None: - """Test that verification failure is handled (sends email, skips maintenance).""" + """Test that verification failure raises, emails once, and skips maintenance.""" config_file, _, _ = temp_config mock_restic_client = Mock() @@ -518,9 +568,10 @@ def test_run_backup_verification_failure( ResticSnapshotId("abc123de"), ResticSnapshotId("a1b2c3d6"), ] - mock_restic_client.diff.return_value = "Files: 10" - mock_restic_client.find.return_value = "No matching entries found" - mock_restic_client.log_file = Path("/tmp/restic.log") + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json(found=False) + mock_restic_client.session_log = Path("/tmp/restic_session.log") + mock_restic_client.session_log.touch() mock_encrypted_mail = Mock() @@ -546,11 +597,14 @@ def test_run_backup_verification_failure( mock_pm_class.return_value = mock_password_manager backup_script = BackupScript(str(config_file)) - backup_script.run() + with pytest.raises(VerificationError): + backup_script.run() - # Verify verification failure email was sent - mock_encrypted_mail.send_mail_with_retries.assert_called() - # Verify maintenance was NOT performed (verification failed) + failure_subjects = [ + call.kwargs.get("subject", "") + for call in mock_encrypted_mail.send_mail_with_retries.call_args_list + ] + assert sum("verification failed" in s for s in failure_subjects) == 1 mock_restic_client.forget.assert_not_called() mock_restic_client.prune.assert_not_called() @@ -570,10 +624,8 @@ def test_run_backup_maintenance_success( ResticSnapshotId("a1b2c3d4"), ResticSnapshotId("87654321"), ] - mock_restic_client.diff.return_value = "Files: 10" - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot 87654321" - ) + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -606,8 +658,80 @@ def test_run_backup_maintenance_success( # Verify all maintenance operations were performed mock_restic_client.forget.assert_called_once() mock_restic_client.cache_cleanup.assert_called_once() + mock_restic_client.check.assert_called_once() mock_restic_client.prune.assert_called_once() + # Prune must run only after a successful repository check + maintenance_names = [ + call[0] + for call in mock_restic_client.method_calls + if call[0] in {"forget", "cache_cleanup", "check", "prune"} + ] + assert maintenance_names == [ + "forget", + "cache_cleanup", + "check", + "prune", + ] + + def test_run_backup_maintenance_skips_prune_when_check_fails( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that prune is skipped when repository check reports problems.""" + config_file, _, _ = temp_config + + mock_restic_client = Mock() + snapshot_id = ResticSnapshotId("87654321") + mock_restic_client.backup.return_value = snapshot_id + mock_restic_client.get_snapshots.return_value = [ + ResticSnapshotId("12345678"), + ResticSnapshotId("a1b2c3d4"), + ResticSnapshotId("87654321"), + ] + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json() + mock_restic_client.check.return_value = "error: pack is damaged" + mock_restic_client.log_file = Path("/tmp/restic.log") + + mock_encrypted_mail = Mock() + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch( + "opsbox.backup.restic_backup.EncryptedMail", + return_value=mock_encrypted_mail, + ), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + backup_script.run() + + mock_restic_client.forget.assert_called_once() + mock_restic_client.cache_cleanup.assert_called_once() mock_restic_client.check.assert_called_once() + mock_restic_client.prune.assert_not_called() + + warning_subjects = [ + call.kwargs.get("subject", "") + for call in mock_encrypted_mail.send_mail_with_retries.call_args_list + ] + assert any( + "completed with warnings" in subject for subject in warning_subjects + ) def test_generate_diff_summary_success( self, @@ -627,12 +751,8 @@ def test_generate_diff_summary_success( ResticSnapshotId("a1b2c3d4"), ResticSnapshotId("87654321"), ] - mock_restic_client.diff.return_value = ( - "Files: 10\nDirs: 5\nAdded: 3\nRemoved: 2" - ) - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot 87654321" - ) + mock_restic_client.diff.return_value = make_diff_ndjson(changed_files=10) + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -675,9 +795,7 @@ def test_generate_diff_summary_insufficient_snapshots( mock_restic_client.get_snapshots.return_value = [ ResticSnapshotId("a1b2c3d4"), ] # Only one snapshot - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot a1b2c3d4" - ) + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -748,11 +866,11 @@ def test_check_thresholds_and_send_warnings_deletion( ResticSnapshotId("a1b2c3d6"), ] # Create diff output with 10 deleted files (exceeds threshold of 5) - diff_output = "\n".join([f"- /path/to/file{i}.txt" for i in range(10)]) - mock_restic_client.diff.return_value = diff_output - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot a1b2c3d6" + diff_output = make_diff_ndjson( + [("-", f"/path/to/file{i}.txt") for i in range(10)], ) + mock_restic_client.diff.return_value = diff_output + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -838,11 +956,11 @@ def test_check_thresholds_and_send_warnings_alteration( ResticSnapshotId("87654321"), ] # Create diff output with 10 modified files (exceeds threshold of 5) - diff_output = "\n".join([f"M /path/to/file{i}.txt" for i in range(10)]) - mock_restic_client.diff.return_value = diff_output - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot 87654321" + diff_output = make_diff_ndjson( + [("M", f"/path/to/file{i}.txt") for i in range(10)], ) + mock_restic_client.diff.return_value = diff_output + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -929,13 +1047,14 @@ def test_check_monitored_folders_and_send_alerts( ResticSnapshotId("87654321"), ] # Create diff output with files in monitored folder - diff_output = ( - "- /important/folder/file1.txt\nM /important/folder/file2.txt" + diff_output = make_diff_ndjson( + [ + ("-", "/important/folder/file1.txt"), + ("M", "/important/folder/file2.txt"), + ], ) mock_restic_client.diff.return_value = diff_output - mock_restic_client.find.return_value = ( - "Found matching entries in snapshot 87654321" - ) + mock_restic_client.find.return_value = make_find_json() mock_restic_client.check.return_value = "no errors were found" mock_restic_client.log_file = Path("/tmp/restic.log") @@ -974,6 +1093,288 @@ def test_check_monitored_folders_and_send_alerts( ] assert any("monitored folder" in call.lower() for call in calls) + def test_monitored_folder_alerts_cover_all_change_types( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that added, altered and deleted files in a monitored folder all alert.""" + config_file, email_settings, backup_source = temp_config + config_data = { + "backup_source": str(backup_source), + "excluded_files": ["*.tmp"], + "backup_target": "sftp:user@host:/repo", + "password_lookup_1": "service", + "password_lookup_2": "username", + "email_settings_path": str(email_settings), + "file_to_check": "important_file.txt", + "monitored_folders": ["/important/folder"], + } + + excluded_file = config_data["excluded_files"][0] + config_file.write_text( + f"backup_source: {config_data['backup_source']}\n" + f"excluded_files:\n - '{excluded_file}'\n" + f"backup_target: {config_data['backup_target']}\n" + f"password_lookup_1: {config_data['password_lookup_1']}\n" + f"password_lookup_2: {config_data['password_lookup_2']}\n" + f"email_settings_path: {config_data['email_settings_path']}\n" + f"file_to_check: {config_data['file_to_check']}\n" + f"monitored_folders:\n - {config_data['monitored_folders'][0]}\n", + ) + + mock_restic_client = Mock() + snapshot_id = ResticSnapshotId("87654321") + mock_restic_client.backup.return_value = snapshot_id + mock_restic_client.get_snapshots.return_value = [ + ResticSnapshotId("12345678"), + ResticSnapshotId("a1b2c3d4"), + ResticSnapshotId("87654321"), + ] + # One added (+), one modified (M) and one deleted (-) file in the folder + mock_restic_client.diff.return_value = make_diff_ndjson( + [ + ("+", "/important/folder/new.txt"), + ("M", "/important/folder/changed.txt"), + ("-", "/important/folder/gone.txt"), + ], + ) + mock_restic_client.find.return_value = make_find_json() + mock_restic_client.check.return_value = "no errors were found" + mock_restic_client.log_file = Path("/tmp/restic.log") + + mock_encrypted_mail = Mock() + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch( + "opsbox.backup.restic_backup.EncryptedMail", + return_value=mock_encrypted_mail, + ), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + backup_script.run() + + calls = [ + str(call) + for call in mock_encrypted_mail.send_mail_with_retries.call_args_list + ] + monitored_calls = [ + call for call in calls if "monitored folder" in call.lower() + ] + # Every change type must produce a monitored-folder alert + assert any("added in monitored folder" in call for call in monitored_calls) + assert any( + "altered in monitored folder" in call for call in monitored_calls + ) + assert any( + "deleted in monitored folder" in call for call in monitored_calls + ) + + def test_run_aborts_on_empty_source( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that the backup is aborted when the source directory is empty.""" + config_file, _, backup_source = temp_config + + # Remove the fixture's entry so the source becomes empty + for entry in backup_source.iterdir(): + entry.unlink() + + mock_restic_client = Mock() + mock_restic_client.log_file = Path("/tmp/restic.log") + mock_encrypted_mail = Mock() + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch( + "opsbox.backup.restic_backup.EncryptedMail", + return_value=mock_encrypted_mail, + ), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + + with pytest.raises(EmptySourceError): + backup_script.run() + + # Backup must not be attempted for an empty source + mock_restic_client.backup.assert_not_called() + + def test_run_addition_threshold_warning( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that a warning email is sent when the addition threshold is exceeded.""" + config_file, email_settings, backup_source = temp_config + config_data: dict[str, str | int | list[str]] = { + "backup_source": str(backup_source), + "excluded_files": ["*.tmp"], + "backup_target": "sftp:user@host:/repo", + "password_lookup_1": "service", + "password_lookup_2": "username", + "email_settings_path": str(email_settings), + "file_to_check": "important_file.txt", + "addition_threshold": 5, + } + + excluded_file = config_data["excluded_files"][0] # type: ignore[index] + config_file.write_text( + f"backup_source: {config_data['backup_source']}\n" + f"excluded_files:\n - '{excluded_file}'\n" + f"backup_target: {config_data['backup_target']}\n" + f"password_lookup_1: {config_data['password_lookup_1']}\n" + f"password_lookup_2: {config_data['password_lookup_2']}\n" + f"email_settings_path: {config_data['email_settings_path']}\n" + f"file_to_check: {config_data['file_to_check']}\n" + f"addition_threshold: {config_data['addition_threshold']}\n", + ) + + mock_restic_client = Mock() + snapshot_id = ResticSnapshotId("87654321") + mock_restic_client.backup.return_value = snapshot_id + mock_restic_client.get_snapshots.return_value = [ + ResticSnapshotId("12345678"), + ResticSnapshotId("a1b2c3d4"), + ResticSnapshotId("87654321"), + ] + # 10 added files exceeds the addition threshold of 5 + diff_output = make_diff_ndjson( + [("+", f"/path/to/file{i}.txt") for i in range(10)], + ) + mock_restic_client.diff.return_value = diff_output + mock_restic_client.find.return_value = make_find_json() + mock_restic_client.check.return_value = "no errors were found" + mock_restic_client.log_file = Path("/tmp/restic.log") + + mock_encrypted_mail = Mock() + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch( + "opsbox.backup.restic_backup.EncryptedMail", + return_value=mock_encrypted_mail, + ), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + backup_script.run() + + calls = [ + str(call) + for call in mock_encrypted_mail.send_mail_with_retries.call_args_list + ] + assert any("files added (threshold" in call for call in calls) + + def test_check_read_data_subset_passed_to_check( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that the configured check_read_data_subset is passed to restic check.""" + config_file, email_settings, backup_source = temp_config + config_data: dict[str, str | list[str]] = { + "backup_source": str(backup_source), + "excluded_files": ["*.tmp"], + "backup_target": "sftp:user@host:/repo", + "password_lookup_1": "service", + "password_lookup_2": "username", + "email_settings_path": str(email_settings), + "file_to_check": "important_file.txt", + "check_read_data_subset": "100%", + } + + excluded_file = config_data["excluded_files"][0] + config_file.write_text( + f"backup_source: {config_data['backup_source']}\n" + f"excluded_files:\n - '{excluded_file}'\n" + f"backup_target: {config_data['backup_target']}\n" + f"password_lookup_1: {config_data['password_lookup_1']}\n" + f"password_lookup_2: {config_data['password_lookup_2']}\n" + f"email_settings_path: {config_data['email_settings_path']}\n" + f"file_to_check: {config_data['file_to_check']}\n" + f"check_read_data_subset: '{config_data['check_read_data_subset']}'\n", + ) + + mock_restic_client = Mock() + snapshot_id = ResticSnapshotId("87654321") + mock_restic_client.backup.return_value = snapshot_id + mock_restic_client.get_snapshots.return_value = [ + ResticSnapshotId("12345678"), + ResticSnapshotId("a1b2c3d4"), + ResticSnapshotId("87654321"), + ] + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json() + mock_restic_client.check.return_value = "no errors were found" + mock_restic_client.log_file = Path("/tmp/restic.log") + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch("opsbox.backup.restic_backup.EncryptedMail"), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + backup_script.run() + + mock_restic_client.check.assert_called_once_with("100%") + def test_run_backup_failure_sends_email( self, temp_config, @@ -984,8 +1385,8 @@ def test_run_backup_failure_sends_email( mock_restic_client = Mock() mock_restic_client.backup.side_effect = ResticBackupFailedError("Backup failed") - mock_restic_client.log_file = Path("/tmp/restic.log") - mock_restic_client.log_file.touch() + mock_restic_client.session_log = Path("/tmp/restic_session.log") + mock_restic_client.session_log.touch() mock_encrypted_mail = Mock() @@ -1015,7 +1416,7 @@ def test_run_backup_failure_sends_email( with pytest.raises(ResticBackupFailedError): backup_script.run() - # Verify error email was sent with log attachment + # Verify error email was sent with full session log attachment mock_encrypted_mail.send_mail_with_retries.assert_called() # Check all calls to find the backup failure email calls = mock_encrypted_mail.send_mail_with_retries.call_args_list @@ -1038,7 +1439,147 @@ def test_run_backup_failure_sends_email( if hasattr(backup_failure_call, "kwargs") else backup_failure_call[1] ) - assert kwargs.get("mail_attachment") == str(mock_restic_client.log_file) + assert kwargs.get("mail_attachment") == str(mock_restic_client.session_log) + + def test_backup_retries_once_after_repository_lock( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that a stale repository lock triggers unlock and a single retry.""" + config_file, _, _ = temp_config + + mock_restic_client = Mock() + snapshot_id = ResticSnapshotId("c9d0e1f2") + # First backup attempt hits a repository lock, the retry succeeds. + mock_restic_client.backup.side_effect = [ + ResticRepositoryLockedError("repository is already locked"), + snapshot_id, + ] + mock_restic_client.get_snapshots.return_value = [ + ResticSnapshotId("e5f6a7b8"), + ResticSnapshotId("a1b2c3d4"), + ResticSnapshotId("c9d0e1f2"), + ] + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json() + mock_restic_client.check.return_value = "no errors were found" + mock_restic_client.log_file = Path("/tmp/restic.log") + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch("opsbox.backup.restic_backup.EncryptedMail"), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + backup_script.run() + + assert mock_restic_client.backup.call_count == 2 + mock_restic_client.unlock.assert_called_once() + + def test_backup_fails_when_still_locked_after_unlock( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that a persistent repository lock fails after a single retry.""" + config_file, _, _ = temp_config + + mock_restic_client = Mock() + mock_restic_client.backup.side_effect = ResticRepositoryLockedError( + "repository is already locked", + ) + mock_restic_client.log_file = Path("/tmp/restic.log") + mock_restic_client.log_file.touch() + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch("opsbox.backup.restic_backup.EncryptedMail"), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + + with pytest.raises(ResticRepositoryLockedError): + backup_script.run() + + # Original attempt plus exactly one retry. + assert mock_restic_client.backup.call_count == 2 + mock_restic_client.unlock.assert_called_once() + + def test_check_retries_once_after_repository_lock( + self, + temp_config, + mock_lock_manager, + ) -> None: + """Test that a locked repository during check unlocks and retries once.""" + config_file, _, _ = temp_config + + mock_restic_client = Mock() + snapshot_id = ResticSnapshotId("c9d0e1f2") + mock_restic_client.backup.return_value = snapshot_id + mock_restic_client.get_snapshots.return_value = [ + ResticSnapshotId("e5f6a7b8"), + ResticSnapshotId("a1b2c3d4"), + ResticSnapshotId("c9d0e1f2"), + ] + mock_restic_client.diff.return_value = make_diff_ndjson() + mock_restic_client.find.return_value = make_find_json() + # check() does not raise; the lock surfaces as text in the output. + mock_restic_client.check.side_effect = [ + "unable to create lock in backend: repository is already locked", + "no errors were found", + ] + mock_restic_client.log_file = Path("/tmp/restic.log") + + with ( + patch( + "opsbox.backup.restic_backup.LockManager", + return_value=mock_lock_manager, + ), + patch("opsbox.backup.restic_backup.EncryptedMail"), + patch("opsbox.backup.restic_backup.PasswordManager") as mock_pm_class, + patch("opsbox.backup.restic_backup.NetworkChecker"), + patch("opsbox.backup.restic_backup.SSHManager"), + patch( + "opsbox.backup.restic_backup.ResticClient", + return_value=mock_restic_client, + ), + ): + mock_password_manager = Mock() + mock_password_manager.get_restic_password.return_value = "test_password" + mock_pm_class.return_value = mock_password_manager + + backup_script = BackupScript(str(config_file)) + backup_script.run() + + assert mock_restic_client.check.call_count == 2 + mock_restic_client.unlock.assert_called_once() if __name__ == "__main__": diff --git a/tests/backup/test_restic_client.py b/tests/backup/test_restic_client.py index a083864..0fb20be 100644 --- a/tests/backup/test_restic_client.py +++ b/tests/backup/test_restic_client.py @@ -1,17 +1,22 @@ """Tests for the restic_client module.""" +import json import logging import subprocess import tempfile from pathlib import Path +from typing import IO, cast from unittest.mock import Mock, patch import pytest -from opsbox.backup.exceptions import ResticCommandFailedError, SnapshotIDNotFoundError +from opsbox.backup.exceptions import ( + ResticCommandFailedError, + ResticRepositoryLockedError, + SnapshotIDNotFoundError, +) from opsbox.backup.restic_client import ResticClient from opsbox.backup.snapshot_id import ResticSnapshotId -from opsbox.encrypted_mail import EncryptedMail class TestResticClient: @@ -23,18 +28,12 @@ def logger(self) -> Mock: return Mock(spec=logging.Logger) @pytest.fixture - def encrypted_mail(self) -> Mock: - """Create a mock EncryptedMail for testing.""" - return Mock(spec=EncryptedMail) - - @pytest.fixture - def restic_client(self, logger, encrypted_mail) -> ResticClient: + def restic_client(self, logger) -> ResticClient: """Create a ResticClient instance for testing.""" return ResticClient( restic_path="/snap/bin/restic", backup_target="sftp:user@host:/repo", logger=logger, - encrypted_mail=encrypted_mail, ) def test_set_environment_with_password(self, restic_client) -> None: @@ -120,33 +119,58 @@ def test_backup_snapshot_id_not_found(self, restic_client) -> None: restic_client.backup("/backup/source", ["*.tmp"]) def test_get_snapshots_success(self, restic_client) -> None: - """Test that get_snapshots returns list of snapshot IDs.""" + """Test that get_snapshots parses snapshot IDs from JSON output.""" restic_client.set_environment("test_password") - mock_result = Mock() - mock_result.returncode = 0 - mock_result.stdout = ( - "ID Time Host Tags Paths\n" - "------------------------------------------------------------------------------\n" - "a1b2c3d4 2024-01-01 12:00:00 host /path/to/backup\n" - "e5f6a7b8 2024-01-02 12:00:00 host /path/to/backup\n" - "c9d0e1f2 2024-01-03 12:00:00 host /path/to/backup\n" - "------------------------------------------------------------------------------\n" - "3 snapshots" + json_output = json.dumps( + [ + {"short_id": "a1b2c3d4", "time": "2024-01-01T12:00:00Z"}, + {"short_id": "e5f6a7b8", "time": "2024-01-02T12:00:00Z"}, + {"short_id": "c9d0e1f2", "time": "2024-01-03T12:00:00Z"}, + ], ) - with patch.object(restic_client, "_run_command", return_value=mock_result): + with patch.object( + restic_client, + "_run_json_command", + return_value=json_output, + ): snapshots = restic_client.get_snapshots() assert len(snapshots) == 3 assert all(isinstance(s, ResticSnapshotId) for s in snapshots) - assert ResticSnapshotId("a1b2c3d4") in snapshots - assert ResticSnapshotId("e5f6a7b8") in snapshots - assert ResticSnapshotId("c9d0e1f2") in snapshots - # Also test string comparison - assert "a1b2c3d4" in [str(s) for s in snapshots] - assert "e5f6a7b8" in [str(s) for s in snapshots] - assert "c9d0e1f2" in [str(s) for s in snapshots] + # Order (oldest to newest) is preserved from the JSON output + assert [str(s) for s in snapshots] == ["a1b2c3d4", "e5f6a7b8", "c9d0e1f2"] + + def test_get_snapshots_falls_back_to_id(self, restic_client) -> None: + """Test that get_snapshots derives the short id from the full id.""" + restic_client.set_environment("test_password") + + json_output = json.dumps( + [{"id": "a1b2c3d4e5f6a7b8c9d0e1f2", "time": "2024-01-01T12:00:00Z"}], + ) + + with patch.object( + restic_client, + "_run_json_command", + return_value=json_output, + ): + snapshots = restic_client.get_snapshots() + + assert len(snapshots) == 1 + assert str(snapshots[0]) == "a1b2c3d4" + + def test_get_snapshots_invalid_json(self, restic_client) -> None: + """Test that invalid JSON output raises ResticCommandFailedError.""" + restic_client.set_environment("test_password") + + with patch.object( + restic_client, + "_run_json_command", + return_value="not valid json", + ): + with pytest.raises(ResticCommandFailedError, match="Failed to parse"): + restic_client.get_snapshots() def test_get_snapshots_failure(self, restic_client) -> None: """Test that ResticCommandFailedError is raised on get_snapshots failure.""" @@ -154,27 +178,31 @@ def test_get_snapshots_failure(self, restic_client) -> None: with patch.object( restic_client, - "_run_command", + "_run_json_command", side_effect=ResticCommandFailedError("Command failed"), ): with pytest.raises(ResticCommandFailedError, match="Command failed"): restic_client.get_snapshots() def test_diff_success(self, restic_client) -> None: - """Test that diff returns output between snapshots.""" + """Test that diff returns the raw JSON output between snapshots.""" restic_client.set_environment("test_password") - mock_result = Mock() - mock_result.returncode = 0 - mock_result.stdout = "diff output between snapshots" + json_output = json.dumps( + {"message_type": "change", "path": "/a", "modifier": "M"}, + ) - with patch.object(restic_client, "_run_command", return_value=mock_result): + with patch.object( + restic_client, + "_run_json_command", + return_value=json_output, + ): diff_output = restic_client.diff( ResticSnapshotId("a1b2c3d4"), ResticSnapshotId("e5f6a7b8"), ) - assert diff_output == "diff output between snapshots" + assert diff_output == json_output restic_client.logger.info.assert_called() def test_diff_failure(self, restic_client) -> None: @@ -183,7 +211,7 @@ def test_diff_failure(self, restic_client) -> None: with patch.object( restic_client, - "_run_command", + "_run_json_command", side_effect=ResticCommandFailedError("Diff failed"), ): with pytest.raises(ResticCommandFailedError, match="Diff failed"): @@ -193,17 +221,27 @@ def test_diff_failure(self, restic_client) -> None: ) def test_find_success(self, restic_client) -> None: - """Test that find returns output when searching for files in snapshot.""" + """Test that find returns the raw JSON output when searching a snapshot.""" restic_client.set_environment("test_password") - mock_result = Mock() - mock_result.returncode = 0 - mock_result.stdout = "Found matching entries in snapshot a1b2c3d4" + json_output = json.dumps( + [ + { + "hits": 1, + "snapshot": "a1b2c3d4", + "matches": [{"path": "/file.txt", "type": "file"}], + }, + ], + ) - with patch.object(restic_client, "_run_command", return_value=mock_result): + with patch.object( + restic_client, + "_run_json_command", + return_value=json_output, + ): find_output = restic_client.find("file.txt", ResticSnapshotId("a1b2c3d4")) - assert "Found matching entries" in find_output + assert find_output == json_output def test_find_failure(self, restic_client) -> None: """Test that ResticCommandFailedError is raised on find failure.""" @@ -211,7 +249,7 @@ def test_find_failure(self, restic_client) -> None: with patch.object( restic_client, - "_run_command", + "_run_json_command", side_effect=ResticCommandFailedError("Find failed"), ): with pytest.raises(ResticCommandFailedError, match="Find failed"): @@ -394,24 +432,115 @@ def test_run_command_subprocess_error(self, restic_client) -> None: ): restic_client._run_command(["restic", "backup"]) - def test_send_error_email_on_failure(self, restic_client) -> None: - """Test that error email is sent when command fails.""" + def test_command_failure_raises_without_email_dependency( + self, + restic_client, + ) -> None: + """Test that command failures raise; client does not own notifications.""" restic_client.set_environment("test_password") with tempfile.TemporaryDirectory() as temp_dir: log_file = Path(temp_dir) / "restic.log" + session_log = Path(temp_dir) / "restic_session.log" + session_log.write_text("session header\n") log_file.write_text("error log content") mock_result = Mock() mock_result.returncode = 1 + with ( + patch.object(restic_client, "log_file", log_file), + patch.object(restic_client, "session_log", session_log), + patch("subprocess.run", return_value=mock_result), + ): + with pytest.raises(ResticCommandFailedError): + restic_client._run_command(["restic", "backup"]) + + assert "=== restic backup ===" in session_log.read_text() + + def test_session_log_accumulates_command_output(self, restic_client) -> None: + """Test that each command's output is appended to the session log.""" + restic_client.set_environment("test_password") + + with tempfile.TemporaryDirectory() as temp_dir: + log_file = Path(temp_dir) / "restic.log" + session_log = Path(temp_dir) / "restic_session.log" + session_log.write_text("session header\n") + + mock_result = Mock() + mock_result.returncode = 0 + + def fake_run(*_args: object, **kwargs: object) -> Mock: + cast("IO[str]", kwargs["stdout"]).write("backup line\n") + return mock_result + + with ( + patch.object(restic_client, "log_file", log_file), + patch.object(restic_client, "session_log", session_log), + patch("subprocess.run", side_effect=fake_run), + ): + restic_client._run_command(["restic", "backup", "/src"]) + restic_client._run_command(["restic", "forget"]) + + session_text = session_log.read_text() + assert "session header" in session_text + assert "=== restic backup /src ===" in session_text + assert "backup line" in session_text + assert "=== restic forget ===" in session_text + # Per-command log only holds the last command + assert log_file.read_text() == "backup line\n" + + def test_run_command_raises_locked_error_without_email(self, restic_client) -> None: + """Test that a repository lock error raises the dedicated exception. + + A lock is potentially recoverable, so no failure email should be sent; + the caller is expected to unlock and retry instead. + """ + restic_client.set_environment("test_password") + + with tempfile.TemporaryDirectory() as temp_dir: + log_file = Path(temp_dir) / "restic.log" + + mock_result = Mock() + mock_result.returncode = 1 + + def fake_run(*_args: object, **kwargs: object) -> Mock: + # _run_command opens the log file in "w" mode, so the lock text + # has to be written by the (mocked) subprocess itself. + cast("IO[str]", kwargs["stdout"]).write( + "unable to create lock in backend: repository is already locked", + ) + return mock_result + with patch.object(restic_client, "log_file", log_file): - with patch("subprocess.run", return_value=mock_result): - with pytest.raises(ResticCommandFailedError): + with patch("subprocess.run", side_effect=fake_run): + with pytest.raises(ResticRepositoryLockedError): restic_client._run_command(["restic", "backup"]) - # Verify error email was sent - restic_client.encrypted_mail.send_mail_with_retries.assert_called() + def test_unlock_uses_raise_on_error_false(self, restic_client) -> None: + """Test that unlock invokes the command with raise_on_error disabled.""" + restic_client.set_environment("test_password") + + mock_result = Mock() + mock_result.returncode = 0 + + with patch.object( + restic_client, + "_run_command", + return_value=mock_result, + ) as mock_run: + restic_client.unlock() + + assert mock_run.call_args.kwargs.get("raise_on_error") is False + + def test_is_lock_error_detects_lock_messages(self) -> None: + """Test the lock-error signature detection helper.""" + assert ResticClient.is_lock_error("repository is already locked exclusively") + assert ResticClient.is_lock_error("unable to create lock in backend") + assert ResticClient.is_lock_error("REPOSITORY IS ALREADY LOCKED") + assert not ResticClient.is_lock_error("no errors were found") + assert not ResticClient.is_lock_error("") + assert not ResticClient.is_lock_error(None) if __name__ == "__main__": diff --git a/tests/file_integrity/__init__.py b/tests/file_integrity/__init__.py new file mode 100644 index 0000000..a7420f0 --- /dev/null +++ b/tests/file_integrity/__init__.py @@ -0,0 +1 @@ +"""Tests for file integrity checks.""" diff --git a/tests/sync_health/__init__.py b/tests/sync_health/__init__.py new file mode 100644 index 0000000..6b3f918 --- /dev/null +++ b/tests/sync_health/__init__.py @@ -0,0 +1 @@ +"""Tests for sync health checks.""" diff --git a/tests/test_lock_manager.py b/tests/test_lock_manager.py index 52656de..4ee095d 100644 --- a/tests/test_lock_manager.py +++ b/tests/test_lock_manager.py @@ -1,5 +1,6 @@ """Tests for the lock manager module.""" +import fcntl import logging import os import tempfile @@ -13,6 +14,17 @@ from opsbox.locking.lock_manager import LockManager +def _hold_flock(lock_file: Path) -> int: + """Acquire an exclusive advisory lock on ``lock_file`` and return the fd. + + Simulates another running instance holding the lock. The caller is + responsible for closing the returned descriptor. + """ + fd = os.open(lock_file, os.O_RDWR | os.O_CREAT, 0o644) + fcntl.flock(fd, fcntl.LOCK_EX | fcntl.LOCK_NB) + return fd + + class TestLockManager: """Test cases for LockManager functionality.""" @@ -35,6 +47,7 @@ def test_init_with_all_parameters(self) -> None: assert lock_manager.logger == logger assert lock_manager.encrypted_mail == encrypted_mail assert lock_manager.script_name == script_name + assert lock_manager._lock_fd is None def test_init_with_minimal_parameters(self) -> None: """Test LockManager initialization with only required parameters.""" @@ -76,9 +89,10 @@ def test_context_manager_success(self) -> None: with LockManager(lock_file=lock_file, logger=logger) as lock_manager: assert lock_manager.lock_file == lock_file assert lock_file.exists() + assert lock_manager._lock_fd is not None - # Lock should be released after context exit - assert not lock_file.exists() + # The advisory lock is released (fd closed) after context exit. + assert lock_manager._lock_fd is None # Check that both log messages were called assert logger.info.call_count == 2 logger.info.assert_any_call(f"Lock file {lock_file} created.") @@ -91,12 +105,13 @@ def test_context_manager_with_exception(self) -> None: logger = Mock(spec=logging.Logger) test_exception_message = "Test exception" + lock_manager = LockManager(lock_file=lock_file, logger=logger) with pytest.raises(ValueError, match=test_exception_message): - with LockManager(lock_file=lock_file, logger=logger): + with lock_manager: raise ValueError(test_exception_message) # Lock should still be released despite exception - assert not lock_file.exists() + assert lock_manager._lock_fd is None # Check that both log messages were called assert logger.info.call_count == 2 logger.info.assert_any_call(f"Lock file {lock_file} created.") @@ -112,94 +127,115 @@ def test_create_lock_success(self) -> None: lock_manager.create_lock() assert lock_file.exists() + assert lock_manager._lock_fd is not None logger.info.assert_called_with(f"Lock file {lock_file} created.") - def test_create_lock_already_exists(self) -> None: - """Test lock creation fails when lock file already exists.""" + lock_manager.release_lock() + + def test_create_lock_writes_holder_diagnostics(self) -> None: + """Test that PID/host diagnostics are written into the lock file.""" with tempfile.TemporaryDirectory() as temp_dir: lock_file = Path(temp_dir) / "test.lock" logger = Mock(spec=logging.Logger) - # Create the lock file first - lock_file.touch() - lock_manager = LockManager(lock_file=lock_file, logger=logger) + lock_manager.create_lock() + try: + contents = lock_file.read_text() + assert f"pid={os.getpid()}" in contents + assert "host=" in contents + assert "acquired=" in contents + finally: + lock_manager.release_lock() - with pytest.raises(LockAlreadyTakenError) as exc_info: - lock_manager.create_lock() + def test_create_lock_already_held(self) -> None: + """Test lock creation fails when the lock is actively held.""" + with tempfile.TemporaryDirectory() as temp_dir: + lock_file = Path(temp_dir) / "test.lock" + logger = Mock(spec=logging.Logger) - assert str(exc_info.value) == f"Lock file {lock_file} already exists." - logger.error.assert_called_with( - "Lock file exists. Another instance may be running.", - ) + holder_fd = _hold_flock(lock_file) + try: + lock_manager = LockManager(lock_file=lock_file, logger=logger) + + with pytest.raises(LockAlreadyTakenError) as exc_info: + lock_manager.create_lock() + + assert str(exc_info.value) == f"Lock file {lock_file} is already held." + assert lock_manager._lock_fd is None + logger.exception.assert_called_once() + finally: + os.close(holder_fd) - def test_create_lock_already_exists_with_email_notification(self) -> None: - """Test email notification is sent when lock is already taken.""" + def test_create_lock_already_held_with_email_notification(self) -> None: + """Test email notification is sent when lock is already held.""" with tempfile.TemporaryDirectory() as temp_dir: lock_file = Path(temp_dir) / "test.lock" logger = Mock(spec=logging.Logger) encrypted_mail = Mock(spec=EncryptedMail) script_name = "test_script.py" - # Create the lock file first - lock_file.touch() - - lock_manager = LockManager( - lock_file=lock_file, - logger=logger, - encrypted_mail=encrypted_mail, - script_name=script_name, - ) - - with pytest.raises(LockAlreadyTakenError): - lock_manager.create_lock() + holder_fd = _hold_flock(lock_file) + try: + lock_manager = LockManager( + lock_file=lock_file, + logger=logger, + encrypted_mail=encrypted_mail, + script_name=script_name, + ) + + with pytest.raises(LockAlreadyTakenError): + lock_manager.create_lock() - encrypted_mail.send_mail_with_retries.assert_called_once_with( - subject=f"Lock already taken by script {script_name}", - message=f"The lock file {lock_file} already exists. Script {script_name} cannot acquire lock.", - ) + encrypted_mail.send_mail_with_retries.assert_called_once() + call_kwargs = encrypted_mail.send_mail_with_retries.call_args.kwargs + assert ( + call_kwargs["subject"] + == f"Lock already taken by script {script_name}" + ) + assert str(lock_file) in call_kwargs["message"] + finally: + os.close(holder_fd) - def test_create_lock_already_exists_without_email_config(self) -> None: + def test_create_lock_already_held_without_email_config(self) -> None: """Test no email notification when email is not configured.""" with tempfile.TemporaryDirectory() as temp_dir: lock_file = Path(temp_dir) / "test.lock" logger = Mock(spec=logging.Logger) - # Create the lock file first - lock_file.touch() - - lock_manager = LockManager(lock_file=lock_file, logger=logger) + holder_fd = _hold_flock(lock_file) + try: + lock_manager = LockManager(lock_file=lock_file, logger=logger) - with pytest.raises(LockAlreadyTakenError): - lock_manager.create_lock() + with pytest.raises(LockAlreadyTakenError): + lock_manager.create_lock() - # Should not try to send email - logger.error.assert_called_with( - "Lock file exists. Another instance may be running.", - ) + logger.exception.assert_called_once() + finally: + os.close(holder_fd) - def test_create_lock_already_exists_without_script_name(self) -> None: + def test_create_lock_already_held_without_script_name(self) -> None: """Test no email notification when script_name is not provided.""" with tempfile.TemporaryDirectory() as temp_dir: lock_file = Path(temp_dir) / "test.lock" logger = Mock(spec=logging.Logger) encrypted_mail = Mock(spec=EncryptedMail) - # Create the lock file first - lock_file.touch() - - lock_manager = LockManager( - lock_file=lock_file, - logger=logger, - encrypted_mail=encrypted_mail, - script_name=None, - ) - - with pytest.raises(LockAlreadyTakenError): - lock_manager.create_lock() + holder_fd = _hold_flock(lock_file) + try: + lock_manager = LockManager( + lock_file=lock_file, + logger=logger, + encrypted_mail=encrypted_mail, + script_name=None, + ) + + with pytest.raises(LockAlreadyTakenError): + lock_manager.create_lock() - # Should not try to send email - encrypted_mail.send_mail_with_retries.assert_not_called() + encrypted_mail.send_mail_with_retries.assert_not_called() + finally: + os.close(holder_fd) def test_create_lock_email_sending_failure(self) -> None: """Test email sending failure is handled gracefully.""" @@ -209,28 +245,27 @@ def test_create_lock_email_sending_failure(self) -> None: encrypted_mail = Mock(spec=EncryptedMail) script_name = "test_script.py" - # Configure email to raise an exception encrypted_mail.send_mail_with_retries.side_effect = ( EmailSettingsNotFoundError("Email settings not found") ) - # Create the lock file first - lock_file.touch() - - lock_manager = LockManager( - lock_file=lock_file, - logger=logger, - encrypted_mail=encrypted_mail, - script_name=script_name, - ) - - with pytest.raises(LockAlreadyTakenError): - lock_manager.create_lock() + holder_fd = _hold_flock(lock_file) + try: + lock_manager = LockManager( + lock_file=lock_file, + logger=logger, + encrypted_mail=encrypted_mail, + script_name=script_name, + ) + + with pytest.raises(LockAlreadyTakenError): + lock_manager.create_lock() - # Should log the email failure but still raise LockAlreadyTakenError - logger.exception.assert_called_with( - "Failed to send lock notification email", - ) + logger.exception.assert_called_with( + "Failed to send lock notification email", + ) + finally: + os.close(holder_fd) def test_create_lock_email_os_error(self) -> None: """Test OSError from email sending is handled gracefully.""" @@ -240,44 +275,41 @@ def test_create_lock_email_os_error(self) -> None: encrypted_mail = Mock(spec=EncryptedMail) script_name = "test_script.py" - # Configure email to raise OSError encrypted_mail.send_mail_with_retries.side_effect = OSError("Network error") - # Create the lock file first - lock_file.touch() - - lock_manager = LockManager( - lock_file=lock_file, - logger=logger, - encrypted_mail=encrypted_mail, - script_name=script_name, - ) - - with pytest.raises(LockAlreadyTakenError): - lock_manager.create_lock() + holder_fd = _hold_flock(lock_file) + try: + lock_manager = LockManager( + lock_file=lock_file, + logger=logger, + encrypted_mail=encrypted_mail, + script_name=script_name, + ) + + with pytest.raises(LockAlreadyTakenError): + lock_manager.create_lock() - # Should log the email failure but still raise LockAlreadyTakenError - logger.exception.assert_called_with( - "Failed to send lock notification email", - ) + logger.exception.assert_called_with( + "Failed to send lock notification email", + ) + finally: + os.close(holder_fd) def test_release_lock_success(self) -> None: - """Test successful lock release when lock file exists.""" + """Test successful lock release when a lock is held.""" with tempfile.TemporaryDirectory() as temp_dir: lock_file = Path(temp_dir) / "test.lock" logger = Mock(spec=logging.Logger) - # Create the lock file first - lock_file.touch() - lock_manager = LockManager(lock_file=lock_file, logger=logger) + lock_manager.create_lock() lock_manager.release_lock() - assert not lock_file.exists() + assert lock_manager._lock_fd is None logger.info.assert_called_with("Lock file released.") - def test_release_lock_file_not_exists(self) -> None: - """Test lock release when lock file doesn't exist.""" + def test_release_lock_not_held(self) -> None: + """Test lock release when no lock is held.""" with tempfile.TemporaryDirectory() as temp_dir: lock_file = Path(temp_dir) / "test.lock" logger = Mock(spec=logging.Logger) @@ -285,21 +317,18 @@ def test_release_lock_file_not_exists(self) -> None: lock_manager = LockManager(lock_file=lock_file, logger=logger) lock_manager.release_lock() - assert not lock_file.exists() logger.warning.assert_called_with( "Lock file does not exist when attempting to release.", ) def test_lock_file_permissions_error(self) -> None: - """Test behavior when lock file directory has permission issues.""" + """Test behavior when lock file cannot be opened due to permissions.""" with tempfile.TemporaryDirectory() as temp_dir: lock_file = Path(temp_dir) / "test.lock" logger = Mock(spec=logging.Logger) - # Mock Path.touch to raise PermissionError - with patch.object( - Path, - "touch", + with patch( + "opsbox.locking.lock_manager.os.open", side_effect=PermissionError("Permission denied"), ): lock_manager = LockManager(lock_file=lock_file, logger=logger) @@ -325,14 +354,15 @@ def test_lock_file_with_spaces_in_path(self) -> None: lock_manager = LockManager(lock_file=lock_file, logger=logger) lock_manager.create_lock() - - assert lock_file.exists() - logger.info.assert_called_with(f"Lock file {lock_file} created.") + try: + assert lock_file.exists() + logger.info.assert_called_with(f"Lock file {lock_file} created.") + finally: + lock_manager.release_lock() def test_lock_file_relative_path(self) -> None: """Test lock file creation with relative path.""" with tempfile.TemporaryDirectory() as temp_dir: - # Change to temp directory to test relative paths original_cwd = Path.cwd() try: os.chdir(temp_dir) @@ -341,9 +371,9 @@ def test_lock_file_relative_path(self) -> None: lock_manager = LockManager(lock_file=lock_file, logger=logger) lock_manager.create_lock() - assert lock_file.exists() logger.info.assert_called_with(f"Lock file {lock_file} created.") + lock_manager.release_lock() finally: os.chdir(original_cwd) @@ -358,7 +388,7 @@ def test_concurrent_lock_attempts(self) -> None: lock_manager1 = LockManager(lock_file=lock_file, logger=logger1) lock_manager1.create_lock() - # Second instance should fail + # Second instance should fail while the first holds the lock lock_manager2 = LockManager(lock_file=lock_file, logger=logger2) with pytest.raises(LockAlreadyTakenError): lock_manager2.create_lock() @@ -369,23 +399,24 @@ def test_concurrent_lock_attempts(self) -> None: # Now second instance should succeed lock_manager2.create_lock() assert lock_file.exists() + lock_manager2.release_lock() - def test_lock_file_race_condition(self) -> None: - """Test race condition where lock file is created between check and creation.""" + def test_stale_lock_file_does_not_block(self) -> None: + """Test that a leftover lock file with no active flock does not block.""" with tempfile.TemporaryDirectory() as temp_dir: - lock_file = Path(temp_dir) / "race_test.lock" + lock_file = Path(temp_dir) / "stale.lock" logger = Mock(spec=logging.Logger) - lock_manager = LockManager(lock_file=lock_file, logger=logger) + # Simulate a stale lock file left behind by a crashed process: + # the file exists but nobody holds an advisory lock on it. + lock_file.write_text("pid=99999 host=dead acquired=2020-01-01T00:00:00") - # Mock Path.touch to raise FileExistsError to simulate race condition - with patch.object( - Path, - "touch", - side_effect=FileExistsError("File exists"), - ): - with pytest.raises(FileExistsError): - lock_manager.create_lock() + lock_manager = LockManager(lock_file=lock_file, logger=logger) + lock_manager.create_lock() + try: + assert lock_manager._lock_fd is not None + finally: + lock_manager.release_lock() def test_lock_already_taken_error_message(self) -> None: """Test that LockAlreadyTakenError includes proper error message.""" @@ -393,16 +424,17 @@ def test_lock_already_taken_error_message(self) -> None: lock_file = Path(temp_dir) / "error_test.lock" logger = Mock(spec=logging.Logger) - # Create the lock file first - lock_file.touch() - - lock_manager = LockManager(lock_file=lock_file, logger=logger) + holder_fd = _hold_flock(lock_file) + try: + lock_manager = LockManager(lock_file=lock_file, logger=logger) - with pytest.raises(LockAlreadyTakenError) as exc_info: - lock_manager.create_lock() + with pytest.raises(LockAlreadyTakenError) as exc_info: + lock_manager.create_lock() - expected_message = f"Lock file {lock_file} already exists." - assert str(exc_info.value) == expected_message + expected_message = f"Lock file {lock_file} is already held." + assert str(exc_info.value) == expected_message + finally: + os.close(holder_fd) if __name__ == "__main__": diff --git a/uv.lock b/uv.lock index 2096d97..c51f0d7 100644 --- a/uv.lock +++ b/uv.lock @@ -1,5 +1,5 @@ version = 1 -revision = 3 +revision = 2 requires-python = ">=3.12" [[package]] @@ -525,7 +525,7 @@ wheels = [ [[package]] name = "opsbox" -version = "0.2.1" +version = "0.3.1" source = { editable = "." } dependencies = [ { name = "dbus-python" },